[pgcluster: 916] Re: クラスタDBのリカバリが途中で止まる
Eiichiro ITANI
emu @ ceres.dti.ne.jp
2006年 8月 12日 (土) 02:21:10 JST
お世話になっております、猪谷です。
長文で失礼いたします。
今回私のところでも同様な状況になりました。
Start in recovery mode!
Please wait until a data synchronization finishes from Master DB...
1st recovery step of [global] directory...OK
1st recovery step of [base] directory...OK
1st recovery step of [pg_clog] directory...OK
1st recovery step of [pg_xlog] directory...OK
1st sync_table_space OK
まで行った所で完全にストップします(一時間程放置して変化無し)。
pgreplicate を非 daemon モードで走らせ直してログを見てみた所、青木さん
の場合と全く同様の状態で止まった感じです。
クラスタの OS は Ubuntu 6.06 の Xeon x86-64 な環境です。いずれのマシン
でも HTT はオフにしております。PGCluster 1.5.0rc7 に、先日頂いた
deadlock.patch と、以前英語版MLに流れていた2種のパッチ(ストアドプロシジャ
関連)を当てています。
クラスタは L1R1C2のハードウェア4台構成で、
ロードバランサ: loadbalancer_1/192.168.100.5
レプリケータ: replicate_1/192.168.100.10
クラスタ: cluster_1/192.168.100.20、cluster_2/192.168.100.21
です。いずれも、pgcluster が使用している領域はローカルのストレージ上に
確保しており、NFS などで共有している部分はありません。
今回多少設定を弄った面があるのでそれと関係があるかもしれないのですが、
少なくとも今回以前にリカバリで止まることはありませんでした。但し、以前
リカバリを試して以降データのサイズがだいぶ増えていて、今現在クラスタ1
の$PGDATA 以下に 5G 程度のデータが入っています。
今回、両クラスタサーバの postgresql.conf で work_mem、
effective_cache_size を弄ったので、まず双方で pg_ctl reload を行いまし
た。その後、一方のクラスタ(cluster_2/192.168.100.21)の max_connection
を増やしたので一旦 cluster_2 を停止、その後念のため recover モードで起
動しました。…というところで、止まっています。
# max_connection 変更後再起動が必須だったかどうかは覚えてません(_ _;)
その後、レプリケータを非デーモンモードで再起動、何度か cluster_2 を
recover モードでスタート、殺してまたスタート、などやっています。この際
に多少 pgcluster 固有設定の変更を行っていますが、おかしなホスト/ ポート
をしたり、といったミスはしていないと思います。
1st ステップの rsync が完了し、完全に待ちモードに入った所で調べてみる
と、rsync 完了直後の replicator のログは以下でした。
> 2006-08-12 01:29:12 [15473] DEBUG:cmdType=x
> 2006-08-12 01:29:12 [15473] DEBUG:rlog=-1
> 2006-08-12 01:29:12 [15473] DEBUG:port=5432
> 2006-08-12 01:29:12 [15473] DEBUG:pid=18325
> 2006-08-12 01:29:12 [15473] DEBUG:from_host=192.168.100.20
> 2006-08-12 01:29:12 [15473] DEBUG:dbName=template1
> 2006-08-12 01:29:12 [15473] DEBUG:userName=postgres
> 2006-08-12 01:29:12 [15473] DEBUG:recieve sec=1155313752
> 2006-08-12 01:29:12 [15473] DEBUG:recieve usec=110752
> 2006-08-12 01:29:12 [15473] DEBUG:query_size=21
> 2006-08-12 01:29:12 [15473] DEBUG:request_id=0
> 2006-08-12 01:29:12 [15473] DEBUG:replicate_id=0
> 2006-08-12 01:29:12 [15473] DEBUG:query=PGR_CLOSE_CONNECTION
> 2006-08-12 01:29:12 [15473] DEBUG:sem_lock [1] req
> 2006-08-12 01:29:12 [15473] DEBUG:sem_lock [1] got it
> 2006-08-12 01:29:12 [15473] DEBUG:PGRreplicate_packet_send():checking host cluster_1.jwsys.localnet for creating threads
> 2006-08-12 01:29:12 [15473] DEBUG:[0] is same host
> 2006-08-12 01:29:12 [15473] DEBUG:PGRreplicate_packet_send():checking host cluster_2.jwsys.localnet for creating threads
> 2006-08-12 01:29:12 [15473] DEBUG:sem_unlock[1]
> 2006-08-12 01:29:12 [15473] DEBUG:PGRdo_replicate():PGRreplicate_packet_send returns 0
> 2006-08-12 01:29:12 [15473] DEBUG:replicate_loop():session closed
> 2006-08-12 01:29:12 [15473] DEBUG:replicate_loop():replicate loop exit
cluster_2 上で ps で状態を見てみると
# ps auxww|grep postgres
# postgres 8997 0.0 0.1 22740 2668 pts/0 S 01:14 0:00 /usr/local/pgsql/bin/postmaster -D /srv/pgcluster/1.5.0rc7/data -i -R
とスリープ状態(なのかな?)になっており、また cluster_2 に pgcluster 関係
では postmaster 以外のプロセスは存在しません。
この段階で試しに recover 実行中の cluster を gdb attach して見たところ、
(gdb) attach 8997
〜シンボルテーブル読み込みメッセージ省略〜
(gdb) where
#0 0x00002aaaaba92d25 in select () from /lib/libc.so.6
#1 0x0000000000513822 in PGR_Recovery_Main ()
#2 0x000000000054f732 in PostmasterMain ()
#3 0x0000000000513e3e in main ()
(gdb)
となり、ネットワークのパケット待ち? の所で止まってるみたいです。さらに
lsof で postmaster の状態をチェックしてみると
> # lsof -p 8997
> COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
> postmaste 8997 postgres cwd DIR 253,0 4096 159 /srv/pgcluster/1.5.0rc7/data
> postmaste 8997 postgres rtd DIR 8,3 736 2 /
> postmaste 8997 postgres txt REG 8,3 3557699 22019 /usr/local/pgsql/bin/postgres
> postmaste 8997 postgres mem REG 0,0 0 [heap] (stat: No such file or directory)
> postmaste 8997 postgres mem REG 8,3 94448 10490 /lib/ld-2.3.6.so
> postmaste 8997 postgres mem REG 8,6 217016 2451 /var/db/nscd/passwd
> postmaste 8997 postgres mem REG 8,6 217016 2452 /var/db/nscd/group
> postmaste 8997 postgres mem REG 8,3 14475 4297 /usr/lib/locale/en_US/LC_COLLATE
> postmaste 8997 postgres mem REG 8,3 177984 4293 /usr/lib/locale/en_US/LC_CTYPE
> postmaste 8997 postgres mem REG 8,3 61 4300 /usr/lib/locale/en_US/LC_MESSAGES/SYS_LC_MESSAGES
> postmaste 8997 postgres DEL REG 0,7 1081358 /SYSV00000000
> postmaste 8997 postgres DEL REG 0,7 1114127 /SYSV00000000
> postmaste 8997 postgres mem REG 8,6 217016 2453 /var/db/nscd/hosts
> postmaste 8997 postgres mem REG 8,3 34088 1532 /lib/libpam.so.0.79
> postmaste 8997 postgres mem REG 8,3 292392 12290 /usr/lib/libssl.so.0.9.8
> postmaste 8997 postgres mem REG 8,3 1493960 12289 /usr/lib/libcrypto.so.0.9.8
> postmaste 8997 postgres mem REG 8,3 89512 2307 /usr/lib/libz.so.1.2.3
> postmaste 8997 postgres mem REG 8,3 690218 12356 /lib/libreadline.so.5.1
> postmaste 8997 postgres mem REG 8,3 20376 10495 /lib/libcrypt-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 75288 10508 /lib/libresolv-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 83424 10499 /lib/libnsl-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 10056 10496 /lib/libdl-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 546000 10497 /lib/libm-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 98224 10507 /lib/libpthread-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 1267512 10493 /lib/libc-2.3.6.so
> postmaste 8997 postgres mem REG 8,3 373480 1456 /lib/libncurses.so.5.5
> postmaste 8997 postgres 0r CHR 1,3 5436 /dev/null
> postmaste 8997 postgres 1u CHR 136,0 2 /dev/pts/0
> postmaste 8997 postgres 2u CHR 136,0 2 /dev/pts/0
> postmaste 8997 postgres 3u IPv4 162553 TCP cluster_2.jwsys.localnet:44124->replicate_1.jwsys.localnet:8001 (ESTABLISHED)
> postmaste 8997 postgres 4r CHR 1,9 2887 /dev/urandom
> postmaste 8997 postgres 5u IPv4 162554 TCP cluster_2.jwsys.localnet:60445->replicate_1.jwsys.localnet:8101 (ESTABLISHED)
となりました。
で、何も変化せず、ログも出ないので諦めて cluster_2 の postmaster を
kill してみた所、cluster_2 では何のメッセージもなくプロセスが消え去り
ます。レプリケータのログでは、
> 2006-08-12 02:06:15 [15393] DEBUG:replicate_loop():session closed
> 2006-08-12 02:06:15 [15393] DEBUG:replicate_loop():replicate loop exit
の2行が出力されていました。
…大変長くなってしまいましたが、おおよそこんな状況です。何かわかります
でしょうか? すみませんがよろしくお願いいたします。
ちなみに、今 cluster_1 に残ってるデータどうやって取り出そうか悩んでる
最中です(^^;) pg_dumpall は拒否されちゃうし…(;_;)
--
いたに えいいちろう
pgcluster メーリングリストの案内