SequelでPG::ConnectionBad: PQconsumeInput()エラーが出るようになって困った話

急に出始めた 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オプションとかあれば良いのに。