[pgcluster: 949] ロードバランサが固まります
shinozaki ＠ cobalt.co.jp
shinozaki ＠ cobalt.co.jp
2006年 12月 26日 (火) 14:42:12 JST
前回pgbenchでＤＢがロックする件でお世話になりました。
篠崎です。
今回は、また別の件でメールさせていただきます。
システムの安定度を確認するために、
PHPからselectとinsertをトランザクションを張らずに１回呼ぶプログラムを
外部から（http経由で）毎秒４０回程度回すベンチを流してみたのですが、
だいたい２０分から３０分程度でロードバランサが固まってしまいます。
ロードバランサをリスタートすると復活するのですが、
書き込みが間に合ってない感じでしょうか？
なにか対策等ありましたら、ご教授ください。
よろしくお願いいたします。
PGCluster-1.5.0rc10
pglb.conf
<Cluster_Server_Info>
<Host_Name> db01 </Host_Name>
<Port> 5432 </Port>
<Max_Connect> 128 </Max_Connect>
</Cluster_Server_Info>
<Cluster_Server_Info>
<Host_Name> db02 </Host_Name>
<Port> 5432 </Port>
<Max_Connect> 128 </Max_Connect>
</Cluster_Server_Info>
<Cluster_Server_Info>
<Host_Name> db03 </Host_Name>
<Port> 5432 </Port>
<Max_Connect> 128 </Max_Connect>
</Cluster_Server_Info>
<Backend_Socket_Dir> /tmp </Backend_Socket_Dir>
<Receive_Port> 5432 </Receive_Port>
<Recovery_Port> 6001 </Recovery_Port>
<Max_Cluster_Num> 4 </Max_Cluster_Num>
<Use_Connection_Pooling> yes </Use_Connection_Pooling>
pgreplicate.conf
<Cluster_Server_Info>
<Host_Name> db01 </Host_Name>
<Port> 5432 </Port>
<Recovery_Port> 7001 </Recovery_Port>
</Cluster_Server_Info>
<Cluster_Server_Info>
<Host_Name> db02 </Host_Name>
<Port> 5432 </Port>
<Recovery_Port> 7001 </Recovery_Port>
</Cluster_Server_Info>
<Cluster_Server_Info>
<Host_Name> db03 </Host_Name>
<Port> 5432 </Port>
<Recovery_Port> 7001 </Recovery_Port>
</Cluster_Server_Info>
<LoadBalance_Server_Info>
<Host_Name> localhost </Host_Name>
<Recovery_Port> 6001 </Recovery_Port>
</LoadBalance_Server_Info>
<LoadBalance_Server_Info>
<Host_Name> lb02 </Host_Name>
<Recovery_Port> 6001 </Recovery_Port>
</LoadBalance_Server_Info>
<Replication_Port> 8001 </Replication_Port>
<Recovery_Port> 8101 </Recovery_Port>
<Response_Mode> normal </Response_Mode>
<Status_Log_File> /dbdata/pgreplicate.sts </Status_Log_File>
<Error_Log_File> /dbdata/pgreplicate.log </Error_Log_File>
<Use_Replication_Log> yes </Use_Replication_Log>
<RLOG_Port> 8301 </RLOG_Port>
止まった時あたりの
ロードバランサログ以下のログが繰り返されます。
2006-12-26 11:52:51 [29260] DEBUG:pool_process_query():read kind from backend C
2006-12-26 11:52:51 [29260] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 11
2006-12-26 11:52:51 [29260] DEBUG:ReadyForQuery(): message length: 5
2006-12-26 11:52:51 [29260] DEBUG:ReadyForQuery(): transaction state: I
2006-12-26 11:52:51 [29260] DEBUG:pool_connection_pool_timer():pool_connection_pool_timer: called
2006-12-26 11:52:51 [29222] DEBUG:pool_process_query():read kind from backend C
2006-12-26 11:52:51 [29222] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 11
2006-12-26 11:52:51 [29222] DEBUG:ReadyForQuery(): message length: 5
2006-12-26 11:52:51 [29222] DEBUG:ReadyForQuery(): transaction state: I
2006-12-26 11:52:51 [29222] DEBUG:pool_connection_pool_timer():pool_connection_pool_timer: called
2006-12-26 11:52:51 [29343] DEBUG:pool_process_query():read kind from backend C
2006-12-26 11:52:51 [29343] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 11
2006-12-26 11:52:51 [29343] DEBUG:ReadyForQuery(): message length: 5
2006-12-26 11:52:51 [29343] DEBUG:ReadyForQuery(): transaction state: I
2006-12-26 11:52:51 [29343] DEBUG:pool_connection_pool_timer():pool_connection_pool_timer: called
2006-12-26 11:52:51 [29391] DEBUG:pool_process_query():read kind from backend C
2006-12-26 11:52:51 [29391] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 11
2006-12-26 11:52:51 [29391] DEBUG:ReadyForQuery(): message length: 5
2006-12-26 11:52:51 [29391] DEBUG:ReadyForQuery(): transaction state: I
2006-12-26 11:52:51 [29391] DEBUG:pool_connection_pool_timer():pool_connection_pool_timer: called
2006-12-26 11:52:51 [29470] DEBUG:pool_process_query():read kind from backend C
2006-12-26 11:52:51 [29470] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 11
2006-12-26 11:52:51 [29470] DEBUG:ReadyForQuery(): message length: 5
2006-12-26 11:52:51 [29470] DEBUG:ReadyForQuery(): transaction state: I
2006-12-26 11:52:51 [29470] DEBUG:pool_connection_pool_timer():pool_connection_pool_timer: called
2006-12-26 11:52:51 [29471] DEBUG:pool_process_query():read kind from backend C
2006-12-26 11:52:51 [29471] DEBUG:pool_process_query():read kind from backend pending data Z len: 5 po: 11
2006-12-26 11:52:51 [29471] DEBUG:ReadyForQuery(): message length: 5
2006-12-26 11:52:51 [29471] DEBUG:ReadyForQuery(): transaction state: I
2006-12-26 11:52:51 [29471] DEBUG:pool_connection_pool_timer():pool_connection_pool_timer: called
レプリログ以下のログ５１分台が止まった時、ロードバランサを停止した時に５３分のログが一気に出力されました。
2006-12-26 11:52:51 [29746] DEBUG:same host
2006-12-26 11:52:51 [30169] DEBUG:PGRread_packet():PG_read_query returns PGR_QUERY_DONE_NOTICE_CMD.
2006-12-26 11:52:51 [29184] DEBUG:start thread_send_cluster()
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(8,9574,0,1) )
2006-12-26 11:52:51 [29184] DEBUG:start thread_send_cluster()
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(8,9574,0,1) )
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec send :RESET ALL
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec returns :RESET
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():return value from send_replicate_packet_to_server() is 0
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():pthread_exit[0]
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec send :RESET ALL
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec returns :RESET
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():return value from send_replicate_packet_to_server() is 0
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():pthread_exit[1]
2006-12-26 11:52:51 [29746] DEBUG:PGRreturn_result():PGRreturn_result[8,9574,0,1]
2006-12-26 11:52:51 [29746] DEBUG:PGRreturn_result():128 send
2006-12-26 11:52:51 [29746] DEBUG:end thread_send_source()
2006-12-26 11:52:51 [29746] DEBUG:sem_unlock[1]
2006-12-26 11:52:51 [29738] DEBUG:sem_lock [1] got it
2006-12-26 11:52:51 [29738] DEBUG:same host
2006-12-26 11:52:51 [29184] DEBUG:start thread_send_cluster()
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(8,9575,0,1) )
2006-12-26 11:52:51 [29184] DEBUG:start thread_send_cluster()
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(8,9575,0,1) )
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():sync_command returns SYSTEM_COMMAND
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec send :RESET ALL
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec returns :RESET
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():return value from send_replicate_packet_to_server() is 0
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():pthread_exit[0]
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec send :RESET ALL
2006-12-26 11:52:51 [29184] DEBUG:send_replicate_packet_to_server():PQexec returns :RESET
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():return value from send_replicate_packet_to_server() is 0
2006-12-26 11:52:51 [29184] DEBUG:thread_send_cluster():pthread_exit[1]
2006-12-26 11:52:51 [29738] DEBUG:PGRreturn_result():PGRreturn_result[8,9575,0,1]
2006-12-26 11:52:51 [29738] DEBUG:PGRreturn_result():128 send
2006-12-26 11:52:51 [29738] DEBUG:end thread_send_source()
2006-12-26 11:52:51 [29738] DEBUG:sem_unlock[1]
2006-12-26 11:52:51 [29738] DEBUG:PGRread_packet():PG_read_query returns PGR_QUERY_DONE_NOTICE_CMD.
2006-12-26 11:52:51 [29746] DEBUG:PGRread_packet():PG_read_query returns PGR_QUERY_DONE_NOTICE_CMD.
2006-12-26 11:58:53 [29673] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29717] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [30007] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29697] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [30010] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29704] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [30021] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29720] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [30032] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:PGRread_packet():PG_read_query returns .
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():got result:cmdSys='S'
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): CMD_STS_TRANSACTION_ABORT
2006-12-26 11:58:53 [29185] DEBUG:reconfirm_commit():PGR_NOT_YET_COMMIT
2006-12-26 11:58:53 [29185] DEBUG:do_rlog(): SYS_CALL process done
2006-12-26 11:58:53 [29185] DEBUG:do_rlog():process result done:cmdSys='S'
2006-12-26 11:58:53 [29673] DEBUG:PGRreturn_result():PGRreturn_result[5,0]
2006-12-26 11:58:53 [29717] DEBUG:PGRreturn_result():PGRreturn_result[5,0]
2006-12-26 11:58:53 [29717] DEBUG:PGRreturn_result():128 send
2006-12-26 11:58:53 [29717] DEBUG:replicate_loop():session closed
2006-12-26 11:58:53 [29717] DEBUG:PGRdo_replicate():query :: PGR_CLOSE_CONNECTION
pgcluster メーリングリストの案内