[pgsql-jp: 36568] Re: JDBC+pgpool利用時の不具合(!?)について

YAMADA Toshio toshi @ mx1.freemail.ne.jp
2005年 12月 17日 (土) 02:01:02 JST


山田です。

石井様>
たびたびのご対応と修正版のご提供、感謝しております。

Date: Thu, 15 Dec 2005 23:50:16 +0900 (JST)
From: Tatsuo Ishii <ishii @ sraoss.co.jp>
> 本日本家MLでちょっとやり取りしてみたのですが、結果 Execute したあとに、
> pgpoolの中から"Flush"というメッセージを送ってあげればよさそうだ、とい
> うことが分かりました。Flushは、バックエンドに対して、バッファリングさ
> れているメッセージをすべてフロントエンドに送るように指示します。これで
> Executeの完了が間接的に分かるので、うまくいくと思います。

ふむ、ふむ、syncの前にflushというのは、なんとなく感覚で
理解できますです。

それで、修正版のほうで試させていただきました。
結果ですが、5回ほど実行しまして、うち2回が2サーバーから
10000行の挿入に成功して、他3回が最初のメールと同じように
デッドロック(!?)と思われる現象が発生しました。
最初の時点よりは格段に発生率が下がりましたが、
なんともすっきりとしない結果になってしまいました。

上記のflushとは別の要素や、私どものシステム環境(OSとかH/W)の
話になってくるんでしょうか?

気になると言えば、PostgreSQLが受け取るコマンドを見ると、
通常は理路整然と PREPARE->BIND->EXECUTE と順番に繰り返し
ているのですが、やはり、停止時にはLOCKコマンドが
PREPARE, PREPARE, EXECUTE, EXECUTE
と交差した状態になっています。
#…というか、これは結局"結果"で、こういう現象が発生する
#ときにデッドロック(!?)と思しき状態になるのですかね?

上記以外でなにか気になる点(設定や環境)等ございましたら、
お知らせいただけると幸いです。

長くなってしまい恐縮ですが、念のためログを追記いたします。
それでは、よろしくお願いいたします。


■(8)[app1:down側] pgpoolデバッグ出力(13:26:20停止近辺抜粋)
----------------------------------------------------------------
2005-12-16 13:26:20 DEBUG: pid 7108: ReadyForQuery: message length: 5
2005-12-16 13:26:20 DEBUG: pid 7108: ReadyForQuery: transaction state: I
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend B(42)
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend E(45)
2005-12-16 13:26:20 DEBUG: pid 7108: Execute: portal name <>
2005-12-16 13:26:20 DEBUG: pid 7108: waiting for backend[0] completing the query
2005-12-16 13:26:20 DEBUG: pid 7108: waiting for backend[1] completing the query
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend P(50)
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend B(42)
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend D(44)
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend E(45)
2005-12-16 13:26:20 DEBUG: pid 7108: Execute: portal name <>
2005-12-16 13:26:20 DEBUG: pid 7108: waiting for backend[0] completing the query
2005-12-16 13:26:20 DEBUG: pid 7108: waiting for backend[1] completing the query
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from frontend S(53)
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from backend 2
2005-12-16 13:26:20 DEBUG: pid 7108: pool_process_query: waiting for secondary for data ready
2005-12-16 13:26:20 DEBUG: pid 7108: pool_process_query: kind from backend: 2
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from backend pending data C len: 10 po: 5
2005-12-16 13:26:20 DEBUG: pid 7108: pool_process_query: kind from backend: C
2005-12-16 13:26:20 DEBUG: pid 7108: read kind from backend 1
2005-12-16 13:26:20 DEBUG: pid 7108: pool_process_query: waiting for secondary for data ready
2005-12-16 13:26:36 LOG:   pid 7090: starting health checking
2005-12-16 13:27:06 LOG:   pid 7090: starting health checking
2005-12-16 13:27:10 ERROR: pid 7108: pool_check_fd: data is not ready tp->tv_sec 50 tp->tp_usec 50000000
2005-12-16 13:27:10 ERROR: pid 7108: pool_process_query: secondary data is not ready at synchronous point. abort this session
2005-12-16 13:27:10 ERROR: pid 7108: pool_process_query: kind does not match between backends master(1) secondary(^@)
2005-12-16 13:27:10 LOG:   pid 7108: notice_backend_error: master: 1 fail over request from pid 7108
2005-12-16 13:27:10 DEBUG: pid 7090: failover_handler called
2005-12-16 13:27:10 LOG:   pid 7090: starting degeneration. shutdown master host log-online1(5432)
2005-12-16 13:27:10 DEBUG: pid 7090: kill 7091
2005-12-16 13:27:10 DEBUG: pid 7090: kill 7092
----------------------------------------------------------------

