[pgsql-jp: 36438] Re: pgpoolでfail Overするタイミング

[森山 和宏]

石井様

moriyamaです

返信ありがとうございました。

> どうやらまたもやVACUUMをCSEから実行されているようですね。あのツールは
> 挙動が不可解だし(なぜか必ずクエリのキャンセルをするし...)、使っている
> libpqのバージョンが古く、更新も止まっているようなので使うのを止めた方
> がいいと思います(問題の切り分けの邪魔になることもあります)。

やはり、もう使用を中止したほうが良さそうですね。
現在 psqledit にツールの変更を考えています。

VACUUM自体はサーバにTELNETでログインして実行しました
その際、現象確認用にCSEで接続してshowコマンドでDBの切断を確認しました。

./pg8x/bin/vacuumdb -p5530 -a -z >/dev/null &

5530 ポートはpgpoolのポートです

>> 2005-11-21 19:13:10 ERROR: pid 31850: pool_process_query: kind does not
>> match between backends master(E) secondary(P)
>
> というエラーは、マスタがE(エラー)を返しているのに、セカンダリは
> P(CursorResponse)を返していることを示しています。もし本当にこれが
> VACUUMを実行した直後の状態だとすると、かなり不可解ですね。VACUUMがEを
> 返すことはありますが、Pを返すことはあり得ません。Pが返るのは検索をし
> たときだけです。VACUUMだけでなく、SELECTか何かを実行しているように見え
> ますが、違いますか?

pgpoolのテストをしながらWebアプリからの動作確認もしていたのでSELECT系
のSQLが実行されている可能性が十分あります。
pgpoolのログを見てみたところpool_process_query: kind from backend: E　と
エラーが出ているSQLが大量に出てきました。

SQLの内容から、おそらくCSEでテーブルのプロパティを呼んだ時にエラーを起こしている
気がします。
とりあえずCSEの使用を止めて、他操作時に同様のSQLエラーが発生していないか
確認して見ます。

2005-11-21 19:48:03 DEBUG: pid 32248: read kind from backend pending data C 
len: 8 po: 165
2005-11-21 19:48:03 DEBUG: pid 32248: pool_process_query: kind from backend: 
C
2005-11-21 19:48:03 DEBUG: pid 32248: pool_read_string: read all from 
pending data. po:172 len:1
2005-11-21 19:48:03 DEBUG: pid 32248: Complete Command Response: string: 
"SELECT"
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from backend pending data Z 
len: 0 po: 0
2005-11-21 19:48:03 DEBUG: pid 32248: pool_process_query: kind from backend: 
Z
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from frontend Q(51)
2005-11-21 19:48:03 DEBUG: pid 32248: pool_read_string: read all from 
pending data. po:0 len:0
2005-11-21 19:48:03 DEBUG: pid 32248: Query: SELECT 
s.seq_scan,s.seq_tup_read,s.idx_scan,s.idx_tup_fetch,s.n_tup_ins,s.n_tup_upd,s.n_tup_del,i
o.heap_blks_read,io.heap_blks_hit,io.idx_blks_read,io.idx_blks_hit,io.toast_blks_read,io.toast_blks_hit,io.tidx_blks_read,io.tidx_blks_hit 
,oi
d as InternalOid FROM pg_catalog.pg_class c left join 
pg_catalog.pg_stat_all_tables s on c.oid=s.relid left join 
pg_catalog.pg_statio_all_tabl
es io on c.oid=io.relid WHERE pg_catalog.pg_table_is_visible(c.oid) AND 
c.relname ='corp_session'
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from backend E
2005-11-21 19:48:03 DEBUG: pid 32248: pool_process_query: kind from backend: 
E
2005-11-21 19:48:03 DEBUG: pid 32248: pool_read_string: read all from 
pending data. po:0 len:0
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from backend Z
2005-11-21 19:48:03 DEBUG: pid 32248: pool_process_query: kind from backend: 
Z
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from frontend Q(51)
2005-11-21 19:48:03 DEBUG: pid 32248: pool_read_string: read all from 
pending data. po:0 len:0
2005-11-21 19:48:03 DEBUG: pid 32248: Query: SELECT 
s.seq_scan,s.seq_tup_read,s.idx_scan,s.idx_tup_fetch,s.n_tup_ins,s.n_tup_upd,s.n_tup_del,i
o.heap_blks_read,io.heap_blks_hit,io.idx_blks_read,io.idx_blks_hit,io.toast_blks_read,io.toast_blks_hit,io.tidx_blks_read,io.tidx_blks_hit 
FRO
M pg_catalog.pg_class c left join pg_catalog.pg_stat_all_tables s on 
c.oid=s.relid left join pg_catalog.pg_statio_all_tables io on c.oid=io.re
lid WHERE pg_catalog.pg_table_is_visible(c.oid) AND c.relname 
='corp_session'
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from backend P
2005-11-21 19:48:03 DEBUG: pid 32248: pool_process_query: kind from backend: 
P
2005-11-21 19:48:03 DEBUG: pid 32248: pool_read_string: read all from 
pending data. po:6 len:411
2005-11-21 19:48:03 DEBUG: pid 32248: read kind from backend pending data T 
len: 410 po: 7