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

Tatsuo Ishii ishii @ sraoss.co.jp
2006年 1月 3日 (火) 19:44:27 JST


あけましておめでとうございます。石井です。

以下の件ですが、残念ながらまだ原因が分かっていません。しかし、他にも
fixが溜まっていたり、海外から機能追加リクエストがあったので、とりあえ
ず現状のまま2.7としてリリースしました。

最新版は、

http://pgfoundry.org/frs/download.php/572/pgpool-2.7.tar.gz

から入手できます。いつものように、Vine Linux用のRPM/SRPMも用意しました。
ただし、今回からはVine Linux 3.2用になっています(たぶん2.6でもrebuild
すればOKだと思います)。

以下、NEWSからの引用。

2.7(kalekale) 2006/01/03

      o child_max_connectionsオプションを追加。各pgpool子プロセスへの
	接続回数がこの設定値を超えると、その子プロセスを終了する。
	child_life_timeやconnection_life_timeが効かないくらい忙しいサー
	バで、PostgreSQLバックエンドが肥大化するのを防ぐのに有効。
	contributed by Pomarede Nicolas

      o ignore_leading_white_spaceオプションを追加。SQL文の先頭に追加
        されたホワイトスペースを無視する。DBI/DBD:Pgのコンビネーション
        は勝手に行頭にホワイトスペースを追加する結果、ロードバランスさ
        れなくなるらしい。

      o V2プロトコルで、copyの最中にreadがEOFを検出した場合に対応して
        いなかったのを修正(stdinからのcopyがCTRL-Cで強制終了した場合な
        どに起こる)

      o master/slaveモード時に縮退運転させるサーバがmaster/slaveで逆に
        なっていたのを修正

      o extended queryでExecute実行時にコマンドの完了待ちをしていない
	ためにデッドロックが起きる問題に対応(Flushメッセージを送信)
	詳細は[pgsql-jp: 36546]を参照
--
Tatsuo Ishii
SRA OSS, Inc. Japan

> 山田です。
> たいへんお忙しいところ、ログ調査ならびにテストプログラムの提示、
> ありがとうございました。
> 
> とりあえずご回答から…。
> 
> > 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 メーリングリストの案内