[pgcluster: 1017] Re: 更新でレプリケーションサーバが固まってしまいます。
At.Mitani
mitani ＠ sraw.co.jp
2008年 1月 22日 (火) 12:00:04 JST
はじめまして。
ログを見たところ、Preparedのクエリーが呼ばれているようですね。
単純にUPDATE文を呼んだだけ、とのことですので、
恐らくJDBC経由でアクセスしておられるのではないかと思うのですが、
どうでしょうか。
JDBCに投げられたクエリーは内部で複数のクエリーを生成しますが、
この場合
Second First
---------------------------
PARSE PARSE
BIND
DESCRIBE BIND
ECEXUTE DESCRIBE
SYNC EXECUTE
(ここでロック発生）
となっているようです。
PreparedクエリーはEXECUTE命令が送られて来るまで実行されませんので、ロック競合を発生させるクエリーの場合、面倒なことになります。
クエリーの投げ方によってはデッドロックを引き起こすことも考えられます。
よければ、テストされた環境も教えてください。
三谷
On Fri, 18 Jan 2008 20:25:45 +0900
Shiroyuki Inooka <inooka ＠ cyphertec.co.jp> wrote:
>
> 初めまして。イノオカと申します。
>
> 以下の3台構成で、クラスタサーバ1,2上には
> 同じWebアプリケーションを起動させているのですが、
> WebアプリケーションからそれぞれのDBへ、
> 同時に同じレコードに対しアップデートを行うと、
> レプリケーションサーバが固まってしまいます。
>
> PgClusterバージョン：pgcl.1.5.0rc14
>
> ・クラスタサーバ1
> OS：CentOS4.4
> ホスト名：first
> IP：192.168.1.53
>
> ・クラスタサーバ2
> OS：CentOS4.4
> ホスト名：second
> IP：192.168.1.52
>
> ・レプリケーションサーバ
> OS：CentOS4.4
> ホスト名：replica
> IP：192.168.1.51
>
> アップデートは以下のごく単純なSQL文で
> クラスタ1,2両方からそれぞれ一回、同時に投入しています。
> 「UPDATE test set name = 'ddd' where id = 1」
>
> 以下が設定ファイルとログになりますが、
> 何か分かることがありましたらご教授下さい。
>
> 〜設定ファイル〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜
> ■クラスタサーバ1
> ・cluster.conf
> <Replicate_Server_Info>
> <Host_Name> replica </Host_Name>
> <Port> 8001 </Port>
> <Recovery_Port> 8101 </Recovery_Port>
> </Replicate_Server_Info>
> <Host_Name> first </Host_Name>
> <Recovery_Port> 7001 </Recovery_Port>
> <Rsync_Path> /usr/bin/rsync </Rsync_Path>
> <Rsync_Option> ssh -1 </Rsync_Option>
> <Rsync_Compress> yes </Rsync_Compress>
> <Pg_Dump_Path> /usr/local/pgsql/bin/pg_dump </Pg_Dump_Path>
> <When_Stand_Alone> read_write </When_Stand_Alone>
> <Replication_Timeout> 10s </Replication_Timeout>
> ・pg_hba.conf
> host all all 192.168.1.53 255.255.255.255 trust
> host all all 192.168.1.52 255.255.255.255 trust
> host all all 192.168.1.51 255.255.255.255 trust
>
> ■クラスタサーバ2
> ・cluster.conf
> <Replicate_Server_Info>
> <Host_Name> replica </Host_Name>
> <Port> 8001 </Port>
> <Recovery_Port> 8101 </Recovery_Port>
> <LifeCheck_Port> 8201 </LifeCheck_Port>
> </Replicate_Server_Info>
> <Host_Name> second </Host_Name>
> <Recovery_Port> 7001 </Recovery_Port>
> <LifeCheck_Port> 7201 </LifeCheck_Port>
> <Rsync_Path> /usr/bin/rsync </Rsync_Path>
> <Rsync_Option> ssh -1 </Rsync_Option>
> <Rsync_Compress> yes </Rsync_Compress>
> <Pg_Dump_Path> /usr/local/pgsql/bin/pg_dump </Pg_Dump_Path>
> <When_Stand_Alone> read_write </When_Stand_Alone>
> <Replication_Timeout> 10s </Replication_Timeout>
> ・pg_hba.conf
> host all all 192.168.1.53 255.255.255.255 trust
> host all all 192.168.1.52 255.255.255.255 trust
> host all all 192.168.1.51 255.255.255.255 trust
>
> ■レプリケーションサーバ
> ・pgreplicate.conf
> <Cluster_Server_Info>
> <Host_Name> first </Host_Name>
> <Port> 5432 </Port>
> <Recovery_Port> 7001 </Recovery_Port>
> </Cluster_Server_Info>
> <Cluster_Server_Info>
> <Host_Name> second </Host_Name>
> <Port> 5432 </Port>
> <Recovery_Port> 7001 </Recovery_Port>
> </Cluster_Server_Info>
> <Host_Name> replica </Host_Name>
> <Replication_Port> 8001 </Replication_Port>
> <Recovery_Port> 8101 </Recovery_Port>
> <RLOG_Port> 8301 </RLOG_Port>
> <Response_Mode> normal </Response_Mode>
> <Use_Replication_Log> no </Use_Replication_Log>
> <Replication_Timeout> 10s </Replication_Timeout>
> <Log_File_Info>
> <File_Name> /tmp/pgreplicate.log </File_Name>
> <File_Size> 1M </File_Size>
> <Rotate> 3 </Rotate>
> </Log_File_Info>
> ・pg_hba.conf
> host all all 192.168.1.53 255.255.255.255 trust
> host all all 192.168.1.52 255.255.255.255 trust
> host all all 192.168.1.51 255.255.255.255 trust
> 〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜
>
> 〜ログ〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜
> [立ち上げ時]
> 2008-01-18 19:11:56 [9067] DEBUG:PGR_Get_Conf_Data ok
> 2008-01-18 19:11:56 [9067] DEBUG:LoadBalanceTbl allocate ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():CascadeTbl shmget ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():CascadeTbl shmat ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():CascadeInf shmget ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():CascadeInf shmat ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():CommitLog shmget ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():Commit_Log_Tbl shmat ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():RLog Memory
> Allocation ok
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(Host_Name,first)
> 2008-01-18 19:11:56 [9067] DEBUG:registering hostname first
> 2008-01-18 19:11:56 [9067] DEBUG:resolved name is 192.168.1.53
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(Port,5432)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Recovery_Port,7001)
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(Host_Name,second)
> 2008-01-18 19:11:56 [9067] DEBUG:registering hostname second
> 2008-01-18 19:11:56 [9067] DEBUG:resolved name is 192.168.1.52
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(Port,5432)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Recovery_Port,7001)
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(Host_Name,replica)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Replication_Port,8001)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Recovery_Port,8101)
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(RLOG_Port,8301)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Response_Mode,normal)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Use_Replication_Log,no)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(Replication_Timeout,10s)
> 2008-01-18 19:11:56 [9067] DEBUG:registering
> (key,value)=(File_Name,/tmp/pgreplicate.log)
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(File_Size,1M)
> 2008-01-18 19:11:56 [9067] DEBUG:registering (key,value)=(Rotate,3)
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():HostTbl shmget ok
> 2008-01-18 19:11:56 [9067] DEBUG:PGRget_Conf_Data():HostTbl shmat ok
> 2008-01-18 19:11:56 [9068] DEBUG:PGRrecovery_main():PGRrecovery_main
> bind port 8101
> 2008-01-18 19:11:56 [9067] DEBUG:replicate_main():entering replicate_main
> 2008-01-18 19:11:56 [9067] DEBUG:replicate_main() 8001 port bind OK
> 2008-01-18 19:11:56 [9067] DEBUG:cmdSts=N
> 2008-01-18 19:11:56 [9067] DEBUG:rlog=0
> 2008-01-18 19:11:56 [9067] DEBUG:port=0
> 2008-01-18 19:11:56 [9067] DEBUG:pid=0
> 2008-01-18 19:11:56 [9067] DEBUG:from_host=192.168.1.51
> 2008-01-18 19:11:56 [9067] DEBUG:dbName=template1
> 2008-01-18 19:11:56 [9067] DEBUG:userName=postgres
> 2008-01-18 19:11:56 [9067] DEBUG:recieve sec=0
> 2008-01-18 19:11:56 [9067] DEBUG:recieve usec=0
> 2008-01-18 19:11:56 [9067] DEBUG:query_size=64
> 2008-01-18 19:11:56 [9067] DEBUG:request_id=0
> 2008-01-18 19:11:56 [9067] DEBUG:replicate_id=0
> 2008-01-18 19:11:56 [9067] DEBUG:recovery_status=0
> 2008-01-18 19:11:56 [9067] DEBUG:query=SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(1,'192.168.1.51',8001,8101)
> 2008-01-18 19:11:56 [9067] DEBUG:PGRis_same_host():target host
> 2008-01-18 19:11:56 [9067] DEBUG:pgr_createConn():PQsetdbLogin
> host[192.168.1.53] port[5432] db[template1] user[postgres]
> 2008-01-18 19:11:56 [9067] DEBUG:pgr_createConn():PQsetdbLogin ok!!
> 2008-01-18 19:11:56 [9067] DEBUG:PGRis_same_host():target host
> 2008-01-18 19:11:56 [9067] DEBUG:pgr_createConn():PQsetdbLogin
> host[192.168.1.52] port[5432] db[template1] user[postgres]
> 2008-01-18 19:11:56 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command(SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(8,1,0,1) )
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():PQexec send :SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(1,'192.168.1.51',8001,8101)
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():PQexec returns :SYSTEM_COMMAND
> 2008-01-18 19:11:56 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:11:56 [9067] DEBUG:thread_send_cluster():pthread_exit[0]
> 2008-01-18 19:11:56 [9067] DEBUG:pgr_createConn():PQsetdbLogin ok!!
> 2008-01-18 19:11:56 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command(SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(8,1,0,1) )
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():PQexec send :SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(1,'192.168.1.51',8001,8101)
> 2008-01-18 19:11:56 [9067]
> DEBUG:send_replicate_packet_to_server():PQexec returns :SYSTEM_COMMAND
> 2008-01-18 19:11:56 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:11:56 [9067] DEBUG:thread_send_cluster():pthread_exit[1]
>
> [SQL発行時]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9071] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9071] DEBUG:cmdType=P
> 2008-01-18 19:12:09 [9071] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9071] DEBUG:port=5432
> 2008-01-18 19:12:09 [9071] DEBUG:pid=13344
> 2008-01-18 19:12:09 [9071] DEBUG:from_host=192.168.1.52
> 2008-01-18 19:12:09 [9071] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9071] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9071] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9071] DEBUG:recieve usec=646207
> 2008-01-18 19:12:09 [9071] DEBUG:query_size=46
> 2008-01-18 19:12:09 [9071] DEBUG:request_id=1
> 2008-01-18 19:12:09 [9071] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9071] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9071] DEBUG:pgr_createConn():PQsetdbLogin
> host[192.168.1.53] port[5432] db[test_replica] user[postgres]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9072] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9072] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9072] DEBUG:cmdType=P
> 2008-01-18 19:12:09 [9072] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9072] DEBUG:port=5432
> 2008-01-18 19:12:09 [9072] DEBUG:pid=9636
> 2008-01-18 19:12:09 [9072] DEBUG:from_host=192.168.1.53
> 2008-01-18 19:12:09 [9072] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9072] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9072] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9072] DEBUG:recieve usec=684129
> 2008-01-18 19:12:09 [9072] DEBUG:query_size=46
> 2008-01-18 19:12:09 [9072] DEBUG:request_id=1
> 2008-01-18 19:12:09 [9072] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9072] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9071] DEBUG:pgr_createConn():PQsetdbLogin ok!!
> 2008-01-18 19:12:09 [9071] DEBUG:source host
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command [SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(3,1200651129,646207,0,1,2) ]
> 2008-01-18 19:12:09 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[0]
> 2008-01-18 19:12:09 [9071]
> DEBUG:PGRreturn_result():PGRreturn_result[8,2,0,1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9071] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9072] DEBUG:source host
> 2008-01-18 19:12:09 [9072] DEBUG:pgr_createConn():PQsetdbLogin
> host[192.168.1.52] port[5432] db[test_replica] user[postgres]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9071] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9071] DEBUG:cmdType=B
> 2008-01-18 19:12:09 [9071] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9071] DEBUG:port=5432
> 2008-01-18 19:12:09 [9071] DEBUG:pid=13344
> 2008-01-18 19:12:09 [9071] DEBUG:from_host=192.168.1.52
> 2008-01-18 19:12:09 [9071] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9071] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9071] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9071] DEBUG:recieve usec=760237
> 2008-01-18 19:12:09 [9071] DEBUG:query_size=9
> 2008-01-18 19:12:09 [9071] DEBUG:request_id=2
> 2008-01-18 19:12:09 [9071] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9071] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9072] DEBUG:pgr_createConn():PQsetdbLogin ok!!
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command [SELECT
> PGR_SYSTEM_COMMAND_FUNCTION(3,1200651129,684129,0,1,3) ]
> 2008-01-18 19:12:09 [9067]
> DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[1]
> 2008-01-18 19:12:09 [9072]
> DEBUG:PGRreturn_result():PGRreturn_result[8,3,0,1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9072] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9072] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9071] DEBUG:source host
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[0]
> 2008-01-18 19:12:09 [9071]
> DEBUG:PGRreturn_result():PGRreturn_result[3,1200651129,760237,52708,1,4]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9071] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns P.
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns P.
> 2008-01-18 19:12:09 [9071] DEBUG:PGRdo_replicate():query :: P
> 2008-01-18 19:12:09 [9071] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9071] DEBUG:cmdType=D
> 2008-01-18 19:12:09 [9071] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9071] DEBUG:port=5432
> 2008-01-18 19:12:09 [9071] DEBUG:pid=13344
> 2008-01-18 19:12:09 [9071] DEBUG:from_host=192.168.1.52
> 2008-01-18 19:12:09 [9071] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9071] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9071] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9071] DEBUG:recieve usec=804292
> 2008-01-18 19:12:09 [9071] DEBUG:query_size=3
> 2008-01-18 19:12:09 [9071] DEBUG:request_id=3
> 2008-01-18 19:12:09 [9071] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9071] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9071] DEBUG:source host
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9072] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9072] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9072] DEBUG:cmdType=B
> 2008-01-18 19:12:09 [9072] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9072] DEBUG:port=5432
> 2008-01-18 19:12:09 [9072] DEBUG:pid=9636
> 2008-01-18 19:12:09 [9072] DEBUG:from_host=192.168.1.53
> 2008-01-18 19:12:09 [9072] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9072] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9072] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9072] DEBUG:recieve usec=822115
> 2008-01-18 19:12:09 [9072] DEBUG:query_size=9
> 2008-01-18 19:12:09 [9072] DEBUG:request_id=2
> 2008-01-18 19:12:09 [9072] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9072] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[0]
> 2008-01-18 19:12:09 [9071]
> DEBUG:PGRreturn_result():PGRreturn_result[8,5,0,1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9071] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9072] DEBUG:source host
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[1]
> 2008-01-18 19:12:09 [9072]
> DEBUG:PGRreturn_result():PGRreturn_result[3,1200651129,822115,52709,1,6]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9072] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9072] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9071] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9071] DEBUG:cmdType=E
> 2008-01-18 19:12:09 [9071] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9071] DEBUG:port=5432
> 2008-01-18 19:12:09 [9071] DEBUG:pid=13344
> 2008-01-18 19:12:09 [9071] DEBUG:from_host=192.168.1.52
> 2008-01-18 19:12:09 [9071] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9071] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9071] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9071] DEBUG:recieve usec=844383
> 2008-01-18 19:12:09 [9071] DEBUG:query_size=6
> 2008-01-18 19:12:09 [9071] DEBUG:request_id=4
> 2008-01-18 19:12:09 [9071] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9071] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns P.
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9071] DEBUG:source host
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[0]
> 2008-01-18 19:12:09 [9071]
> DEBUG:PGRreturn_result():PGRreturn_result[8,7,0,1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9071] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns P.
> 2008-01-18 19:12:09 [9072] DEBUG:PGRdo_replicate():query :: P
> 2008-01-18 19:12:09 [9072] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9072] DEBUG:cmdType=D
> 2008-01-18 19:12:09 [9072] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9072] DEBUG:port=5432
> 2008-01-18 19:12:09 [9072] DEBUG:pid=9636
> 2008-01-18 19:12:09 [9072] DEBUG:from_host=192.168.1.53
> 2008-01-18 19:12:09 [9072] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9072] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9072] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9072] DEBUG:recieve usec=861199
> 2008-01-18 19:12:09 [9072] DEBUG:query_size=3
> 2008-01-18 19:12:09 [9072] DEBUG:request_id=3
> 2008-01-18 19:12:09 [9072] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9072] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9072] DEBUG:source host
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9071] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
> 2008-01-18 19:12:09 [9071] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9071] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9071] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9071] DEBUG:cmdType=S
> 2008-01-18 19:12:09 [9071] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9071] DEBUG:port=5432
> 2008-01-18 19:12:09 [9071] DEBUG:pid=13344
> 2008-01-18 19:12:09 [9071] DEBUG:from_host=192.168.1.52
> 2008-01-18 19:12:09 [9071] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9071] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9071] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9071] DEBUG:recieve usec=880275
> 2008-01-18 19:12:09 [9071] DEBUG:query_size=1
> 2008-01-18 19:12:09 [9071] DEBUG:request_id=5
> 2008-01-18 19:12:09 [9071] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9071] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():return value from
> send_replicate_packet_to_server() is 0
> 2008-01-18 19:12:09 [9067] DEBUG:thread_send_cluster():pthread_exit[1]
> 2008-01-18 19:12:09 [9072]
> DEBUG:PGRreturn_result():PGRreturn_result[8,8,0,1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9072] DEBUG:end thread_send_source()
> 2008-01-18 19:12:09 [9072] DEBUG:sem_unlock[1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():PGRreturn_result[1]
> 2008-01-18 19:12:09 [9072] DEBUG:PGRreturn_result():128 send
> 2008-01-18 19:12:09 [9071] DEBUG:sem_lock [1] got it
> 2008-01-18 19:12:09 [9071] DEBUG:source host
> 2008-01-18 19:12:09 [9072] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:09 [9072] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:09 [9072] DEBUG:cmdSts=P
> 2008-01-18 19:12:09 [9072] DEBUG:cmdType=E
> 2008-01-18 19:12:09 [9072] DEBUG:rlog=0
> 2008-01-18 19:12:09 [9072] DEBUG:port=5432
> 2008-01-18 19:12:09 [9072] DEBUG:pid=9636
> 2008-01-18 19:12:09 [9072] DEBUG:from_host=192.168.1.53
> 2008-01-18 19:12:09 [9072] DEBUG:dbName=test_replica
> 2008-01-18 19:12:09 [9072] DEBUG:userName=postgres
> 2008-01-18 19:12:09 [9072] DEBUG:recieve sec=1200651129
> 2008-01-18 19:12:09 [9072] DEBUG:recieve usec=899380
> 2008-01-18 19:12:09 [9072] DEBUG:query_size=6
> 2008-01-18 19:12:09 [9072] DEBUG:request_id=4
> 2008-01-18 19:12:09 [9072] DEBUG:replicate_id=0
> 2008-01-18 19:12:09 [9072] DEBUG:recovery_status=0
> 2008-01-18 19:12:09 [9072] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:09 [9067] DEBUG:start thread_send_cluster()
>
> ・・・ここで固まります。
>
>
> この後10秒おきに以下の繰り返しとなります。
>
> 2008-01-18 19:12:18 [9081] DEBUG:PGRread_packet():PG_read_query returns
> SELECT PGR_SYSTEM_COMMAND_FUNCTION(2,replica,8001,8101).
> 2008-01-18 19:12:18 [9081] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:18 [9081] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:18 [9081] DEBUG:cmdSts=P
> 2008-01-18 19:12:18 [9081] DEBUG:cmdType=E
> 2008-01-18 19:12:18 [9081] DEBUG:rlog=3
> 2008-01-18 19:12:18 [9081] DEBUG:port=5432
> 2008-01-18 19:12:18 [9081] DEBUG:pid=9636
> 2008-01-18 19:12:18 [9081] DEBUG:from_host=192.168.1.53
> 2008-01-18 19:12:18 [9081] DEBUG:dbName=test_replica
> 2008-01-18 19:12:18 [9081] DEBUG:userName=postgres
> 2008-01-18 19:12:18 [9081] DEBUG:recieve sec=1200651138
> 2008-01-18 19:12:18 [9081] DEBUG:recieve usec=937903
> 2008-01-18 19:12:18 [9081] DEBUG:query_size=6
> 2008-01-18 19:12:18 [9081] DEBUG:request_id=4
> 2008-01-18 19:12:18 [9081] DEBUG:replicate_id=0
> 2008-01-18 19:12:18 [9081] DEBUG:recovery_status=0
> 2008-01-18 19:12:18 [9081] DEBUG:sem_lock [1] req
> 2008-01-18 19:12:19 [9082] DEBUG:PGRread_packet():PG_read_query returns
> SELECT PGR_SYSTEM_COMMAND_FUNCTION(2,replica,8001,8101).
> 2008-01-18 19:12:19 [9082] DEBUG:PGRread_packet():PG_read_query returns .
> 2008-01-18 19:12:19 [9082] DEBUG:PGRdo_replicate():query ::
> 2008-01-18 19:12:19 [9082] DEBUG:cmdSts=P
> 2008-01-18 19:12:19 [9082] DEBUG:cmdType=S
> 2008-01-18 19:12:19 [9082] DEBUG:rlog=3
> 2008-01-18 19:12:19 [9082] DEBUG:port=5432
> 2008-01-18 19:12:19 [9082] DEBUG:pid=13344
> 2008-01-18 19:12:19 [9082] DEBUG:from_host=192.168.1.52
> 2008-01-18 19:12:19 [9082] DEBUG:dbName=test_replica
> 2008-01-18 19:12:19 [9082] DEBUG:userName=postgres
> 2008-01-18 19:12:19 [9082] DEBUG:recieve sec=1200651139
> 2008-01-18 19:12:19 [9082] DEBUG:recieve usec=146098
> 2008-01-18 19:12:19 [9082] DEBUG:query_size=1
> 2008-01-18 19:12:19 [9082] DEBUG:request_id=5
> 2008-01-18 19:12:19 [9082] DEBUG:replicate_id=0
> 2008-01-18 19:12:19 [9082] DEBUG:recovery_status=0
> 2008-01-18 19:12:19 [9082] DEBUG:sem_lock [1] req
> 〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜〜
--
At.Mitani <mitani ＠ sraw.co.jp>
pgcluster メーリングリストの案内