急に出始めた PG::ConnectionBad: PQconsumeInput() エラー
RailsでActiveRecordを使わずSequelをORMとして使っているのだが、いつからかRails起動直後のRDS（Postgresql）接続時に「PG::ConnectionBad: PQconsumeInput()」エラーが出るようになってしまった。
PG::ConnectionBad: PQconsumeInput() SSL error: decryption failed or bad record mac
PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
PG::ConnectionBad: PQconsumeInput() SSL error: sslv3 alert bad record mac
Sequel側は変えていないのでRDSで何か仕様変更があったのか・・・。RDSのCA証明書の変更の影響かと思ったが、変更する前から当エラーは出てた。
状況
- Rails起動直後にいくつかのリクエストでこのエラーになる。全てではない。
- ある程度エラーが出るとその後は出ない。
- ステージング環境などで8時間くらいアクセスがないとまたでるようになる。
- なので、本番環境ではRails再起動直後だけこのエラーがでる。
- 開発環境のRDSではないPostgresqlだと出ない。
このエラーが出たらretryする仕組みも入れたけど、やはりそもそも出ないようにしたい。
connection_validatorを試す
真偽はわからないがpumaのようなマルチスレッドのアプリケーションサーバを使っているとこのエラーが出るらしい。Sequelのコネクションプーリングがスレッドセーフではない？
で、色々ググったところ日本語の情報はさっぱりの中、海外のサイトで以下の設定を入れれば解決するらしい情報を入手。
DB.extension(:connection_validator)
DB.pool.connection_validation_timeout = -1
コネクションプーリング内のコネクションが有効かどうかチェックして、有効でなければ再接続する設定。
DB.pool.connection_validation_timeout はチェックする間隔（秒）で、デフォルト3600秒、−1のときは常にチェック。
connection_validation_timeoutの値を変えて検証
- -1： エラーが出なくなった！
- 1以上： 起動直後はエラーでる
検証結果
DB.pool.connection_validation_timeout = -1 なら効果あり。
3600で効果出て欲しかったなあ。
パフォーマンス試験
公式にもあるように、常にチェックだと気になるのがパフォーマンスの劣化。
connection_validatorありなしでApacheBenchでパフォーマンステストしてみた。
connection_validatorなし
$ ab -c 100 -n 10000 "http://xxxxxxxxxx"
Concurrency Level: 100
Time taken for tests: 22.620 seconds
Complete requests: 10000
Failed requests: 0
Total transferred: 15650000 bytes
HTML transferred: 11390000 bytes
Requests per second: 442.09 [#/sec] (mean)
Time per request: 226.196 [ms] (mean)
Time per request: 2.262 [ms] (mean, across all concurrent requests)
Transfer rate: 675.66 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.4 0 5
Processing: 5 226 162.3 178 1102
Waiting: 5 226 162.3 178 1102
Total: 5 226 162.3 178 1102
connection_validatorあり （connection_validation_timeout = -1）
$ ab -c 100 -n 10000 "http://xxxxxxxxxx"
Concurrency Level: 100
Time taken for tests: 26.522 seconds
Complete requests: 10000
Failed requests: 0
Total transferred: 15650000 bytes
HTML transferred: 11390000 bytes
Requests per second: 377.05 [#/sec] (mean)
Time per request: 265.216 [ms] (mean)
Time per request: 2.652 [ms] (mean, across all concurrent requests)
Transfer rate: 576.26 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.1 0 2
Processing: 10 264 157.8 231 1126
Waiting: 10 264 157.8 231 1126
Total: 10 264 157.9 231 1126
（結果は3回試して一番良かった結果）
テスト結果
1リクエストあたり約40ms遅くなった。
結論
超絶負荷のかかる様なサーバではないので、40msのパフォーマンス劣化は許容範囲としてconnection_validatorを採用することにした。
auto_reconnectオプションとかあれば良いのに。