[pgcluster: 415] Re: トランザクション実行速度低下について

[Wataru Oguro]

oguroです。

主要な部分のデバッグログをお送りいたします。

>　２．トランザクション開始
>　　#begin;
>  
>
DEBUG(PGRread_packet): query size=5
DEBUG(PGRread_packet): read[5] query[begin]
DEBUG(PGRread_packet): query :: begin
DEBUG(PGRreplicate_packet_send): cmdSts=T
DEBUG(PGRreplicate_packet_send): cmdType=B
DEBUG(PGRreplicate_packet_send): port=5432
DEBUG(PGRreplicate_packet_send): pid=22656
DEBUG(PGRreplicate_packet_send): except_host=db01
DEBUG(PGRreplicate_packet_send): from_host=db01
DEBUG(PGRreplicate_packet_send): dbName=test
DEBUG(PGRreplicate_packet_send): userName=postgres
DEBUG(PGRreplicate_packet_send): recieve sec=1089858394
DEBUG(PGRreplicate_packet_send): recieve usec=614943
DEBUG(PGRreplicate_packet_send): query_size=5
DEBUG(PGRreplicate_packet_send): query=begin
DEBUG(PGRreplicate_packet_send): useFlag[2]
DEBUG(is_need_response): sem_lock[1]
DEBUG(PGRreplicate_packet_send_each_server): except:5432 ＠ db01 host:5432 ＠ db02
DEBUG(PGRreplicate_packet_send_each_server): send replicate to:db02
DEBUG(PGRsend_replicate_packet_to_server): host(db02) : port(5432)
DEBUG(getTransactionTbl): not found in getTransactionTbl
DEBUG(pgr_createConn): PQsetdbLogin host[db02] port[5432] db[test]
user[postgres]
DEBUG(pgr_createConn): PQsetdbLogin ok!!
DEBUG(insertTransactionTbl): db:test port:5432 user:postgres host:db02
query:begin
DEBUG(insertTransactionTbl): sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1089858394,614943) )
DEBUG(insertTransactionTbl): PQexec send :begin
DEBUG(insertTransactionTbl): PQexec end
DEBUG(insertTransactionTbl): sem_lock[2]
DEBUG(PGRsem_lock): sem_unlock[1]
DEBUG(PGRis_same_host): 5432 @ db01 return trigger
DEBUG(PGRreturn_result): PGRreturn_result[3,1089858394,614943]
DEBUG(PGRreturn_result): 128 send
DEBUG(PGRreturn_result): wait for answer
DEBUG(PGRread_packet): query size=25
DEBUG(PGRread_packet): read[25] query[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG(PGRread_packet): answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG(PGRread_packet): QUERY DONE
DEBUG(PGRread_packet): status of PGRreturn_result[0]
DEBUG(PGRread_packet): sem_lock[3]
DEBUG(PGRsem_lock): sem_unlock[2]
DEBUG(delete_template): sem_unlock[3]
DEBUG(PGRsem_unlock): PGRreplicate_packet_send end

>　４．パーサエラーを発生させる
>　　#ooo;
>　　ERROR: parser: parse error at or near "ooo" at character 1
>  
>
DEBUG(PGRsem_unlock): replicate_loop selected
DEBUG(PGRread_packet): query size=25
DEBUG(PGRread_packet): read[25] query[PGR_QUERY_DONE_NOTICE_CMD]


>　５．再びクエリーを発行
>　　#insert into test values('112');
>　　ERROR: current transaction is aborted, queries ignored until end of
>transaction block
>  
>
DEBUG(PGRread_packet): replicate_loop selected
DEBUG(PGRread_packet): query size=30
DEBUG(PGRread_packet): read[30] query[insert into test values('111')]
DEBUG(PGRread_packet): query :: insert into test values('111')
DEBUG(PGRreplicate_packet_send): cmdSts=T
DEBUG(PGRreplicate_packet_send): cmdType=I
DEBUG(PGRreplicate_packet_send): port=5432
DEBUG(PGRreplicate_packet_send): pid=22656
DEBUG(PGRreplicate_packet_send): except_host=db01
DEBUG(PGRreplicate_packet_send): from_host=db01
DEBUG(PGRreplicate_packet_send): dbName=test
DEBUG(PGRreplicate_packet_send): userName=postgres
DEBUG(PGRreplicate_packet_send): recieve sec=1089858449
DEBUG(PGRreplicate_packet_send): recieve usec=580743
DEBUG(PGRreplicate_packet_send): query_size=30
DEBUG(PGRreplicate_packet_send): query=insert into test values('111')
DEBUG(PGRreplicate_packet_send): useFlag[2]
DEBUG(is_need_response): sem_lock[1]
DEBUG(PGRreplicate_packet_send_each_server): except:5432 ＠ db01 host:5432 ＠ db02
DEBUG(PGRreplicate_packet_send_each_server): send replicate to:db02
DEBUG(PGRsend_replicate_packet_to_server): host(db02) : port(5432)
DEBUG(getTransactionTbl): hit !! transaction tbl host db02 db:test pid:22656
DEBUG(getTransactionTbl): db:test port:5432 user:postgres host:db02
query:insert into test values('111')
DEBUG(getTransactionTbl): PQexec send :insert into test values('111')
DEBUG(getTransactionTbl): PQexec end
DEBUG(getTransactionTbl): sem_lock[2]
DEBUG(PGRsem_lock): sem_unlock[1]
DEBUG(PGRis_same_host): 5432 @ db01 return trigger
DEBUG(PGRreturn_result): PGRreturn_result[]
DEBUG(PGRreturn_result): 128 send
DEBUG(PGRreturn_result): wait for answer
DEBUG(PGRread_packet): query size=28
DEBUG(PGRread_packet): read[28] query[PGR_QUERY_ABORTED_NOTICE_CMD]
DEBUG(PGRread_packet): answer[PGR_QUERY_ABORTED_NOTICE_CMD]
DEBUG(PGRread_packet): QUERY ABORTED
DEBUG(PGRread_packet): status of PGRreturn_result[4]
DEBUG(PGRread_packet): sem_lock[3]
DEBUG(PGRsem_lock): sem_unlock[2]
DEBUG(delete_template): sem_unlock[3]
DEBUG(PGRsem_unlock): PGRreplicate_packet_send end
DEBUG(PGRsem_unlock): status is STATUS_ABORTED
DEBUG(child_wait): replicate main: selected
DEBUG(replicate_loop): wait replicate
DEBUG(replicate_loop): replicate_loop selected
DEBUG(PGRread_packet): query size=0
DEBUG(PGRreturn_result): PGRreturn_result[5,0]
DEBUG(PGRreturn_result): 128 send
DEBUG(PGRreturn_result): status of PGRreturn_result[0]
DEBUG(PGRreturn_result): replicate_loop selected
DEBUG(PGRread_packet): connection closed
DEBUG(child_wait): replicate main: selected

>　６．トランザクション終了
>　　#rollback;
>  
>
デバッグログなし

更新系クエリーが遅くなるだけでなく、そもそもレプリケーションされなくなる
ようです。
６．以降の更新系クエリーは、レプリケーションサーバのデバッグログに出てき
ません。