[pgpool-general-jp: 123] Re: pgpool3.2+JDBC環境でのreplication_strictの挙動について

tutui-t @ sys.tosho.co.jp tutui-t @ sys.tosho.co.jp
2007年 5月 7日 (月) 15:04:03 JST


こんにちは、筒井です。


> 同じような再現プログラムを書いて動かしてみましたが、手元の環境では結果
> が返ってきてからセカンダリに送っていました。もしデバッグログが残ってい
> ましたらいただけないでしょうか?
> 
> また、接続する際に以下のように loglevel を 2 にしていただけますでしょ
> うか?JDBC ドライバのデバッグログを取得することができます。

先ほど、テストした結果をお送りします(少し長くなります)。
パケットのやり取り順序は前と変わりありませんでした。
今回は以下のように実行しています。
  connection.setAutoCommit(false);
  stmt = connection.createStatement();
  stmt.executeUpdate("LOCK test_data;");
  stmt.executeUpdate("UPDATE 〜");
  connection.commit();



pgpoolのデバッグログです。
---------------------------------------------------------------
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737: I
am 9737 accept fd 6
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
Protocol Major: 3 Minor: 0 database: test_db user: postgres
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length: lenghth: 8
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
trying clear text password authentication
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 28
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: client_encoding value: UNICODE
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: client_encoding value: UNICODE
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 23
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: DateStyle value: ISO, YMD
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: DateStyle value: ISO, YMD
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 26
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: integer_datetimes value: off
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: integer_datetimes value: off
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 20
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: is_superuser value: on
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: is_superuser value: on
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 27
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: server_encoding value: EUC_JP
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: server_encoding value: EUC_JP
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 25
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: server_version value: 8.2.4
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: server_version value: 8.2.4
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 35
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: session_authorization value: postgres
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: session_authorization value: postgres
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 36
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: standard_conforming_strings value: off
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: standard_conforming_strings value: off
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length2: master lenghth: 19
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
name: TimeZone value: Japan
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
secondary name: TimeZone value: Japan
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length: lenghth: 12
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_send_auth_ok: send pid 304 to frontend
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from backend pending data Z len: 5 po: 270
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_process_query: kind from backend: Z
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length: lenghth: 5
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: message length: 5
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: transaction state: I
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend P(50)
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend B(42)
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
bind message: portal_name  stmt_name S_1
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend E(45)
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
Execute: portal name <>
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend P(50)
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend B(42)
May  7 14:25:25 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
bind message: portal_name  stmt_name
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend D(44)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend E(45)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
Execute: portal name <>
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend S(53)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from secondary backend Z
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_process_query: kind from backend: Z
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length: lenghth: 5
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: message length: 5
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: transaction state: T
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend P(50)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend B(42)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
bind message: portal_name  stmt_name
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend D(44)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend E(45)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
Execute: portal name <>
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend S(53)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from secondary backend Z
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_process_query: kind from backend: Z
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length: lenghth: 5
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: message length: 5
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: transaction state: T
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend P(50)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend B(42)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
bind message: portal_name  stmt_name S_2
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend E(45)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
Execute: portal name <>
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
waiting for backend completing the query
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from frontend S(53)
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
read kind from backend Z
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_process_query: waiting for secondary for data ready
May  7 14:25:26 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_process_query: kind from backend: Z
May  7 14:25:27 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
pool_read_message_length: lenghth: 5
May  7 14:25:27 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: message length: 5
May  7 14:25:27 test_host pgpool: 2007-05-07 14:25:25 DEBUG: pid 9737:
ReadyForQuery: transaction state: I


