[pgcluster: 784] リグレッションテスト実行時に無応答となる

kondo_yo @ itg.hitachi.co.jp kondo_yo @ itg.hitachi.co.jp
2005年 6月 14日 (火) 17:05:46 JST


はじめまして。近藤と申します。

PGCluster 1.1.1aのフルパッケージ版をインストール後,ロードバランサ上でregression test
を実行したところ,途中の項目(test bit)でダンマリ状態となってしまいました。
レプリケーションサーバ,クラスタサーバのログを見ると,copyコマンド(COPY varbit_table FROM stdin)
で止まっているように見えます。
各クラスタサーバのログを確認したところ,ダンマリになるまではレプリケーションは正常に動作しているようでした。
同様の現象を経験された方がいらっしゃいましたら,原因などご教示いただけませんでしょうか。

−−環境,ログなど−−−−−−−−−−−−−−−−−−−−−−−−−−−−−
<使用バージョン>
 PGCluster 1.1.1a
 OS: Red Hat Enterprise Linux AS 3

<マシン構成>
 ロードバランサ 1台
 レプリケーションサーバ 1台
 データベースクラスタ 2台

<リグレッションテスト結果表示>
============== dropping database "regression"         ==============
dropdb: database removal failed: ERROR:  database "regression" does not exist
============== creating database "regression"         ==============
CREATE DATABASE
============== dropping regression test user accounts ==============
============== installing PL/pgSQL                    ==============
============== running regression test queries        ==============
test boolean              ... ok
test char                 ... ok
test name                 ... ok
test varchar              ... ok
test text                 ... ok
test int2                 ... ok
test int4                 ... ok
test int8                 ... ok
test oid                  ... ok
test float4               ... ok
test float8               ... ok
test bit                  ...     ← ここで沈黙

<レプリケーションサーバ設定>
 <Cluster_Server_Info>
     <Host_Name>   oss241.osstc.jp  </Host_Name>
     <Port>                5432        </Port>
     <Recovery_Port>       7101        </Recovery_Port>
     <LifeCheck_Port>      7201        </LifeCheck_Port>
 </Cluster_Server_Info>
 <Cluster_Server_Info>
     <Host_Name>   oss242.osstc.jp  </Host_Name>
     <Port>                5432        </Port>
     <Recovery_Port>       7101        </Recovery_Port>
     <LifeCheck_Port>      7201        </LifeCheck_Port>
 </Cluster_Server_Info>
 <LoadBalance_Server_Info>
     <Host_Name>   oss239.osstc.jp  </Host_Name>
     <Recovery_Port>       6101        </Recovery_Port>
     <LifeCheck_Port>      6201        </LifeCheck_Port>
 </LoadBalance_Server_Info>
 <Status_Log_File>  /tmp/pgreplicate.sts  </Status_Log_File>
 <Error_Log_File>   /tmp/pgreplicate.log  </Error_Log_File>
 <Replication_Port>       8001            </Replication_Port>
 <Recovery_Port>          8101            </Recovery_Port>
 <LifeCheck_Port>         8201            </LifeCheck_Port>
 <RLOG_Port>              8301            </RLOG_Port>
 <Response_Mode>        normal            </Response_Mode>
 <Use_Replication_Log>      no            </Use_Replication_Log>
 <Reserved_Connections>      1            </Reserved_Connections>

<ロードバランサ設定>
 <Cluster_Server_Info>
     <Host_Name>   oss241.osstc.jp  </Host_Name>
     <Port>        5432                </Port>
     <Max_Connect> 32                  </Max_Connect>
 </Cluster_Server_Info>
 <Cluster_Server_Info>
     <Host_Name>   oss242.osstc.jp   </Host_Name>
     <Port>        5432                </Port>
     <Max_Connect> 32                  </Max_Connect>
 </Cluster_Server_Info>
 <Backend_Socket_Dir>    /tmp     </Backend_Socket_Dir> 
 <Receive_Port>          5432     </Receive_Port>
 <Recovery_Port>         6101     </Recovery_Port>
 <LifeCheck_Port>        6201     </LifeCheck_Port>
 <Max_Cluster_Num>        128     </Max_Cluster_Num>
 <Use_Connection_Pooling>  no     </Use_Connection_Pooling>

<クラスタサーバ設定>
 <Replicate_Server_Info>
         <Host_Name> oss240.osstc.jp </Host_Name>
         <Port> 8001 </Port>
         <Recovery_Port> 8101 </Recovery_Port>
         <LifeCheck_Port> 8201 </LifeCheck_Port>
 </Replicate_Server_Info>
 <Recovery_Port> 7101 </Recovery_Port>
 <LifeCheck_Port> 7201 </LifeCheck_Port>
 <Rsync_Path> /usr/bin/rsync </Rsync_Path>
 <Rsync_Option> ssh -1 </Rsync_Option>
 <When_Stand_Alone> read_only  </When_Stand_Alone>
 <Status_Log_File>  /tmp/cluster.sts </Status_Log_File>
 <Error_Log_File> /tmp/cluster.log  </Error_Log_File>

