[pgpool-general-jp: 534] Re: pgpool-II オンラインリカバリの挙動について

[Tatsuo Ishii]

石井です．

ご報告ありがとうございます．

確かに仰有る通りの実装になっているようです．なぜこうなっているのか良く分か
りませんが，コードを調べてみます．
--
Tatsuo Ishii
SRA OSS, Inc. Japan

> お世話になります。
> 平馬と申します。
> 
> pgpool-IIのレプリケーションモードにおけるオンラインリカバリについて
> 確認したい点があり、こちらのMLに参加させていただきました。
> 
> READMEやy-asaba氏の作成された資料(*1)を読んだ限りでは、pgpool-IIの
> オンラインリカバリの内部処理は、以下の処理が「順番に」実行されて
> いくものだと思っていました。
> 
> 1. CHECKPOINT 実行 (バッファ上のデータをディスクへ同期)
> 2. ファーストステージの実施 (recovery_1st_stage_command の実行)
> 3. 接続がすべて切断されるまで待機 (新規接続をブロックする)
> 4. CHECKPOINT 実行 (バッファ上のデータをディスクへ同期)
> 5. セカンドステージの実施 (recovery_2nd_stage_command の実行)
> 6. postmaster の起動 (pgpool_remote_start の実行) 
> 7. リカバリしたPostgreSQLへ接続できるか確認
> 8. ノードの復帰 (復帰を確認後、接続のブロックを解除する)
> 
> (*1) http://osb.sraoss.co.jp/event_seminar/2007/pgpool-II-2.0.pdf
> 
> しかし、何度か検証を行ってみるとこの認識と食い違う動作をしていることに
> 気づきました。
> 
> 検証手順は以下のようになります。
> 
> 1. ノード１を切り離す (pcp_detach_node)
> 2. ノード１のオンラインリカバリを開始する (pcp_recovery_node)
> 　 ※ノード１のPostgreSQLの停止をファーストステージ冒頭で実行
> 3. セカンドステージの接続ブロック中にクエリの送信を試みる
> 
> なお、検証ではPostgreSQL 8.3.5を２つと、pgpool-II 2.2 beta1を同一の
> PCで動作させています。
> 
> ---- pgpool.conf (抜粋) ----
> port = 5432
> replication_mode = true
> load_balance_mode = true
> backend_hostname0 = ''
> backend_port0 = 5433
> backend_weight0 = 1
> backend_data_directory0 = '/usr/local/pgsql/data'
> backend_hostname1 = ''
> backend_port1 = 5434
> backend_weight1 = 1
> backend_data_directory1 = '/usr/local/pgsql/data2'
> ---- pgpool.conf (抜粋) ----
> 
> ---- postgresql.conf (マスタノード側) ----
> port = 5433
> archive_mode = on
> archive_command = 'cp %p /usr/local/pgsql/data/archive_log/%f'
> log_line_prefix = '%t [%p]: [%l-1] '
> ---- postgresql.conf (マスタノード側) ----
> 
> ---- pgpool-II側ログ ----
> 2009-02-02 15:04:03 LOG:   pid 11985: 1 node restarted
> 2009-02-02 15:04:03 LOG:   pid 11985: send_failback_request: fail back 1 th node request from pid 11985
> 2009-02-02 15:04:03 LOG:   pid 11985: recovery done
> 2009-02-02 15:04:03 LOG:   pid 11991: connection received: host=127.0.0.1 port=52412
> 2009-02-02 15:04:03 LOG:   pid 11992: connection received: host=127.0.0.1 port=52413
> 2009-02-02 15:04:03 LOG:   pid 11951: starting fail back. reconnect host localhost(5434)
> 2009-02-02 15:04:03 LOG:   pid 11951: failover_handler: set new master node: 0
> 2009-02-02 15:04:03 LOG:   pid 11951: failback done. reconnect host localhost(5434)
> ---- pgpool-II側ログ ----
> 
> ---- PostgreSQL(マスタノード)側ログ ----
> 2009-02-02 15:04:02 JST [12036]: [3-1] LOG:  duration: 14930.568 ms  statement: SELECT pgpool_remote_start('localhost', '/usr/local/pgsql/data2')
> 2009-02-02 15:04:03 JST [12627]: [1-1] LOG:  could not send data to client: Broken pipe
> 2009-02-02 15:04:03 JST [12628]: [1-1] LOG:  could not send data to client: Broken pipe
> ---- PostgreSQL(マスタノード)側ログ ----
> 
> ログを確認しながらpgpool-IIのソースコードを読んでみたところ、次の
> ような動作をしているように思えます。
> 
> 1. pid 11985にて、send_failback_request() が実行され、フェイルバック
> 　 処理の開始を指示する。
> 2. pid 11985にて、finish_recovery() がリカバリ状態フラグ InRecovery を
> 　 0 に設定する。
> 　 この時点でpreforkしている子プロセスの do_accept() の接続ブロックが
> 　 解除されてしまう。
> 3. pid 11991と11992にて、do_accept() が接続を受け入れる。
> 4. ここでようやくpid 11951にて、failover()が実行され、preforkしている
> 　 pgpool-IIの子プロセスを全てkillする。
> 　 これによりpid 11991と11992がkillされるため、pid 12627と12628が中断
> 　 される。
> 
> これが仕様であるかバグであるかはわかりませんが、現在の実装では、
> 
> 1. ノード復帰前にクエリの処理が開始されてしまうことがあるため、
> 　 レプリケーションが必要なクエリが復帰予定のノードに対して送られない
> 　 可能性がある。
> 2. ノード復帰前に開始されてしまった処理は中断される可能性がある。
> 
> という認識で間違いないでしょうか？
> 
> 
> 以上、よろしくお願いいたします。
> _______________________________________________
> pgpool-general-jp mailing list
> pgpool-general-jp ＠ sraoss.jp
> http://www.sraoss.jp/mailman/listinfo/pgpool-general-jp