JDBCのデバッグログです。
---------------------------------------------------------------
14:25:25.032 (2) PostgreSQL 8.2 JDBC3 with SSL (build 505)
14:25:25.033 (2) Trying to establish a protocol version 3 connection to
192.168.0.25:5432
14:25:25.046 (2)  FE=> StartupPacket(user=postgres, database=test_db,
client_encoding=UNICODE, DateStyle=ISO)
14:25:25.055 (2)  <=BE AuthenticationReqPassword
14:25:25.055 (2)  FE=> Password(password=<not shown>)
14:25:25.063 (2)  <=BE AuthenticationOk
14:25:25.071 (2)  <=BE ParameterStatus(client_encoding = UNICODE)
14:25:25.072 (2)  <=BE ParameterStatus(DateStyle = ISO, YMD)
14:25:25.073 (2)  <=BE ParameterStatus(integer_datetimes = off)
14:25:25.073 (2)  <=BE ParameterStatus(is_superuser = on)
14:25:25.074 (2)  <=BE ParameterStatus(server_encoding = EUC_JP)
14:25:25.074 (2)  <=BE ParameterStatus(server_version = 8.2.4)
14:25:25.074 (2)  <=BE ParameterStatus(session_authorization = postgres)
14:25:25.075 (2)  <=BE ParameterStatus(standard_conforming_strings = off)
14:25:25.075 (2)  <=BE ParameterStatus(TimeZone = Japan)
14:25:25.075 (2)  <=BE BackendKeyData(pid=304,ckey=200397122)
14:25:25.075 (2)  <=BE ReadyForQuery(I)
14:25:25.076 (2)     compatible = 8.2
14:25:25.076 (2)     loglevel = 2
14:25:25.076 (2)     prepare threshold = 5
14:25:25.078 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler @ 2f0d54,
maxRows=0, fetchSize=0, flags=5
14:25:25.079 (2)  FE=> Parse(stmt=S_1,query="BEGIN",oids={})
14:25:25.079 (2)  FE=> Bind(stmt=S_1,portal=null)
14:25:25.079 (2)  FE=> Execute(portal=null,limit=0)
14:25:25.080 (2)  FE=> Parse(stmt=null,query="LOCK test_data",oids={})
14:25:25.080 (2)  FE=> Bind(stmt=null,portal=null)
14:25:25.080 (2)  FE=> Describe(portal=null)
14:25:25.080 (2)  FE=> Execute(portal=null,limit=1)
14:25:25.081 (2)  FE=> Sync
14:25:25.083 (2)  <=BE ParseComplete [S_1]
14:25:25.083 (2)  <=BE BindComplete [null]
14:25:25.085 (2)  <=BE CommandStatus(BEGIN)
14:25:25.085 (2)  <=BE ParseComplete [null]
14:25:25.086 (2)  <=BE BindComplete [null]
14:25:25.087 (2)  <=BE NoData
14:25:25.089 (2)  <=BE CommandStatus(LOCK TABLE)
14:25:25.090 (2)  <=BE ReadyForQuery(T)
14:25:25.090 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler @ a9255c,
maxRows=0, fetchSize=0, flags=5
14:25:25.091 (2)  FE=> Parse(stmt=null,query="UPDATE test_data SET
last_logout='2007-05-07 14:25:00' WHERE user_id = '12'",oids={})
14:25:25.091 (2)  FE=> Bind(stmt=null,portal=null)
14:25:25.091 (2)  FE=> Describe(portal=null)
14:25:25.091 (2)  FE=> Execute(portal=null,limit=1)
14:25:25.092 (2)  FE=> Sync
14:25:25.095 (2)  <=BE ParseComplete [null]
14:25:25.096 (2)  <=BE BindComplete [null]
14:25:25.096 (2)  <=BE NoData
14:25:25.099 (2)  <=BE CommandStatus(UPDATE 1)
14:25:25.146 (2)  <=BE ReadyForQuery(T)
14:25:25.147 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler @ d3c6a3,
maxRows=0, fetchSize=0, flags=22
14:25:25.147 (2)  FE=> Parse(stmt=S_2,query="COMMIT",oids={})
14:25:25.147 (2)  FE=> Bind(stmt=S_2,portal=null)
14:25:25.148 (2)  FE=> Execute(portal=null,limit=1)
14:25:25.148 (2)  FE=> Sync
14:25:25.149 (2)  <=BE ParseComplete [S_2]
14:25:25.150 (2)  <=BE BindComplete [null]
14:25:25.198 (2)  <=BE CommandStatus(COMMIT)
14:25:25.199 (2)  <=BE ReadyForQuery(I)


以上ですが、これでよろしいでしょうか?
よろしくお願いいたします。


pgpool-general-jp メーリングリストの案内