<レプリケーションサーバのログ>
     :
DEBUG:replicate_loop():replicate_loop selected
DEBUG:PGRreplicate_packet_send():cmdSts=Q
DEBUG:PGRreplicate_packet_send():cmdType=O
DEBUG:PGRreplicate_packet_send():rlog=0
DEBUG:PGRreplicate_packet_send():request_id=13
DEBUG:PGRreplicate_packet_send():replicate_id=0
DEBUG:PGRreplicate_packet_send():port=5432
DEBUG:PGRreplicate_packet_send():pid=1449
DEBUG:PGRreplicate_packet_send():from_host=oss241
DEBUG:PGRreplicate_packet_send():dbName=regression
DEBUG:PGRreplicate_packet_send():userName=postgres
DEBUG:PGRreplicate_packet_send():recieve sec=1118730481
DEBUG:PGRreplicate_packet_send():recieve usec=90962
DEBUG:PGRreplicate_packet_send():query_size=23
DEBUG:PGRreplicate_packet_send():query=DROP TABLE varbit_table
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():status of PGRreturn_result[0]
DEBUG:send_sync_data():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1118730481,90962,109,1) )
DEBUG:sem_unlock[1]
DEBUG:replicate_loop():replicate_loop selected
DEBUG:replicate_loop():replicate_loop selected
DEBUG:PGRreplicate_packet_send():cmdSts=Q
DEBUG:PGRreplicate_packet_send():cmdType=O
DEBUG:PGRreplicate_packet_send():rlog=0
DEBUG:PGRreplicate_packet_send():request_id=14
DEBUG:PGRreplicate_packet_send():replicate_id=0
DEBUG:PGRreplicate_packet_send():port=5432
DEBUG:PGRreplicate_packet_send():pid=1449
DEBUG:PGRreplicate_packet_send():from_host=oss241
DEBUG:PGRreplicate_packet_send():dbName=regression
DEBUG:PGRreplicate_packet_send():userName=postgres
DEBUG:PGRreplicate_packet_send():recieve sec=1118730481
DEBUG:PGRreplicate_packet_send():recieve usec=162603
DEBUG:PGRreplicate_packet_send():query_size=64
DEBUG:PGRreplicate_packet_send():query=CREATE TABLE varbit_table (a BIT VARYING(16), b BIT VARYING(16))
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():status of PGRreturn_result[0]
DEBUG:send_sync_data():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1118730481,162603,109,1) )
DEBUG:sem_unlock[1]
DEBUG:replicate_loop():replicate_loop selected
DEBUG:replicate_loop():replicate_loop selected
DEBUG:PGRreplicate_packet_send():cmdSts=Q
DEBUG:PGRreplicate_packet_send():cmdType=C
DEBUG:PGRreplicate_packet_send():rlog=0
DEBUG:PGRreplicate_packet_send():request_id=15
DEBUG:PGRreplicate_packet_send():replicate_id=0
DEBUG:PGRreplicate_packet_send():port=5432
DEBUG:PGRreplicate_packet_send():pid=1449
DEBUG:PGRreplicate_packet_send():from_host=oss241
DEBUG:PGRreplicate_packet_send():dbName=regression
DEBUG:PGRreplicate_packet_send():userName=postgres
DEBUG:PGRreplicate_packet_send():recieve sec=1118730481
DEBUG:PGRreplicate_packet_send():recieve usec=209692
DEBUG:PGRreplicate_packet_send():query_size=28
DEBUG:PGRreplicate_packet_send():query=COPY varbit_table FROM stdin
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1118730481,209692,110,1]
DEBUG:PGRreturn_result():status of PGRreturn_result[0]
DEBUG:send_sync_data():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1118730481,209692,110,1) )
DEBUG:sem_unlock[1]
DEBUG:replicate_loop():replicate_loop selected
DEBUG:PGRreplicate_packet_send():cmdSts=C
DEBUG:PGRreplicate_packet_send():cmdType=e
DEBUG:PGRreplicate_packet_send():rlog=0
DEBUG:PGRreplicate_packet_send():request_id=16
DEBUG:PGRreplicate_packet_send():replicate_id=0
DEBUG:PGRreplicate_packet_send():port=5432
DEBUG:PGRreplicate_packet_send():pid=1449
DEBUG:PGRreplicate_packet_send():from_host=oss241
DEBUG:PGRreplicate_packet_send():dbName=regression
DEBUG:PGRreplicate_packet_send():userName=postgres
DEBUG:PGRreplicate_packet_send():recieve sec=1118730481
DEBUG:PGRreplicate_packet_send():recieve usec=214539
DEBUG:PGRreplicate_packet_send():query_size=103
DEBUG:PGRreplicate_packet_send():query=X0F	X10
X1F	X11
X2F	X12
X3F	X13
X8F	X04
X000F	X0010
X0123	XFFFF
X2468	X2468
XFA50	X05AF
X1234	XFFF5
\.

