この文書は2013年9月9日から2013年9月15日に発生した障害についての続きです。
現象が再現したので、自分の想定があっているかのコメントをもらえることを期待して記録します。
現象再現時のログ
ロック解除待ちの状態のクエリは以下の通りです。
postgresqlの出力したログは以下の通りです。
強制的にロック待ち状態となっているSQLを切断した際には以下のログを大量に出力しました。
また、当時、I/O waitが著しく増大していました。
考察
pid 1053で実行されていたSQL
SELECT DISTINCT ON (povgroups.game, povlist.system_group) povgroups.game, povlist.system_group, povlist.system_title, count(povgroups.pov) AS count FROM povgroups, povlist, gamelist WHERE gamelist.median >= 80 AND povgroups.pov = povlist.id AND povlist.system_group IN ('傾向', 'ジャンル') GROUP BY povgroups.game, povlist.system_group, povlist.system_title ORDER BY povgroups.game, povlist.system_group, count(povgroups.pov) DESC
は、EXPLAINするとcost=71223460.62..71224672.13です。
query_startが2013-10-14 22:34:25で、23:00の時点でも実行中の超スロークエリでした。
この超スロークエリを実行するため、スワップが発生し、I/O waitが著しく増大しました。
22:57頃、 Postgresqlのログにpgstat wait timeoutが出ていることからPostgreSQLへのアクセスが遅延するという事態が起こっています。
長文感想の閲覧ログはuserreview_display_logテーブルに保存されるのですが、INSERT INTO "userreview_display_log"~のSQLが、トランザクション開始時刻(xact_start)が2013-10-14 22:57:43にも関わらず、実際にクエリの実行が開始された時刻(query_start)が2013-10-14 23:00:39です。
トランザクションが開始されてからINSERTが実行されるまで3分もかかっています。
長文感想はとてもよく閲覧されるので、INSERT INTO "userreview_display_log"~のSQLは激しく実行されます。INSERT INTO "userreview_display_log"~を実行するため、素のままのpostgresqlや現在の最近のpgpoolでは(多分)テーブルにROW EXCLUSIVEのロックが入りますが、ErogameScapeで使っているpgpoolのVerはSHARE ROW EXCLUSIVEのロックが入ります。
Postgresqlのログから当時userreview_display_logにAUTO VACUUMが動いていたと想定されます。(この部分のログがないのと、そもそもどうログをとればいいのか分からないです。)
VACUUMが動くと、テーブルにSHARE UPDATE EXCLUSIVEが入ります。
userreview_display_logへのVACUUMは通常ですと1秒程度で終了するのですが、恐らく当時はすごい時間がかかっていて、SHARE UPDATE EXCLUSIVEがなかなか外れなかったのかと思います。
そこに、SHARE UPDATE EXCLUSIVEと競合するSHARE ROW EXCLUSIVE MODEが重なって待ちが待ちをうんでいたと推測します。
対策
以上から対策としては2点
1.については、新しいVerのpgpoolで設定の検証を実施しております。
折角だから、ついでにPostgreSQLを9.3にあげようと思って、PostgreSQL9.3と最近のpgpoolの組み合わせで検証を実施しており、とりあえずpgpool関連の設定は確定できました。
一つのサーバーに旧新混在可能ですので、設定を商用…じゃないか、えーと、運用?の設定にして、一度どこかでサービスを止めてデータを新しいPostgreSQLに移行したいと思っています。
※Index Only Scanが使えるのでSQLによっては早くなると思います。
2.については対策済みです。
具体的には5分SQLが実行され続けたらやばいだろうということで、
終わりに
大変ご迷惑をおかけいたします。
対策に未だ時間がかかりますがご容赦ください。
考察が間違っている、こういった対策が必要だ、こんなログを取っといた方がいい、等ございましたらコメント、メール、Twitter等でお知らせ頂けますと幸いです。
※9月に事象が発生したときは、こんなにI/O waitは発生していなかった気がするのですが、psコマンドでVACUUMがたくさん見えていたことから多分同一事象だと思っていますが、自信が無いです。
現象が再現したので、自分の想定があっているかのコメントをもらえることを期待して記録します。
現象再現時のログ
ロック解除待ちの状態のクエリは以下の通りです。
SELECT l.locktype, c.relname, l.pid, l.mode, a.current_query, (current_timestamp - xact_start)::interval(3) AS duration FROM pg_locks l LEFT OUTER JOIN pg_stat_activity a ON l.pid = a. procpid LEFT OUTER JOIN pg_class c ON l.relation = c.oid WHERE NOT l.granted ORDER BY l.pid
2013/10/14 23:01:33
locktype | relname | pid | mode | current_query | duration
----------+------------------------+-------+-----------------------+-----------------------------------------------------------------+---------------
relation | userreview_display_log | 727 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:35.709
relation | userreview_display_log | 735 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:37.641
relation | userreview_display_log | 767 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:40.457
relation | userreview_display_log | 813 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:41.588
relation | userreview_display_log | 841 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:29.836
relation | userreview_display_log | 973 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:53.873
relation | userreview_display_log | 1068 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:09.035
relation | userreview_display_log | 1084 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:21.565
relation | userreview_display_log | 1972 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:36.681
relation | userreview_display_log | 2135 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:03.202
relation | userreview_display_log | 2189 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:36.164
relation | userreview_display_log | 2234 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:55.531
relation | userreview_display_log | 2916 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | -00:00:05.685
relation | userreview_display_log | 2982 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:21.07
relation | userreview_display_log | 3120 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:40.184
relation | userreview_display_log | 3155 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:08.594
relation | userreview_display_log | 3305 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:20.286
relation | userreview_display_log | 3328 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:31.648
relation | userreview_display_log | 3367 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:56.553
relation | userreview_display_log | 4039 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:20.503
relation | userreview_display_log | 4068 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:44.787
relation | userreview_display_log | 4099 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:42.992
relation | userreview_display_log | 4142 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:55.519
relation | userreview_display_log | 4269 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:41.038
relation | userreview_display_log | 4304 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:10.638
relation | userreview_display_log | 5079 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:40.237
relation | userreview_display_log | 5176 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:20.161
relation | userreview_display_log | 5188 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:50.947
relation | userreview_display_log | 5222 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:44.545
relation | userreview_display_log | 5252 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:43.97
relation | userreview_display_log | 5261 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:01.49
relation | userreview_display_log | 5290 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:34.926
relation | userreview_display_log | 5377 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:37.072
relation | userreview_display_log | 5381 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:40.194
relation | userreview_display_log | 5390 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:40.269
relation | userreview_display_log | 5407 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:27.328
relation | userreview_display_log | 5416 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:24.409
relation | userreview_display_log | 5431 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:24.352
relation | userreview_display_log | 5514 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:43.222
relation | userreview_display_log | 6107 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:38.747
relation | userreview_display_log | 6146 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:43.289
relation | userreview_display_log | 6170 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:16.195
relation | userreview_display_log | 6183 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:17.921
relation | userreview_display_log | 6240 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:47.813
relation | userreview_display_log | 6255 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:08.762
relation | userreview_display_log | 6260 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:09.733
relation | userreview_display_log | 6274 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:27.178
relation | userreview_display_log | 6409 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:29.407
relation | userreview_display_log | 6418 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:28.043
relation | userreview_display_log | 6419 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:27.825
relation | userreview_display_log | 6440 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:16.079
relation | userreview_display_log | 6464 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:02.546
relation | userreview_display_log | 6469 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:58.385
relation | userreview_display_log | 6494 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:52.121
relation | userreview_display_log | 6515 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:51
relation | userreview_display_log | 6537 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:36.445
relation | userreview_display_log | 6565 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:41.827
relation | userreview_display_log | 6579 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:31.322
relation | userreview_display_log | 6583 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:22.993
relation | userreview_display_log | 6589 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:20.166
relation | userreview_display_log | 6591 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:20.069
relation | userreview_display_log | 6594 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:18.73
relation | userreview_display_log | 7259 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:46.788
relation | userreview_display_log | 7310 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:45.446
relation | userreview_display_log | 7331 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:45.149
relation | userreview_display_log | 7512 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:34.891
relation | userreview_display_log | 7560 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:32.627
relation | userreview_display_log | 7660 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:27.847
relation | userreview_display_log | 7661 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:27.812
relation | userreview_display_log | 7673 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:26.521
relation | userreview_display_log | 7680 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:25.774
relation | userreview_display_log | 7724 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:24.545
relation | userreview_display_log | 7727 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:24.262
relation | userreview_display_log | 7736 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:23.249
relation | userreview_display_log | 7739 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:22.855
relation | userreview_display_log | 7799 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:17.23
relation | userreview_display_log | 7814 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:09.669
relation | userreview_display_log | 7821 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:01.478
relation | userreview_display_log | 7826 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:05.444
relation | userreview_display_log | 25075 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:12.333
relation | userreview_display_log | 27452 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:07.849
relation | userreview_display_log | 28747 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:28.673
relation | userreview_display_log | 29664 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:52.836
relation | userreview_display_log | 29797 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:27.56
relation | userreview_display_log | 30060 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:21.862
relation | userreview_display_log | 30194 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:12.208
relation | userreview_display_log | 30721 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:32.445
relation | userreview_display_log | 31121 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:22.06
relation | userreview_display_log | 32022 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:59.188
relation | userreview_display_log | 32023 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:37.896
relation | userreview_display_log | 32078 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:50.035
relation | userreview_display_log | 32137 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:33.129
relation | userreview_display_log | 32232 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:57.317
relation | userreview_display_log | 32247 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:24.88
relation | userreview_display_log | 32299 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:02:36.863
relation | userreview_display_log | 32311 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:10.166
relation | userreview_display_log | 32411 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:00:14.999
relation | userreview_display_log | 32415 | ShareRowExclusiveLock | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE | 00:03:39.84
(98 行)
何らかのテーブルをロック しているクエリの一覧の抜粋は以下の通りです。SELECT * FROM ( SELECT pid FROM pg_locks group by pid ) l , pg_stat_activity a WHERE l.pid = a.procpid ORDER BY query_start;
pid | datid | datname | procpid | usesysid | usename | application_name | client_addr | client_port | backend_start | xact_start | query_start | waiting | current_query
-------+-------+---------+---------+----------+---------+------------------+--------------+-------------+-------------------------------+-------------------------------+-------------------------------+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1053 | 16386 | ap2 | 1053 | 16390 | nobody | | 192.168.0.10 | 52603 | 2013-10-14 22:34:02.553588+09 | 2013-10-14 22:34:25.219974+09 | 2013-10-14 22:34:25.219974+09 | f | SELECT DISTINCT ON (povgroups.game, povlist.system_group) povgroups.game, povlist.system_group, povlist.system_title, count(povgroups.pov) AS count FROM povgroups, povlist, gamelist WHERE gamelist.median >= 80 AND povgroups.pov = povlist.id AND povlist.system_group IN ('傾向', 'ジャンル') GROUP BY povgroups.game, povlist.system_group, povlist.system_title ORDER BY povgroups.game, povlist.system_group, count(povgroups.pov) DESC
6240 | 16386 | ap2 | 6240 | 16388 | ap3 | | 192.168.0.10 | 51833 | 2013-10-14 22:56:54.96699+09 | 2013-10-14 22:57:46.352629+09 | 2013-10-14 22:57:46.354755+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
4068 | 16386 | ap2 | 4068 | 16388 | ap3 | | 192.168.0.10 | 38148 | 2013-10-14 22:45:56.206301+09 | 2013-10-14 22:57:49.378277+09 | 2013-10-14 22:57:49.378769+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5514 | 16386 | ap2 | 5514 | 16388 | ap3 | | 192.168.0.10 | 44341 | 2013-10-14 22:55:07.122952+09 | 2013-10-14 22:57:50.942674+09 | 2013-10-14 22:57:50.943146+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32415 | 16386 | ap2 | 32415 | 16388 | ap3 | | 192.168.0.10 | 36832 | 2013-10-14 22:29:19.61654+09 | 2013-10-14 22:57:54.324646+09 | 2013-10-14 22:57:54.325124+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6107 | 16386 | ap2 | 6107 | 16388 | ap3 | | 192.168.0.10 | 46900 | 2013-10-14 22:55:43.771562+09 | 2013-10-14 22:57:55.418614+09 | 2013-10-14 22:57:55.419106+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32023 | 16386 | ap2 | 32023 | 16388 | ap3 | | 192.168.0.10 | 51165 | 2013-10-14 22:25:49.572992+09 | 2013-10-14 22:57:56.269301+09 | 2013-10-14 22:57:56.271335+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5377 | 16386 | ap2 | 5377 | 16388 | ap3 | | 192.168.0.10 | 41555 | 2013-10-14 22:54:27.173069+09 | 2013-10-14 22:57:57.093636+09 | 2013-10-14 22:57:57.09429+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32137 | 16386 | ap2 | 32137 | 16388 | ap3 | | 192.168.0.10 | 54392 | 2013-10-14 22:26:40.822437+09 | 2013-10-14 22:58:01.036153+09 | 2013-10-14 22:58:01.036823+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6409 | 16386 | ap2 | 6409 | 16388 | ap3 | | 192.168.0.10 | 56253 | 2013-10-14 22:58:04.748534+09 | 2013-10-14 22:58:04.758485+09 | 2013-10-14 22:58:04.760146+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
28747 | 16386 | ap2 | 28747 | 16388 | ap3 | | 192.168.0.10 | 60953 | 2013-10-14 22:13:20.361285+09 | 2013-10-14 22:58:05.492594+09 | 2013-10-14 22:58:05.493113+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6418 | 16386 | ap2 | 6418 | 16388 | ap3 | | 192.168.0.10 | 56291 | 2013-10-14 22:58:06.107495+09 | 2013-10-14 22:58:06.122538+09 | 2013-10-14 22:58:06.12437+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6419 | 16386 | ap2 | 6419 | 16388 | ap3 | | 192.168.0.10 | 56311 | 2013-10-14 22:58:06.327874+09 | 2013-10-14 22:58:06.340217+09 | 2013-10-14 22:58:06.341937+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
29797 | 16386 | ap2 | 29797 | 16388 | ap3 | | 192.168.0.10 | 46119 | 2013-10-14 22:16:48.231268+09 | 2013-10-14 22:58:06.605009+09 | 2013-10-14 22:58:06.605572+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6274 | 16386 | ap2 | 6274 | 16388 | ap3 | | 192.168.0.10 | 54055 | 2013-10-14 22:57:23.958497+09 | 2013-10-14 22:58:06.986991+09 | 2013-10-14 22:58:06.987467+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32247 | 16386 | ap2 | 32247 | 16388 | ap3 | | 192.168.0.10 | 57646 | 2013-10-14 22:27:28.798974+09 | 2013-10-14 22:58:09.285088+09 | 2013-10-14 22:58:09.285877+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5416 | 16386 | ap2 | 5416 | 16388 | ap3 | | 192.168.0.10 | 43422 | 2013-10-14 22:54:53.72344+09 | 2013-10-14 22:58:09.75662+09 | 2013-10-14 22:58:09.757256+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5431 | 16386 | ap2 | 5431 | 16388 | ap3 | | 192.168.0.10 | 43926 | 2013-10-14 22:55:01.594243+09 | 2013-10-14 22:58:09.812887+09 | 2013-10-14 22:58:09.813553+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
31121 | 16386 | ap2 | 31121 | 16388 | ap3 | | 192.168.0.10 | 41573 | 2013-10-14 22:23:10.812257+09 | 2013-10-14 22:58:12.105214+09 | 2013-10-14 22:58:12.10569+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
1084 | 16386 | ap2 | 1084 | 16388 | ap3 | | 192.168.0.10 | 53415 | 2013-10-14 22:34:20.597873+09 | 2013-10-14 22:58:12.599787+09 | 2013-10-14 22:58:12.600491+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
2982 | 16386 | ap2 | 2982 | 16388 | ap3 | | 192.168.0.10 | 48196 | 2013-10-14 22:40:58.124567+09 | 2013-10-14 22:58:13.094844+09 | 2013-10-14 22:58:13.095468+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
4039 | 16386 | ap2 | 4039 | 16388 | ap3 | | 192.168.0.10 | 36489 | 2013-10-14 22:45:29.013967+09 | 2013-10-14 22:58:13.66203+09 | 2013-10-14 22:58:13.662504+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6183 | 16386 | ap2 | 6183 | 16388 | ap3 | | 192.168.0.10 | 49668 | 2013-10-14 22:56:21.169367+09 | 2013-10-14 22:58:16.243869+09 | 2013-10-14 22:58:16.244392+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6170 | 16386 | ap2 | 6170 | 16388 | ap3 | | 192.168.0.10 | 48855 | 2013-10-14 22:56:09.755635+09 | 2013-10-14 22:58:17.970177+09 | 2013-10-14 22:58:17.970704+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6440 | 16386 | ap2 | 6440 | 16388 | ap3 | | 192.168.0.10 | 56835 | 2013-10-14 22:58:18.073064+09 | 2013-10-14 22:58:18.086587+09 | 2013-10-14 22:58:18.088276+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
25075 | 16386 | ap2 | 25075 | 16388 | ap3 | | 192.168.0.10 | 59939 | 2013-10-14 21:58:57.00914+09 | 2013-10-14 22:58:21.831655+09 | 2013-10-14 22:58:21.832382+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
30194 | 16386 | ap2 | 30194 | 16388 | ap3 | | 192.168.0.10 | 57996 | 2013-10-14 22:20:00.78748+09 | 2013-10-14 22:58:21.957063+09 | 2013-10-14 22:58:21.957648+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
4304 | 16386 | ap2 | 4304 | 16388 | ap3 | | 192.168.0.10 | 49484 | 2013-10-14 22:49:16.386784+09 | 2013-10-14 22:58:23.527397+09 | 2013-10-14 22:58:23.529243+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32311 | 16386 | ap2 | 32311 | 16388 | ap3 | | 192.168.0.10 | 33329 | 2013-10-14 22:28:20.246617+09 | 2013-10-14 22:58:23.998675+09 | 2013-10-14 22:58:23.999461+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6260 | 16386 | ap2 | 6260 | 16388 | ap3 | | 192.168.0.10 | 53390 | 2013-10-14 22:57:14.096916+09 | 2013-10-14 22:58:24.432466+09 | 2013-10-14 22:58:24.432959+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
1068 | 16386 | ap2 | 1068 | 16388 | ap3 | | 192.168.0.10 | 52883 | 2013-10-14 22:34:09.063112+09 | 2013-10-14 22:58:25.130505+09 | 2013-10-14 22:58:25.131008+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6255 | 16386 | ap2 | 6255 | 16388 | ap3 | | 192.168.0.10 | 53179 | 2013-10-14 22:57:12.397941+09 | 2013-10-14 22:58:25.403157+09 | 2013-10-14 22:58:25.403636+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
27452 | 16386 | ap2 | 27452 | 16388 | ap3 | | 192.168.0.10 | 37626 | 2013-10-14 22:07:49.12849+09 | 2013-10-14 22:58:26.315688+09 | 2013-10-14 22:58:26.316276+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6464 | 16386 | ap2 | 6464 | 16388 | ap3 | | 192.168.0.10 | 57445 | 2013-10-14 22:58:31.032254+09 | 2013-10-14 22:58:31.619425+09 | 2013-10-14 22:58:31.621232+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32022 | 16386 | ap2 | 32022 | 16388 | ap3 | | 192.168.0.10 | 51137 | 2013-10-14 22:25:48.566785+09 | 2013-10-14 22:58:34.976959+09 | 2013-10-14 22:58:34.977531+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6469 | 16386 | ap2 | 6469 | 16388 | ap3 | | 192.168.0.10 | 57662 | 2013-10-14 22:58:35.766965+09 | 2013-10-14 22:58:35.779839+09 | 2013-10-14 22:58:35.781399+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32232 | 16386 | ap2 | 32232 | 16388 | ap3 | | 192.168.0.10 | 57460 | 2013-10-14 22:27:25.645294+09 | 2013-10-14 22:58:36.848471+09 | 2013-10-14 22:58:36.849155+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
3367 | 16386 | ap2 | 3367 | 16388 | ap3 | | 192.168.0.10 | 33193 | 2013-10-14 22:44:38.014331+09 | 2013-10-14 22:58:37.61206+09 | 2013-10-14 22:58:37.612627+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
2234 | 16386 | ap2 | 2234 | 16388 | ap3 | | 192.168.0.10 | 41740 | 2013-10-14 22:39:09.259493+09 | 2013-10-14 22:58:38.634428+09 | 2013-10-14 22:58:38.634928+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
4142 | 16386 | ap2 | 4142 | 16388 | ap3 | | 192.168.0.10 | 42475 | 2013-10-14 22:47:11.232382+09 | 2013-10-14 22:58:38.645906+09 | 2013-10-14 22:58:38.646494+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
973 | 16386 | ap2 | 973 | 16388 | ap3 | | 192.168.0.10 | 49231 | 2013-10-14 22:33:00.717233+09 | 2013-10-14 22:58:40.29252+09 | 2013-10-14 22:58:40.293261+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
29664 | 16386 | ap2 | 29664 | 16388 | ap3 | | 192.168.0.10 | 42903 | 2013-10-14 22:16:00.390591+09 | 2013-10-14 22:58:41.329408+09 | 2013-10-14 22:58:41.330064+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6494 | 16386 | ap2 | 6494 | 16388 | ap3 | | 192.168.0.10 | 57959 | 2013-10-14 22:58:42.030171+09 | 2013-10-14 22:58:42.044621+09 | 2013-10-14 22:58:42.046735+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6515 | 16386 | ap2 | 6515 | 16388 | ap3 | | 192.168.0.10 | 58025 | 2013-10-14 22:58:43.131735+09 | 2013-10-14 22:58:43.16526+09 | 2013-10-14 22:58:43.168277+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32078 | 16386 | ap2 | 32078 | 16388 | ap3 | | 192.168.0.10 | 52895 | 2013-10-14 22:26:18.138652+09 | 2013-10-14 22:58:44.130463+09 | 2013-10-14 22:58:44.130962+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5222 | 16386 | ap2 | 5222 | 16388 | ap3 | | 192.168.0.10 | 35207 | 2013-10-14 22:52:46.683942+09 | 2013-10-14 22:58:49.620076+09 | 2013-10-14 22:58:49.620777+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6146 | 16386 | ap2 | 6146 | 16388 | ap3 | | 192.168.0.10 | 48351 | 2013-10-14 22:56:03.234167+09 | 2013-10-14 22:58:50.875798+09 | 2013-10-14 22:58:50.877853+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
4099 | 16386 | ap2 | 4099 | 16388 | ap3 | | 192.168.0.10 | 39293 | 2013-10-14 22:46:19.25302+09 | 2013-10-14 22:58:51.173349+09 | 2013-10-14 22:58:51.174066+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6565 | 16386 | ap2 | 6565 | 16388 | ap3 | | 192.168.0.10 | 58340 | 2013-10-14 22:58:52.315157+09 | 2013-10-14 22:58:52.338545+09 | 2013-10-14 22:58:52.340956+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
813 | 16386 | ap2 | 813 | 16388 | ap3 | | 192.168.0.10 | 45953 | 2013-10-14 22:31:55.821467+09 | 2013-10-14 22:58:52.576682+09 | 2013-10-14 22:58:52.577416+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
4269 | 16386 | ap2 | 4269 | 16388 | ap3 | | 192.168.0.10 | 48260 | 2013-10-14 22:48:51.26448+09 | 2013-10-14 22:58:53.126676+09 | 2013-10-14 22:58:53.127381+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
767 | 16386 | ap2 | 767 | 16388 | ap3 | | 192.168.0.10 | 43970 | 2013-10-14 22:31:21.586331+09 | 2013-10-14 22:58:53.70826+09 | 2013-10-14 22:58:53.709031+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5390 | 16386 | ap2 | 5390 | 16388 | ap3 | | 192.168.0.10 | 42257 | 2013-10-14 22:54:38.804996+09 | 2013-10-14 22:58:53.89572+09 | 2013-10-14 22:58:53.89656+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5079 | 16386 | ap2 | 5079 | 16388 | ap3 | | 192.168.0.10 | 57443 | 2013-10-14 22:51:08.843638+09 | 2013-10-14 22:58:53.927719+09 | 2013-10-14 22:58:53.928401+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5381 | 16386 | ap2 | 5381 | 16388 | ap3 | | 192.168.0.10 | 41791 | 2013-10-14 22:54:29.806088+09 | 2013-10-14 22:58:53.971371+09 | 2013-10-14 22:58:53.972002+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
735 | 16386 | ap2 | 735 | 16388 | ap3 | | 192.168.0.10 | 42689 | 2013-10-14 22:30:57.442602+09 | 2013-10-14 22:58:56.524504+09 | 2013-10-14 22:58:56.525019+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
32299 | 16386 | ap2 | 32299 | 16388 | ap3 | | 192.168.0.10 | 32842 | 2013-10-14 22:28:11.23806+09 | 2013-10-14 22:58:57.302561+09 | 2013-10-14 22:58:57.303042+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
1972 | 16386 | ap2 | 1972 | 16388 | ap3 | | 192.168.0.10 | 33023 | 2013-10-14 22:36:40.548914+09 | 2013-10-14 22:58:57.484051+09 | 2013-10-14 22:58:57.485205+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6537 | 16386 | ap2 | 6537 | 16388 | ap3 | | 192.168.0.10 | 58078 | 2013-10-14 22:58:44.278245+09 | 2013-10-14 22:58:57.720632+09 | 2013-10-14 22:58:57.722393+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
2189 | 16386 | ap2 | 2189 | 16388 | ap3 | | 192.168.0.10 | 40949 | 2013-10-14 22:38:54.473697+09 | 2013-10-14 22:58:58.000865+09 | 2013-10-14 22:58:58.001475+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5290 | 16386 | ap2 | 5290 | 16388 | ap3 | | 192.168.0.10 | 38616 | 2013-10-14 22:53:41.373151+09 | 2013-10-14 22:58:59.239016+09 | 2013-10-14 22:58:59.241039+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
30721 | 16386 | ap2 | 30721 | 16388 | ap3 | | 192.168.0.10 | 58438 | 2013-10-14 22:20:07.672463+09 | 2013-10-14 22:59:01.720245+09 | 2013-10-14 22:59:01.721278+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6579 | 16386 | ap2 | 6579 | 16388 | ap3 | | 192.168.0.10 | 58723 | 2013-10-14 22:59:02.827467+09 | 2013-10-14 22:59:02.842887+09 | 2013-10-14 22:59:02.844867+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5407 | 16386 | ap2 | 5407 | 16388 | ap3 | | 192.168.0.10 | 43029 | 2013-10-14 22:54:48.647886+09 | 2013-10-14 22:59:06.837497+09 | 2013-10-14 22:59:06.838141+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6583 | 16386 | ap2 | 6583 | 16388 | ap3 | | 192.168.0.10 | 59035 | 2013-10-14 22:59:11.10654+09 | 2013-10-14 22:59:11.171647+09 | 2013-10-14 22:59:11.173401+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
3305 | 16386 | ap2 | 3305 | 16388 | ap3 | | 192.168.0.10 | 58312 | 2013-10-14 22:43:49.830214+09 | 2013-10-14 22:59:13.879135+09 | 2013-10-14 22:59:13.879769+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6589 | 16386 | ap2 | 6589 | 16388 | ap3 | | 192.168.0.10 | 59132 | 2013-10-14 22:59:13.983435+09 | 2013-10-14 22:59:13.998694+09 | 2013-10-14 22:59:14.00051+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6591 | 16386 | ap2 | 6591 | 16388 | ap3 | | 192.168.0.10 | 59150 | 2013-10-14 22:59:14.083242+09 | 2013-10-14 22:59:14.096504+09 | 2013-10-14 22:59:14.098721+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6594 | 16386 | ap2 | 6594 | 16388 | ap3 | | 192.168.0.10 | 59219 | 2013-10-14 22:59:15.2832+09 | 2013-10-14 22:59:15.435563+09 | 2013-10-14 22:59:15.437394+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
6254 | 16386 | ap2 | 6254 | 16388 | ap3 | | 192.168.0.10 | 53163 | 2013-10-14 22:57:12.247362+09 | 2013-10-14 22:57:43.994545+09 | 2013-10-14 23:00:39.03541+09 | f | INSERT INTO "userreview_display_log"("game", "uid", "ip", "agent", "referer", "timestamp") VALUES ('17147','kabugiko','e685755540d884b469a097167a19579b','Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)','http://erogamescape.dyndns.org/~ap2/ero/toukei_kaiseki/game.php?game=17147','2013-10-14 22:57:43.994545+09')
5188 | 16386 | ap2 | 5188 | 16388 | ap3 | | 192.168.0.10 | 33324 | 2013-10-14 22:52:18.950382+09 | 2013-10-14 23:00:43.218332+09 | 2013-10-14 23:00:43.219035+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7259 | 16386 | ap2 | 7259 | 16388 | ap3 | | 192.168.0.10 | 60323 | 2013-10-14 23:00:47.218423+09 | 2013-10-14 23:00:47.376782+09 | 2013-10-14 23:00:47.390744+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7310 | 16386 | ap2 | 7310 | 16388 | ap3 | | 192.168.0.10 | 60417 | 2013-10-14 23:00:48.569063+09 | 2013-10-14 23:00:48.719507+09 | 2013-10-14 23:00:48.789653+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7331 | 16386 | ap2 | 7331 | 16388 | ap3 | | 192.168.0.10 | 60443 | 2013-10-14 23:00:48.817855+09 | 2013-10-14 23:00:49.016319+09 | 2013-10-14 23:00:49.024202+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5252 | 16386 | ap2 | 5252 | 16388 | ap3 | | 192.168.0.10 | 36790 | 2013-10-14 22:53:12.055595+09 | 2013-10-14 23:00:50.195247+09 | 2013-10-14 23:00:50.196056+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
3120 | 16386 | ap2 | 3120 | 16388 | ap3 | | 192.168.0.10 | 52376 | 2013-10-14 22:42:11.229133+09 | 2013-10-14 23:00:53.981465+09 | 2013-10-14 23:00:53.98395+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
727 | 16386 | ap2 | 727 | 16388 | ap3 | | 192.168.0.10 | 42246 | 2013-10-14 22:30:49.793865+09 | 2013-10-14 23:00:58.456261+09 | 2013-10-14 23:00:58.456952+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7512 | 16386 | ap2 | 7512 | 16388 | ap3 | | 192.168.0.10 | 60991 | 2013-10-14 23:00:59.239053+09 | 2013-10-14 23:00:59.274209+09 | 2013-10-14 23:00:59.280518+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7560 | 16386 | ap2 | 7560 | 16388 | ap3 | | 192.168.0.10 | 32920 | 2013-10-14 23:01:01.412488+09 | 2013-10-14 23:01:01.538511+09 | 2013-10-14 23:01:01.562022+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
3328 | 16386 | ap2 | 3328 | 16388 | ap3 | | 192.168.0.10 | 59018 | 2013-10-14 22:44:01.752491+09 | 2013-10-14 23:01:02.51731+09 | 2013-10-14 23:01:02.519221+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
841 | 16386 | ap2 | 841 | 16388 | ap3 | | 192.168.0.10 | 46300 | 2013-10-14 22:32:02.884148+09 | 2013-10-14 23:01:04.328939+09 | 2013-10-14 23:01:04.329601+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7660 | 16386 | ap2 | 7660 | 16388 | ap3 | | 192.168.0.10 | 33164 | 2013-10-14 23:01:06.291307+09 | 2013-10-14 23:01:06.318246+09 | 2013-10-14 23:01:06.325056+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7661 | 16386 | ap2 | 7661 | 16388 | ap3 | | 192.168.0.10 | 33168 | 2013-10-14 23:01:06.297305+09 | 2013-10-14 23:01:06.353177+09 | 2013-10-14 23:01:06.358826+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7673 | 16386 | ap2 | 7673 | 16388 | ap3 | | 192.168.0.10 | 33223 | 2013-10-14 23:01:07.630712+09 | 2013-10-14 23:01:07.644601+09 | 2013-10-14 23:01:07.654124+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7680 | 16386 | ap2 | 7680 | 16388 | ap3 | | 192.168.0.10 | 33251 | 2013-10-14 23:01:08.377194+09 | 2013-10-14 23:01:08.391436+09 | 2013-10-14 23:01:08.393231+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7724 | 16386 | ap2 | 7724 | 16388 | ap3 | | 192.168.0.10 | 33277 | 2013-10-14 23:01:09.60526+09 | 2013-10-14 23:01:09.619946+09 | 2013-10-14 23:01:09.621889+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7727 | 16386 | ap2 | 7727 | 16388 | ap3 | | 192.168.0.10 | 33282 | 2013-10-14 23:01:09.887133+09 | 2013-10-14 23:01:09.902696+09 | 2013-10-14 23:01:09.904614+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7736 | 16386 | ap2 | 7736 | 16388 | ap3 | | 192.168.0.10 | 33309 | 2013-10-14 23:01:10.892136+09 | 2013-10-14 23:01:10.916172+09 | 2013-10-14 23:01:10.919248+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
7739 | 16386 | ap2 | 7739 | 16388 | ap3 | | 192.168.0.10 | 33322 | 2013-10-14 23:01:11.285771+09 | 2013-10-14 23:01:11.310435+09 | 2013-10-14 23:01:11.312774+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
30060 | 16386 | ap2 | 30060 | 16388 | ap3 | | 192.168.0.10 | 53997 | 2013-10-14 22:18:55.00588+09 | 2013-10-14 23:01:12.303238+09 | 2013-10-14 23:01:12.303762+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
5176 | 16386 | ap2 | 5176 | 16388 | ap3 | | 192.168.0.10 | 60834 | 2013-10-14 22:52:04.356903+09 | 2013-10-14 23:01:14.003891+09 | 2013-10-14 23:01:14.005589+09 | t | LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE
postgresqlの出力したログは以下の通りです。
,,,11731,2013-10-14 22:57:59.794 JST,01000,WARNING: pgstat wait timeout ,,,6398,2013-10-14 22:58:04.841 JST,01000,WARNING: pgstat wait timeout ,,,11731,2013-10-14 22:58:59.802 JST,01000,WARNING: pgstat wait timeout ,,,6592,2013-10-14 22:59:20.471 JST,01000,WARNING: pgstat wait timeout ,,,11731,2013-10-14 22:59:59.813 JST,01000,WARNING: pgstat wait timeout
強制的にロック待ち状態となっているSQLを切断した際には以下のログを大量に出力しました。
ap3,ap2,192.168.0.10(33168),7661,2013-10-14 23:04:19.171 JST,00000,LOG: sending cancel to blocking autovacuum PID 8348 ap3,ap2,192.168.0.10(33168),7661,2013-10-14 23:04:19.171 JST,00000,DETAIL: Process 7661 waits for ShareRowExclusiveLock on relation 17361 of database 16386. ap3,ap2,192.168.0.10(33168),7661,2013-10-14 23:04:19.171 JST,00000,STATEMENT: LOCK TABLE "userreview_display_log" IN SHARE ROW EXCLUSIVE MODE ,,,8348,2013-10-14 23:04:19.208 JST,57014,ERROR: canceling autovacuum task ,,,8348,2013-10-14 23:04:19.208 JST,57014,CONTEXT: automatic analyze of table "ap2.public.userreview_display_log"
また、当時、I/O waitが著しく増大していました。
考察
pid 1053で実行されていたSQL
SELECT DISTINCT ON (povgroups.game, povlist.system_group) povgroups.game, povlist.system_group, povlist.system_title, count(povgroups.pov) AS count FROM povgroups, povlist, gamelist WHERE gamelist.median >= 80 AND povgroups.pov = povlist.id AND povlist.system_group IN ('傾向', 'ジャンル') GROUP BY povgroups.game, povlist.system_group, povlist.system_title ORDER BY povgroups.game, povlist.system_group, count(povgroups.pov) DESC
は、EXPLAINするとcost=71223460.62..71224672.13です。
query_startが2013-10-14 22:34:25で、23:00の時点でも実行中の超スロークエリでした。
この超スロークエリを実行するため、スワップが発生し、I/O waitが著しく増大しました。
22:57頃、 Postgresqlのログにpgstat wait timeoutが出ていることからPostgreSQLへのアクセスが遅延するという事態が起こっています。
長文感想の閲覧ログはuserreview_display_logテーブルに保存されるのですが、INSERT INTO "userreview_display_log"~のSQLが、トランザクション開始時刻(xact_start)が2013-10-14 22:57:43にも関わらず、実際にクエリの実行が開始された時刻(query_start)が2013-10-14 23:00:39です。
トランザクションが開始されてからINSERTが実行されるまで3分もかかっています。
長文感想はとてもよく閲覧されるので、INSERT INTO "userreview_display_log"~のSQLは激しく実行されます。INSERT INTO "userreview_display_log"~を実行するため、素のままのpostgresqlや現在の最近のpgpoolでは(多分)テーブルにROW EXCLUSIVEのロックが入りますが、ErogameScapeで使っているpgpoolのVerはSHARE ROW EXCLUSIVEのロックが入ります。
Postgresqlのログから当時userreview_display_logにAUTO VACUUMが動いていたと想定されます。(この部分のログがないのと、そもそもどうログをとればいいのか分からないです。)
VACUUMが動くと、テーブルにSHARE UPDATE EXCLUSIVEが入ります。
userreview_display_logへのVACUUMは通常ですと1秒程度で終了するのですが、恐らく当時はすごい時間がかかっていて、SHARE UPDATE EXCLUSIVEがなかなか外れなかったのかと思います。
そこに、SHARE UPDATE EXCLUSIVEと競合するSHARE ROW EXCLUSIVE MODEが重なって待ちが待ちをうんでいたと推測します。
対策
以上から対策としては2点
- pgpoolのVerをあげる
- スロークエリを発見したら止める
1.については、新しいVerのpgpoolで設定の検証を実施しております。
折角だから、ついでにPostgreSQLを9.3にあげようと思って、PostgreSQL9.3と最近のpgpoolの組み合わせで検証を実施しており、とりあえずpgpool関連の設定は確定できました。
一つのサーバーに旧新混在可能ですので、設定を商用…じゃないか、えーと、運用?の設定にして、一度どこかでサービスを止めてデータを新しいPostgreSQLに移行したいと思っています。
※Index Only Scanが使えるのでSQLによっては早くなると思います。
2.については対策済みです。
具体的には5分SQLが実行され続けたらやばいだろうということで、
SELECT pg_terminate_backend(procpid) FROM pg_stat_activity WHERE procpid IN ( SELECT procpid FROM ( SELECT pid FROM pg_locks GROUP BY pid) l , pg_stat_activity a WHERE l.pid = a.procpid AND now() - query_start > '5minutes'::INTERVAL ) ;を定期的に実行することにしました。
終わりに
大変ご迷惑をおかけいたします。
対策に未だ時間がかかりますがご容赦ください。
考察が間違っている、こういった対策が必要だ、こんなログを取っといた方がいい、等ございましたらコメント、メール、Twitter等でお知らせ頂けますと幸いです。
※9月に事象が発生したときは、こんなにI/O waitは発生していなかった気がするのですが、psコマンドでVACUUMがたくさん見えていたことから多分同一事象だと思っていますが、自信が無いです。