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

[Akira HEIMA]

お世話になります。
平馬と申します。

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. ノード復帰前に開始されてしまった処理は中断される可能性がある。

という認識で間違いないでしょうか？


以上、よろしくお願いいたします。