[pgsql-jp: 40177] Re: update文のフリーズ

Eiichiro Sakai sakai ＠ agate-japan.com
2010年 2月 17日 (水) 13:24:49 JST 

fujii様、石井様

お世話になります。
酒井です。

ご返信ありがとうございます。
しかも言葉足らずで申し訳ございません。

１についてですが、SQLログというのはpostgresサーバで出力されているログで
「log_min_duration_statement = 0」にして出力しております。
ログの抜粋を下記添付させていただきますが、下記出力後同一pid(28636)のログが
出力されていない状況となっておりました。
fujii様よりexecute messageが届いてるかどうかというご指摘をいただいたのです
が、
ログを見るとSQL文を実行される際、最後のupdate文で「parse」「bind」が出力され
ていて、
「execute」が出力されていない状況です。
「bind」と「execute」の間はpostgres内部の処理と認識していたので、
SQLの実行メッセージは届いていると認識しておりました。


２についてですが、別々のトランザクション（セッション）という想定でおりまし
た。
ロック取得待ちはPostgresに届いた順にキューイングされて順番に処理されるのかと
勝手に想定しておりました。
そのためfujii様のご返信より
>OS のスケジューラ等の都合によって、クエリの実行順序は前後します。
とのことですので、ロック取得は必ずしも順番に処理されないということで了解しま
した。


------------１についてのログ抜粋--------------------
2010-02-10 13:00:29 JST [28636] LOG:  duration: 0.026 ms  bind S_1: BEGIN
2010-02-10 13:00:29 JST [28636] LOG:  execute S_1: BEGIN
2010-02-10 13:00:29 JST [28636] LOG:  duration: 0.016 ms
2010-02-10 13:00:29 JST [28636] LOG:  duration: 0.091 ms  parse <unnamed>:
select
                *
        from
                AAA
        where
                AAA_id = $1
        for update
2010-02-10 13:00:29 JST [28636] LOG:  duration: 0.128 ms  bind <unnamed>:
select
                *
        from
                AAA
        where
                AAA_id = $1
        for update
2010-02-10 13:00:29 JST [28636] DETAIL:  parameters: $1 = '9'
2010-02-10 13:00:29 JST [28636] LOG:  execute <unnamed>: select
                *
        from
                AAA
        where
                AAA_id = $1
        for update
2010-02-10 13:00:29 JST [28636] DETAIL:  parameters: $1 = '9'
2010-02-10 13:00:31 JST [28636] LOG:  duration: 1755.026 ms
---------------------
省略（他のテーブルに単純なselect文を発行）
---------------------
2010-02-10 13:00:31 JST [28636] LOG:  duration: 0.081 ms  parse <unnamed>:
update AAA set column_1 = $1, column_2 = $2, column_3 = $3, column_4 = $4,
column_5 = $5, column_6 = $6, column_7 = $7, column_8 = $8, column_9 = $9,
column_10 = $10, column_11 = $11, column_12 = $12, column_13 = $13,
column_14 = $14, VERSION = VERSION + 1 where AAA_id = $15 and VERSION = $16
2010-02-10 13:00:31 JST [28636] LOG:  duration: 0.097 ms  bind <unnamed>:
update AAA set column_1 = $1, column_2 = $2, column_3 = $3, column_4 = $4,
column_5 = $5, column_6 = $6, column_7 = $7, column_8 = $8, column_9 = $9,
column_10 = $10, column_11 = $11, column_12 = $12, column_13 = $13,
column_14 = $14, VERSION = VERSION + 1 where AAA_id = $15 and VERSION = $16
2010-02-10 13:00:31 JST [28636] DETAIL:  parameters: $1 = 'xxx', $2 = 'xxx',
$3 = 'xxx', $4 = 'xxx', $5 = 'xxx', $6 = 'xxx', $7 = 'xxx', $8 = 'xxx', $9 =
'xxx', $10 = 'xxx', $11 = 'xxx', $12 = 'xxx', $13 = 'xxx', $14 = 'xxx', $15
= '9', $16 = 'xxx'
------------これ以降28636に関するログは出力されていない--------------------



以上よろしくお願いします。