DEBUG:sem_lock[1]
DEBUG:replicate_loop():replicate_loop selected
DEBUG:replicate_loop():replicate_loop selected
DEBUG:PGRreplicate_packet_send():cmdSts=C
DEBUG:PGRreplicate_packet_send():cmdType=e
DEBUG:PGRreplicate_packet_send():rlog=3
DEBUG:PGRreplicate_packet_send():request_id=16
DEBUG:PGRreplicate_packet_send():replicate_id=0
DEBUG:PGRreplicate_packet_send():port=5432
DEBUG:PGRreplicate_packet_send():pid=1449
DEBUG:PGRreplicate_packet_send():from_host=oss241
DEBUG:PGRreplicate_packet_send():dbName=regression
DEBUG:PGRreplicate_packet_send():userName=postgres
DEBUG:PGRreplicate_packet_send():recieve sec=1118730571
DEBUG:PGRreplicate_packet_send():recieve usec=213924
DEBUG:PGRreplicate_packet_send():query_size=103
DEBUG:PGRreplicate_packet_send():query=X0F	X10
X1F	X11
X2F	X12
X3F	X13
X8F	X04
X000F	X0010
X0123	XFFFF
X2468	X2468
XFA50	X05AF
X1234	XFFF5
\.

DEBUG:sem_lock[1]
DEBUG:replicate_loop():replicate_loop selected
DEBUG:replicate_loop():replicate_loop selected
DEBUG:PGRreplicate_packet_send():cmdSts=C
DEBUG:PGRreplicate_packet_send():cmdType=e
DEBUG:PGRreplicate_packet_send():rlog=3
DEBUG:PGRreplicate_packet_send():request_id=16
DEBUG:PGRreplicate_packet_send():replicate_id=0
DEBUG:PGRreplicate_packet_send():port=5432
DEBUG:PGRreplicate_packet_send():pid=1449
DEBUG:PGRreplicate_packet_send():from_host=oss241
DEBUG:PGRreplicate_packet_send():dbName=regression
DEBUG:PGRreplicate_packet_send():userName=postgres
DEBUG:PGRreplicate_packet_send():recieve sec=1118730661
DEBUG:PGRreplicate_packet_send():recieve usec=213337
DEBUG:PGRreplicate_packet_send():query_size=103
DEBUG:PGRreplicate_packet_send():query=X0F	X10
X1F	X11
X2F	X12
X3F	X13
X8F	X04
X000F	X0010
X0123	XFFFF
X2468	X2468
XFA50	X05AF
X1234	XFFF5
\.

DEBUG:sem_lock[1]

<ロードバランサのログ>
DEBUG:pool_process_query():read kind from backend T
DEBUG:pool_process_query():read kind from backend pending data D len: 147 po: 104
DEBUG:pool_process_query():read kind from backend pending data D len: 124 po: 127
DEBUG:pool_process_query():read kind from backend pending data D len: 100 po: 151
DEBUG:pool_process_query():read kind from backend pending data D len: 66 po: 185
DEBUG:pool_process_query():read kind from backend pending data C len: 17 po: 234
DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 246
DEBUG:ReadyForQuery(): message length: 5
DEBUG:ReadyForQuery(): transaction state: I
DEBUG:ProcessFrontendResponse():read kind from frontend Q(51)
DEBUG:Query(): DROP TABLE varbit_table;
DEBUG:pool_process_query():read kind from backend C
DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 16
DEBUG:ReadyForQuery(): message length: 5
DEBUG:ReadyForQuery(): transaction state: I
DEBUG:ProcessFrontendResponse():read kind from frontend Q(51)
DEBUG:Query(): CREATE TABLE varbit_table (a BIT VARYING(16), b BIT VARYING(16));
DEBUG:pool_process_query():read kind from backend C
DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 18
DEBUG:ReadyForQuery(): message length: 5
DEBUG:ReadyForQuery(): transaction state: I
DEBUG:ProcessFrontendResponse():read kind from frontend Q(51)
DEBUG:Query(): COPY varbit_table FROM stdin;
DEBUG:pool_process_query():read kind from backend G

<クラスタサーバ(マスタ)のログ>
      :
2005-06-13 23:27:31 LOG:  statement: DROP TABLE varbit_table;
2005-06-13 23:27:31 LOG:  statement: CREATE TABLE varbit_table (a BIT VARYING(16), b BIT VARYING(16));
2005-06-13 23:27:31 LOG:  statement: COPY varbit_table FROM stdin;

<クラスタサーバ(スレーブ)のログ>
      :
2005-06-14 15:27:51 LOG:  statement: DROP TABLE varbit_table
2005-06-14 15:27:51 LOG:  statement: SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1118730481,162603,109,1) 
2005-06-14 15:27:51 LOG:  statement: CREATE TABLE varbit_table (a BIT VARYING(16), b BIT VARYING(16))
2005-06-14 15:27:51 LOG:  statement: SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1118730481,209692,110,1) 
2005-06-14 15:27:51 LOG:  statement: COPY varbit_table FROM stdin

以上です。

−−−−−
近藤 洋一



pgcluster メーリングリストの案内