■(9)[app2] pgpoolデバッグ出力(13:26:20停止近辺抜粋)
----------------------------------------------------------------
2005-12-16 13:26:20 DEBUG: pid 27023: waiting for backend[0] completing the query
2005-12-16 13:26:20 DEBUG: pid 27023: waiting for backend[1] completing the query
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from frontend P(50)
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from frontend B(42)
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from frontend D(44)
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from frontend E(45)
2005-12-16 13:26:20 DEBUG: pid 27023: Execute: portal name <>
2005-12-16 13:26:20 DEBUG: pid 27023: waiting for backend[0] completing the query
2005-12-16 13:26:20 DEBUG: pid 27023: waiting for backend[1] completing the query
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from frontend S(53)
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from backend 2
2005-12-16 13:26:20 DEBUG: pid 27023: pool_process_query: waiting for secondary for data ready
2005-12-16 13:26:20 DEBUG: pid 27023: pool_process_query: kind from backend: 2
2005-12-16 13:26:20 DEBUG: pid 27023: read kind from backend pending data C len: 10 po: 5
2005-12-16 13:26:20 DEBUG: pid 27023: pool_process_query: kind from backend: C
2005-12-16 13:26:36 LOG:   pid 27002: starting health checking
2005-12-16 13:27:06 LOG:   pid 27002: starting health checking
2005-12-16 13:27:10 DEBUG: pid 27023: read kind from backend 1
2005-12-16 13:27:10 DEBUG: pid 27023: pool_process_query: waiting for secondary for data ready
2005-12-16 13:27:10 DEBUG: pid 27023: pool_process_query: kind from backend: 1
2005-12-16 13:27:10 DEBUG: pid 27023: read kind from backend pending data 2 len: 31 po: 5
2005-12-16 13:27:10 DEBUG: pid 27023: pool_process_query: kind from backend: 2
2005-12-16 13:27:10 DEBUG: pid 27023: read kind from backend pending data n len: 26 po: 10
----------------------------------------------------------------

■(10)[db1:master] 停止近辺PostgreSQLログ
----------------------------------------------------------------
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
2005-12-16 13:26:20 JST[12444 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*1*/ LOCK t1
2005-12-16 13:26:20 JST[12444 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-16 13:26:20 JST[12444 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-16 13:26:20 JST[12444 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SELECT MAX(id) AS max_id FROM t1]
2005-12-16 13:26:20 JST[12444 LOG:  statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-16 13:26:20 JST[12444 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-16 13:26:20 JST[12444 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
2005-12-16 13:26:20 JST[12444 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
2005-12-16 13:26:20 JST[12444 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*1*/ LOCK t1
2005-12-16 13:26:20 JST[12444 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12445 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*2*/ LOCK t1
2005-12-16 13:26:20 JST[12444 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-16 13:26:20 JST[12445 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[12445 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*2*/ LOCK t1]
2005-12-16 13:27:10 JST[12444 LOG:  could not receive data from client: Connection reset by peer
2005-12-16 13:27:10 JST[12444 LOG:  unexpected EOF on client connection
2005-12-16 13:27:10 JST[12445 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-16 13:27:10 JST[12445 LOG:  statement: <BIND>
----------------------------------------------------------------

■(11)[db2:secondary] 停止近辺PostgreSQLログ
----------------------------------------------------------------
2005-12-16 13:26:20 JST[11820 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-16 13:26:20 JST[11820 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-16 13:26:20 JST[11820 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[11820 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SELECT MAX(id) AS max_id FROM t1]
2005-12-16 13:26:20 JST[11820 LOG:  statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-16 13:26:20 JST[11820 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[11820 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-16 13:26:20 JST[11820 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[11820 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
2005-12-16 13:26:20 JST[11820 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[11820 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
2005-12-16 13:26:20 JST[11820 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*1*/ LOCK t1
2005-12-16 13:26:20 JST[11820 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[11821 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*2*/ LOCK t1
2005-12-16 13:26:20 JST[11821 LOG:  statement: <BIND>
2005-12-16 13:26:20 JST[11821 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*2*/ LOCK t1]
2005-12-16 13:26:20 JST[11820 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-16 13:27:10 JST[11821 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-16 13:27:10 JST[11821 LOG:  statement: <BIND>
2005-12-16 13:27:10 JST[11821 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SELECT MAX(id) AS max_id FROM t1]
2005-12-16 13:27:10 JST[11821 LOG:  statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
----------------------------------------------------------------

-- 
by YAMADA Toshio <toshi @ mx1.freemail.ne.jp>



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