> -----Original Message-----
> From: pgsql-jp-bounces ＠ ml.postgresql.jp
> [mailto:pgsql-jp-bounces ＠ ml.postgresql.jp] On Behalf Of Tatsuo Ishii
> Sent: Tuesday, February 16, 2010 10:45 PM
> To: pgsql-jp ＠ ml.postgresql.jp; masao.fujii ＠ gmail.com
> Subject: [pgsql-jp: 40175] Re: update文のフリーズ
>
> 石井です。
>
> > 2010/2/16 Eiichiro Sakai <sakai ＠ agate-japan.com>:
> > > 以下のようなSQLをpgpool2（2.1）経由で複数のプロセスより大量に実行して
> いたと
> > > ころupdate文（下記tr2）が途中でフリーズし、その後同様のSQLを実行して
> も
> > > select for update文（下記tr1）がロック待ちの状態となり滞留し続けていく
> 状況と
> > > なりました。
> > >
> > > begin;
> > > select * from tableA where id = 1;（tr1）
> > > その他の処理
> > > update tableA SET column = xx where id = 1;（tr2）
> > > commit;
> > >
> > > １．トリガとなったupdate文のSQLログを見るとbindまでは出力されていま
> すが、
> > > executeのログが出力されていない状況で止まってしまっています。
> > > これはどのような時に発生しうるでしょうか？
> > > 回避策をご存じの方がいらっしゃればご教授いただければと思います。
> >
> > 文中の SQL ログとはどのログ (PostgreSQL のサーバログ? pgpool? アプリ独
> 自?) を
> > 指しますでしょうか?
> >
> > 可能であれば、そのログをいただけませんでしょうか?
> >
> > execute message は PostgreSQL には届いていないとの認識でよろしいでしょう
> か?
> > この認識で正しければ、問題の UPDATE の前に実行された SELECT FOR UPDATE
が
> > ロックを獲得したままになっています。このロックは COMMIT / ROLLBACK の段
階
> で
> > 開放されますが、UPDATE の execute message が届かないため、そこまで処理が
> > 進みません。このため、他の SELECT FOR UPDATE がロック待ちになったのだと
思
> われます。
> >
> > まずは、execute message がどこまで届いたのか確認してください。PostgreSQL
> まで
> > 届いていなければ、上記の通りで、pgpool またはアプリ側の問題を次に疑いま
す。
>
> ログがSQLのログだとして...
>
> executeのログが表示されないのは、executeがロック待ちで実行されていない
> 状態もあり得ます。今回はその可能性もあるのではないでしょうか。
>
> もし、tr1とtr2が本当に同じセッションだとし、かつselect for updateと
> updteのwhere句が同じなのに、tr1は実行できていてtr2が実行されない、とい
> うのはかなりあり得ない状況のように思えます。かろうじて近いのは、最近
> hackersに投稿された、ケースですが、これに当てはまるかどうか、良く分か
> りません。詳しいログを見る必要がありますね。
>
> ログにpidやセッションidが出力されていることを確認し、同一トランザクショ
> ン内で上記のような現象が起きているかどうか確認した方がよいと思います。
>
> > > ２．tr2でフリーズ後のpg_stat_activityを見るとフリーズが起こる前に実行
> されて
> > > い
> > >    るがtr1でロック待ちのままとなっているトランザクションが多数存在し
> ていま
> > > した。
> > > ただ、フリーズが起こる前は他のいくつかのトランザクションは正常終了（上
> 記
> > >    commitまで終了）している状態です。
> > > このことよりpostgresは必ずしもロック要求があった順番にロック取得
> > > しているわけではないように思えますが理解は正しいでしょうか？
> >
> > はい。アプリが発行した順序でクエリが実行されるとは限りません。OS のスケ
ジ
> ューラ等の
> > 都合によって、クエリの実行順序は前後します。
>
> 元の質問の意図は、「同じトランザクション(セッション)内で」という前提の
> 話ではないでしょうか。であれば、必ず発行した順にロックが取られます。
> --
> Tatsuo Ishii
> SRA OSS, Inc. Japan
> English: http://www.sraoss.co.jp/index_en.php
> Japanese: http://www.sraoss.co.jp

pgsql-jp メーリングリストの案内