[pgsql-jp: 37844] Re: kind mismatch between backends

Tatsuo Ishii ishii @ sraoss.co.jp
2006年 12月 23日 (土) 00:57:33 JST


石井です.

> 中井です。
> 
> お世話になります。
> # とても光栄です。

そう言われると恐縮します:-)

> Tatsuo Ishii wrote:
> > 石井です.
> > 
> >> 中井です。
> >> 
> >> ありがとうございます。
> > 
> > どういたしまして.
> > 
> >> Tatsuo Ishii wrote:
> >> > とりあえずエラーが発生したときのpgpoolのエラーログを見せていただけます
> >> > か?  また,同じテーブルに関する他の種類のSELECT文ではエラーは出ないの
> >> > でしょうか?
> >> 
> >> 必ずエラーが出るわけではないです。
> >> 
> >> 2006-12-22 08:31:00 LOG:   pid 22580: statement: show pool_status
> >> ;
> >> 2006-12-22 08:31:01 LOG:   pid 22930: statement:  RESET ALL
> >> 2006-12-22 08:31:01 LOG:   pid 22930: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:31:01 LOG:   pid 22930: statement: DEALLOCATE "S_1"
> >> 2006-12-22 08:31:01 LOG:   pid 22930: statement: DEALLOCATE "S_2"
> >> 2006-12-22 08:31:14 LOG:   pid 22930: statement:  RESET ALL
> >> 2006-12-22 08:31:14 LOG:   pid 22930: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:31:14 LOG:   pid 22930: statement: DEALLOCATE "S_1"
> >> 2006-12-22 08:31:14 LOG:   pid 22930: statement: DEALLOCATE "S_2"
> >> 2006-12-22 08:31:22 LOG:   pid 22930: statement:  RESET ALL
> >> 2006-12-22 08:31:22 LOG:   pid 22930: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:31:22 LOG:   pid 22930: statement: DEALLOCATE "S_1"
> >> 2006-12-22 08:31:22 LOG:   pid 22930: statement: DEALLOCATE "S_2"
> >> 2006-12-22 08:31:39 LOG:   pid 22580: statement:  RESET ALL
> >> 2006-12-22 08:31:39 LOG:   pid 22580: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:32:12 ERROR: pid 22580: read_kind: kind does not match
> >> between backends master(82) secondary(69)
> >> 2006-12-22 08:32:46 LOG:   pid 22580: statement: select * from workflow
> >> 2006-12-22 08:33:14 LOG:   pid 22580: statement:  RESET ALL
> >> 2006-12-22 08:33:14 LOG:   pid 22580: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:33:36 LOG:   pid 22580: statement: select * from workflow
> >> 2006-12-22 08:33:36 LOG:   pid 22580: statement:  RESET ALL
> >> 2006-12-22 08:33:36 LOG:   pid 22580: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:34:18 LOG:   pid 22930: statement: select * from workflow
> >> 2006-12-22 08:35:46 ERROR: pid 22930: ProcessFrontendResponse: failed to
> >> read kind from frontend. fronend abnormally exited
> >> 2006-12-22 08:35:46 LOG:   pid 22930: do_child: exits with status 1 due
> >> to error
> >> 2006-12-22 08:37:00 LOG:   pid 22580: statement:  RESET ALL
> >> 2006-12-22 08:37:00 LOG:   pid 22580: statement:  SET SESSION
> >> AUTHORIZATION DEFAULT
> >> 2006-12-22 08:37:00 LOG:   pid 22580: statement: DEALLOCATE "S_1"
> >> 2006-12-22 08:37:00 LOG:   pid 22580: statement: DEALLOCATE "S_2"
> >> 2006-12-22 08:39:02 ERROR: pid 22580: pool_check_fd: data is not ready
> >> tp->tv_sec 5 tp->tp_usec 5000000
> >> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: secondary data
> >> is not ready at synchronous point. abort this session
> >> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: kind does not
> >> match between backends master(E) secondary( (~'@)
> >> 2006-12-22 08:39:02 ERROR: pid 22580: health check failed during write.
> >> master  at port 9999 is down
> >> 2006-12-22 08:39:02 LOG:   pid 22580: notice_backend_error: master: 1
> >> fail over request from pid 22580
> >> 2006-12-22 08:39:02 LOG:   pid 12091: starting degeneration. shutdown
> >> master host (9999)
> >> 2006-12-22 08:39:02 LOG:   pid 12091: degeneration done. shutdown master
> >> host (9999)
> >> 
> >> pid 22580 は、ssh で入って psql でデータベースを検査していた
> >> ところです。show pool_status; の結果は正常でした。
> >> 動作チェックで select * を行う前に、最初のエラーメッセージが
> >> 出ています。でも画面(psql)では、エラーがでませんでした。
> > 
> > これですね.
> > 
> >> 2006-12-22 08:32:12 ERROR: pid 22580: read_kind: kind does not match
> >> between backends master(82) secondary(69)
> > 
> > 82は"R"で,認証要求のパケットです.なのでたぶんこれは正常.secondaryの
> > 69("i")が変ですね.これは"Empty Query Response"で,空のクエリを送った
> > ときの応答です.なぜこんなものが返ってくるのか...調べてみます.
> 
> show pool_status以外なにもしていないときなんです。

そうですか.

> kind does not match で直ちに縮退運転に入るわけではないんですね。

replication_stop_on_mismatch = true

になっていない限り,該当pgpool子プロセスをkillするだけで,縮退にはなり
ません.

> > ところで,
> > 
> >> 2006-12-22 08:37:00 LOG:   pid 22580: statement: DEALLOCATE "S_1"
> >> 2006-12-22 08:37:00 LOG:   pid 22580: statement: DEALLOCATE "S_2"
> > 
> > というのがあります.pid 22580はpsqlで接続しているんですよね?このメッセー
> > ジはprepared queryが使われたことを示していますが,実際使ってますか?
> 
> 使っていません。このメッセージは不定期に頻繁に出ています。

確認ですが,psql以外から接続するときには,このシステムではJavaから接続
するなどして,prepared queryを使うこともあるのでしょうか?

> >> 何回かやっているうちにハングしてしまいました。
> > 
> > これですね.
> > 
> >> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: secondary data
> >> is not ready at synchronous point. abort this session
> >> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: kind does not
> >> match between backends master(E) secondary( (~'@)
> > 
> > これは,secondaryから応答が返ってこなくなり,タイムアウトしたことを示
> > しています.確認ですが,secondaryのpostmasterをshutdownするとか,そう
> > いう操作はされていないですよね?
> 
> 少なくともsecondaryでは何もしていません。
> master側でpsql接続で検査していただけです。
> ハングしたので、master側で、一つずつ子供のプロセスから
> kill していきました。汗;
> 
> >> 従って、この時点では、データベースに異常があったとはわかりません
> >> でした。
> >> # 変ですね。
> >> 
> >> エラー行 08:39:02 の secondary の kind は化けています。
> >> この時点でアプリケーションがエラーを返し、アプリケーションのログに
> >> kind does not smatch が残りました。
> >> このあとしばらくたってから、エラーメッセージ(08:39:02のもの)メールが
> >> 届いて気づきました。縮退運転に入るとメールを飛ばすようにしてあるのです。
> >> 08:32:12の時点では、縮退運転に入っていませんでした。
> >> # これも変ですね。
> > 
> > これですね.
> > 
> >> 2006-12-22 08:39:02 ERROR: pid 22580: health check failed during write.
> >> master  at port 9999 is down
> > 
> > pgpoolから見ると,masterのhealth checkに失敗しているように見えます.
> > ログだけ見ると,postmasterをshutdownしているように見えるのですが...
> 
> ドキッ。ps で Idle になっていた psql は kill しましたが、
> postmaster には手をつけていません。今、ps で見ても、postmaster は
> 生きていますし、PID も pgpool より小さい値だし。(未だ、一周していない)
> history で確認しましたが、若い PID しか kill していないです。
> master at port 9999 is down というは、socket open できなかったという
> ことでしょうか。
> 「secondaryの応答がないので、health check して master が死んでいるから
> master を切り離した。」んですね。ますますわからなくなってきました。

いえ,そうではありません.secondryから応答がないことと,health checkが
失敗したのは無関係です.secondryから応答がないということは,実際のデー
タのやりとりの際にpgpoolの子プロセスで検出されています.health checkは
pgpoolの親プロセスがタイマーで定期的に実施しています.

> 2006-12-22 08:39:02 ERROR: pid 22580: health check failed during
> write.

は,socketをopenし,スタートアップパケットをpostmasterに送信するために
writeしたら失敗した,ということを示します.この現象が発生するのは,
postmasterをshutdownしている最中とか,存在しないDBユーザでhealth check
した際に起こります(ユーザは"health_check_user"で指定します).

> >> master  at port 9999 is down

で,そのwriteに失敗したのはmasterのpostmasterだったと,このログは報告
しています.
--
Tatsuo Ishii
SRA OSS, Inc. Japan



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