環境
PostgreSQL 11.4
ここ3日くらいPostgreSQLで意図しない「FATAL: terminating connection due to administrator command」が発生してpgpoolから切り離されて困っています。
PostgreSQLのログ
2019-07-19 07:50:01.632 JST [27138] FATAL: terminating connection due to administrator command
PostgreSQLの、ログの出力をdebug3、実行されたSQLをすべて出力している状態で現象が再現したのですが、ログを見ても原因が分かりません…
postgresql.conf
log_min_messages = debug3 log_statement = 'all'
「FATAL: terminating connection due to administrator command」となる直接の原因は、おそらく「SELECT pg_terminate_backend(pid)」が実行されていることです。
※とても参考にさせて頂いています。とてもすごい資料です。
2019-07-19 07:50:01.615 JST [10453] LOG: statement: SELECT pg_terminate_backend(pid)
FROM pg_stat_activity
WHERE pid IN (
SELECT l.pid
FROM ( SELECT pid FROM pg_locks GROUP BY pid ) l
, pg_stat_activity a
WHERE l.pid = a.pid
AND now() - query_start > '5minutes'::INTERVAL
)
;
このクエリの結果、クエリが実行されてから5分を超えているプロセスにpg_terminate_backendしにいっています。「FATAL: terminating connection due to administrator command」を出力しているのは、プロセス番号7813なので、プロセス番号7813を抜き出すと以下の通りでした。
PostgreSQLのログ
2019-07-19 07:50:01.621 JST [7813] LOG: statement: BEGIN
2019-07-19 07:50:01.626 JST [7813] LOG: statement:
SELECT tag
, uid
, game
, comment
FROM userreview_with_tag uwg
WHERE EXISTS ( SELECT *
FROM userreview_tag u
WHERE u.uid = uwg.uid
AND u.game = uwg.game
AND timestamp >= ( SELECT timestamp FROM userreview_tag_last_check_timestamp )
)
;
2019-07-19 07:50:01.630 JST [7813] LOG: statement:
SELECT uid
, game
, tags
FROM userreview_tag u
WHERE timestamp >= ( SELECT timestamp FROM userreview_tag_last_check_timestamp )
2019-07-19 07:50:01.632 JST [7813] FATAL: terminating connection due to administrator command
5minutesな設定でクエリを解放しそうなPostgreSQLの設定が「max_standby_streaming_delay」で、デフォルトは30秒なのですが、当時の自分がなんとなく300秒に設定していました。
userreview_tagテーブル/userreview_tag_last_check_timestampテーブルを長時間ロックしそうな処理はしていない…と思うのですが、してるのかな…
2019/07/19追記
pgpoolのログ
Jul 19 04:20:01 erogamescape13 pgpool[25274]: [2975989-1] 2019-07-19 04:20:01: pid 25274: LOG: reading and processing packets
Jul 19 04:20:01 erogamescape13 pgpool[25274]: [2975989-2] 2019-07-19 04:20:01: pid 25274: DETAIL: postmaster on DB node 1 was shutdown by administrative command
Jul 19 04:20:01 erogamescape13 pgpool[25274]: [2975990-1] 2019-07-19 04:20:01: pid 25274: LOG: received degenerate backend request for node_id: 1 from pid [25274]
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [449-1] 2019-07-19 04:20:01: pid 10368: LOG: new IPC connection received
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [450-1] 2019-07-19 04:20:01: pid 10368: LOG: watchdog received the failover command from local pgpool-II on IPC interface
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [451-1] 2019-07-19 04:20:01: pid 10368: LOG: watchdog is processing the failover command [DEGENERATE_BACKEND_REQUEST] received from local pgpool-II on IPC interface
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [452-1] 2019-07-19 04:20:01: pid 10368: LOG: we have got the consensus to perform the failover
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [452-2] 2019-07-19 04:20:01: pid 10368: DETAIL: 1 node(s) voted in the favor
Jul 19 04:20:01 erogamescape13 pgpool[10367]: [2976456-1] 2019-07-19 04:20:01: pid 10367: LOG: Pgpool-II parent process has received failover request
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [453-1] 2019-07-19 04:20:01: pid 10368: LOG: new IPC connection received
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [454-1] 2019-07-19 04:20:01: pid 10368: LOG: received the failover indication from Pgpool-II on IPC interface
Jul 19 04:20:01 erogamescape13 pgpool[10368]: [455-1] 2019-07-19 04:20:01: pid 10368: LOG: watchdog is informed of failover start by the main process
Jul 19 04:20:01 erogamescape13 pgpool[10367]: [2976457-1] 2019-07-19 04:20:01: pid 10367: LOG: starting degeneration. shutdown host 192.168.0.13(5432)
2019/07/24追記
おそらく解決しました。
2013年9月9日から2013年9月15日に発生した障害について(続き)のときに対策として、以下のクエリをcronで5分おきに実行していました。
SELECT pg_terminate_backend(pid)
FROM pg_stat_activity
WHERE pid IN (
SELECT l.pid
FROM ( SELECT pid FROM pg_locks GROUP BY pid ) l
, pg_stat_activity a
WHERE l.pid = a.pid
AND now() - query_start > '5minutes'::INTERVAL
)
;
pg_locksテーブルに存在するクエリで、query_startから5分たったものはpg_terminate_backendで強制的にプロセスを落とすようにしていました。
pg_terminate_backendを実行すると、PostgreSQLのログに「FATAL: terminating connection due to administrator command」が記録されます。また、pg_terminate_backend()関数の値が定数ではない場合、pgpoolから切り離されます。
5分も実行しているクエリなんかあるのかな…と思っていたら
- BEGINではじまるトランザクションで5分以上かかる処理が存在する
- ユーザーさんが5分を超えるクエリを実行することがある。いまいちなSQLの場合は、いつまでも処理が終わらずにCPU使用率が100%にはりつく※ErogameScapeは誰でもクエリを実行できるようにしています。
ことがあることが分かったので、長い間実行しているクエリは殺す必要があります
twitterで「pg_terminate_backend」ではなく「pg_cancel_backend」を使用した方がよいと教わりましたので、「pg_cancel_backend」に置換しました。
