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

YAMADA Toshio toshi @ mx1.freemail.ne.jp
2005年 12月 19日 (月) 22:19:49 JST


山田です。
たいへんお忙しいところ、ログ調査ならびにテストプログラムの提示、
ありがとうございました。

とりあえずご回答から…。

> 1) 添付のlibpqプログラムをJavaと同じような条件で実行して問題が起きない
>    かどうか

問題は起きませんでした。例によって、2サーバーから同時投入で
5回ほど実行しましたが、いずれも問題なく実行できました。


> 2) 山田さんのプログラムでの正常ケースでのpgpoolのログ取得

後述の■(12)に挙げるログを繰り返しているようです。すなわち

> のように、Parse, Bind, Describe, Execute, Syncと来ていきなり2(Bind
> complete)が返ってきています。これは本来1が来てから2が返らなければなら
> ないはずなのですが。

に焦点を当てますと、通常稼動では 2, 1, 1, 2, 2, 1, 1, 2, .... 
と返ってきているようです。

     *     *     *

それで、石井様のこのご指摘をいただきまして、PostgreSQLのログを
libpqのCプログラムの実行結果と比較しながらもう一度みてみました。

JDBC利用のプログラムでは、初回のBEGINおよびCOMMITが S_1, S_2 と
plan_nameを設定してPREPAREされていまして、2回目以降の処理では、
PREPAREコマンド自体が発行されていません(■(13)を参照)。
libpqの方は毎回きれいにPREPARE→BIND→EXECUTEしています。
#<unnamed>だと再利用されない…ということなんでしょうか??

今回のJavaのテストプログラムでは、このBEGINとCOMMITはそれぞれ
 con.setAutoCommit(false);
 con.commit();
のように(Connectionクラスのメソッドで)投入されていますので、
このメソッドを使わずに明示的にSQLステートメントで
 BEGIN
 COMMIT
の命令を発行するように変えたところ、問題は起きなくなりました。
BEGINとCOMMITが<unnamed>でPREPAREされ、read kind from backend も
きっちり全回 1 を返しています。
#pgpoolは石井様のflush修正が入ったバージョンです。

もちろん、このsetAutoCommit()やcommit()メソッドを利用していても、
PostgreSQLを直接叩く場合では問題なかったですし、そもそもこれは
pgpoolがどうこうという解決案とは違うと思いますが、とりあえず
現状のご報告ということで…。

では、よろしくお願いいたします。


■(12) pgpool_log (Java 正常稼動時)
----------------------------------------------------------------------
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend P(50)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend B(42)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend D(44)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend E(45)
2005-12-19 17:31:29 DEBUG: pid 3292: Execute: portal name <>
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[0] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[1] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend S(53)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend 2
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 2
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data C len: 10 po: 5
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: C
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend 1
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 1
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data 2 len: 31 po: 5
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 2
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data n len: 26 po: 10
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: n
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data C len: 21 po: 15
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: C
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data Z len: 5 po: 31
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_read_message_length: lenghth: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: message length: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: transaction state: T
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend P(50)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend B(42)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend D(44)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend E(45)
2005-12-19 17:31:29 DEBUG: pid 3292: Execute: portal name <>
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[0] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[1] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend S(53)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend 1
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 1
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data 2 len: 61 po: 5
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 2
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data T len: 56 po: 10
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: T
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data D len: 24 po: 42
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: D
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data C len: 11 po: 55
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: C
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_read_message_length: lenghth: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: message length: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: transaction state: T
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend P(50)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend B(42)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend D(44)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend E(45)
2005-12-19 17:31:29 DEBUG: pid 3292: Execute: portal name <>
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[0] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[1] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend S(53)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend 1
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 1
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data 2 len: 25 po: 5
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 2
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data n len: 20 po: 10
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: n
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data C len: 15 po: 15
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: C
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_read_message_length: lenghth: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: message length: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: transaction state: T
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend B(42)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend E(45)
2005-12-19 17:31:29 DEBUG: pid 3292: Execute: portal name <>
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[0] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[1] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend S(53)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend 2
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: 2
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend pending data C len: 11 po: 5
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: C
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from backend Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: waiting for secondary for data ready
2005-12-19 17:31:29 DEBUG: pid 3292: pool_process_query: kind from backend: Z
2005-12-19 17:31:29 DEBUG: pid 3292: pool_read_message_length: lenghth: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: message length: 5
2005-12-19 17:31:29 DEBUG: pid 3292: ReadyForQuery: transaction state: I
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend B(42)
2005-12-19 17:31:29 DEBUG: pid 3292: read kind from frontend E(45)
2005-12-19 17:31:29 DEBUG: pid 3292: Execute: portal name <>
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[0] completing the query
2005-12-19 17:31:29 DEBUG: pid 3292: waiting for backend[1] completing the query
----------------------------------------------------------------------

■(13) PostgreSQLログ (Java投入ログ:2回目以降のBEGINとCOMMITは使い回し??)
----------------------------------------------------------------------
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE S_1 AS BEGIN
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*1*/ LOCK t1
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SELECT MAX(id) AS max_id FROM t1]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE S_2 AS COMMIT
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*1*/ LOCK t1
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SELECT MAX(id) AS max_id FROM t1]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  BEGIN]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS /*STRICT*/ /*1*/ LOCK t1
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  /*STRICT*/ /*1*/ LOCK t1]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  SELECT MAX(id) AS max_id FROM t1]
2005-12-19 15:22:43 JST[9355 LOG:  statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-19 15:22:43 JST[9355 LOG:  statement: <BIND>
2005-12-19 15:22:43 JST[9355 LOG:  statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
----------------------------------------------------------------------

以上


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



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