[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 メーリングリストの案内