[Pgpool-general] pgpool, latency, and postgres protocol

Thu Nov 24 08:34:24 UTC 2011

> As temporary solution, is it possible to force pgpool to use v2 protocol
> when communicating with backend?

No.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

> If yes, can pgpool at the same time use v3 protocol to communicate with the
> clients (postgresql jdbc driver)?
> 
> Regards,
> Stevo.
> 
> On Wed, Nov 23, 2011 at 11:46 AM, Stevo Slavić <sslavic at gmail.com> wrote:
> 
>> It's definitely pgpool issue with serializing postgres frontend/backend
>> protocol messages. Tried on environment with actual (non-simulated)
>> latency. Same work takes 5 times longer with pgpool then without it.
>>
>> Using pgpool 3.1.
>>
>> Regards,
>> Stevo.
>>
>>
>> On Mon, Nov 21, 2011 at 3:28 PM, Stevo Slavić <sslavic at gmail.com> wrote:
>>
>>> Hello pgpool users,
>>>
>>> Using tc (see http://linux.die.net/man/8/tc ) I'm simulating 60ms
>>> latency between pgpool and a master backend. When executing a simple query
>>> over pgpool, backend messages seem to get serialized (see [1], notice 60ms+
>>> between almost every backend message), while when executing same query on
>>> same backend but directly (not through pgpool), backend messages get sent
>>> concurrently (see [2]) back to the driver/client.
>>>
>>> Query is executed from a simple CLI Java application which makes use of
>>> postgresql-9.1-901.jdbc4.jar driver, with logging enabled. See [3] pgpool
>>> debug log when this query is executed through pgpool.
>>>
>>> Does anyone have any ideas why is pgpool serializing these backend
>>> messages?
>>>
>>> Is there a way to enable postgres protocol messages logging in pgpool?
>>> Would like to configure that to see if pgpool is receiving messages.
>>>
>>> Also timestamp log format seems to fixed, and doesn't include
>>> milliseconds. Any way to change that?
>>>
>>> Regards,
>>> Stevo.
>>>
>>>
>>> [1] jdbc driver log output, query execution through pgpool
>>> 23:03:22.625 (1) PostgreSQL 9.1 JDBC4 (build 901)
>>> 23:03:22.646 (1) Trying to establish a protocol version 3 connection to
>>> pgsql_srv_standby:9999
>>> 23:03:22.709 (1)  FE=> StartupPacket(user=foo, database=foo,
>>> client_encoding=UTF8, DateStyle=ISO, extra_float_digits=2)
>>> 23:03:22.835 (1)  <=BE AuthenticationOk
>>> 23:03:22.849 (1)  <=BE ParameterStatus(application_name = )
>>> 23:03:22.849 (1)  <=BE ParameterStatus(client_encoding = UTF8)
>>> 23:03:22.851 (1)  <=BE ParameterStatus(DateStyle = ISO, MDY)
>>> 23:03:22.851 (1)  <=BE ParameterStatus(integer_datetimes = on)
>>> 23:03:22.851 (1)  <=BE ParameterStatus(IntervalStyle = postgres)
>>> 23:03:22.851 (1)  <=BE ParameterStatus(is_superuser = on)
>>> 23:03:22.851 (1)  <=BE ParameterStatus(server_encoding = UTF8)
>>> 23:03:22.851 (1)  <=BE ParameterStatus(server_version = 9.1.1)
>>> 23:03:22.852 (1)  <=BE ParameterStatus(session_authorization = foo)
>>> 23:03:22.852 (1)  <=BE ParameterStatus(standard_conforming_strings = on)
>>> 23:03:22.852 (1)  <=BE ParameterStatus(TimeZone = Europe/Amsterdam)
>>> 23:03:22.852 (1)  <=BE BackendKeyData(pid=24275,ckey=1498571326)
>>> 23:03:22.852 (1)  <=BE ReadyForQuery(I)
>>> 23:03:22.858 (1) simple execute,
>>> handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler at 7f54ee6,
>>> maxRows=0, fetchSize=0, flags=23
>>> 23:03:22.864 (1)  FE=> Parse(stmt=null,query="SET extra_float_digits =
>>> 3",oids={})
>>> 23:03:22.873 (1)  FE=> Bind(stmt=null,portal=null)
>>> 23:03:22.873 (1)  FE=> Execute(portal=null,limit=1)
>>> 23:03:22.874 (1)  FE=> Sync
>>> 23:03:22.934 (1)  <=BE ParseComplete [null]
>>> 23:03:22.995 (1)  <=BE BindComplete [null]
>>> 23:03:23.057 (1)  <=BE CommandStatus(SET)
>>> 23:03:23.118 (1)  <=BE ReadyForQuery(I)
>>> 23:03:23.118 (1)     compatible = 9.1
>>> 23:03:23.118 (1)     loglevel = 2
>>> 23:03:23.118 (1)     prepare threshold = 5
>>> getConnection returning
>>> driver[className=org.postgresql.Driver,org.postgresql.Driver at 7f05238]
>>> 23:03:23.150 (1) simple execute,
>>> handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler at 7f64160,
>>> maxRows=0, fetchSize=0, flags=17
>>> 23:03:23.150 (1)  FE=> Parse(stmt=null,query="select
>>> nextval('hibernate_sequence')",oids={})
>>> 23:03:23.150 (1)  FE=> Bind(stmt=null,portal=null)
>>> 23:03:23.151 (1)  FE=> Describe(portal=null)
>>> 23:03:23.151 (1)  FE=> Execute(portal=null,limit=0)
>>> 23:03:23.151 (1)  FE=> Sync
>>> 23:03:23.212 (1)  <=BE ParseComplete [null]
>>> 23:03:23.273 (1)  <=BE BindComplete [null]
>>> 23:03:23.335 (1)  <=BE RowDescription(1)
>>> 23:03:23.396 (1)  <=BE DataRow
>>> 23:03:23.396 (1)  <=BE CommandStatus(SELECT 1)
>>> 23:03:23.456 (1)  <=BE ReadyForQuery(I)
>>> 23:03:23.462 (1)  FE=> Terminate
>>>
>>> [2] jdbc driver log output, query execution directly on backend
>>> 21:16:05.428 (1) simple execute,
>>> handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler at 7f74161,
>>> maxRows=0, fetchSize=0, flags=17
>>> 21:16:05.428 (1)  FE=> Parse(stmt=null,query="select
>>> nextval('hibernate_sequence')",oids={})
>>> 21:16:05.428 (1)  FE=> Bind(stmt=null,portal=null)
>>> 21:16:05.428 (1)  FE=> Describe(portal=null)
>>> 21:16:05.428 (1)  FE=> Execute(portal=null,limit=0)
>>> 21:16:05.428 (1)  FE=> Sync
>>> 21:16:05.489 (1)  <=BE ParseComplete [null]
>>> 21:16:05.489 (1)  <=BE BindComplete [null]
>>> 21:16:05.489 (1)  <=BE RowDescription(1)
>>> 21:16:05.489 (1)  <=BE DataRow
>>> 21:16:05.489 (1)  <=BE CommandStatus(SELECT 1)
>>> 21:16:05.489 (1)  <=BE ReadyForQuery(I)
>>>
>>> [3] pgpool debug log
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: pid_file_name
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value:
>>> '/var/run/pgpool-II-91/pgpool.pid' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: logdir
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '/data/postgresql_db' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: connection_cache
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: reset_query_list
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'ABORT; DISCARD ALL' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: extract_string_tokens: token: ABORT
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: extract_string_tokens: token:
>>>  DISCARD ALL
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: replication_mode
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: replicate_select
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: replicate_select: 0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: insert_lock
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: lobj_lock_table
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: replication_stop_on_mismatch
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: replication_stop_on_mismatch: 0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key:
>>> failover_if_affected_tuples_mismatch
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> failover_if_affected_tuples_mismatch: 0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: load_balance_mode
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: ignore_leading_white_space
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: on kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: white_function_list
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: black_function_list
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value:
>>> 'currval,lastval,nextval,setval' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: extract_string_tokens: token:
>>> currval
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: extract_string_tokens: token:
>>> lastval
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: extract_string_tokens: token:
>>> nextval
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: extract_string_tokens: token: setval
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: add_to_patterns: regex pattern:
>>> ^currval$
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: add_to_patterns: regex pattern:
>>> ^lastval$
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: add_to_patterns: regex pattern:
>>> ^nextval$
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: add_to_patterns: regex pattern:
>>> ^setval$
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_hostname0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'pgsql_srv_primary' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_port0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 5432 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_weight0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 1 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_data_directory0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '/data/postgresql_db' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_flag0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'ALLOW_TO_FAILOVER' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_hostname1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '/tmp' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_port1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 5432 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_weight1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 1 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_data_directory1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '/data/postgresql_db' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: backend_flag1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'DISALLOW_TO_FAILOVER' kind:
>>> 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: master_slave_mode
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: master_slave_sub_mode
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'stream' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: sr_check_period
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 10 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: sr_check_user
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'foo' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: sr_check_password
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: delay_threshold
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 10000000 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: follow_master_command
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: parallel_mode
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: enable_query_cache
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: off kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: pgpool2_hostname
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'pgsql_srv_standby' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: system_db_hostname
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'pgsql_srv_primary' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: system_db_port
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 5432 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: system_db_dbname
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'pgpool' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: system_db_schema
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'pgpool_catalog' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: system_db_user
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'postgres' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: system_db_password
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: health_check_period
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 0 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: health_check_timeout
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 20 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: health_check_user
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'foo' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: health_check_password
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'foo' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: fail_over_on_backend_error
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: on kind: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: recovery_user
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 'nobody' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: recovery_password
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: recovery_1st_stage_command
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: recovery_2nd_stage_command
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: '' kind: 4
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: recovery_timeout
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 90 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: client_idle_limit_in_recovery
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 0 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: key: relcache_expire
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: value: 0 kind: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: num_backends: 2 total_weight:
>>> 2.000000
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: backend 0 weight: 1073741823.500000
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: backend 0 flag: 0000
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: backend 1 weight: 1073741823.500000
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: backend 1 flag: 0001
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: I am 30055 accept fd 5
>>> 2011-11-21 23:03:22 LOG:   pid 30055: connection received:
>>> host=pgsql_srv_standby port=32291
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: Protocol Major: 3 Minor: 0
>>> database: foo user: foo
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: new_connection: connecting 0 backend
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: new_connection: connecting 1 backend
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: new_connection: skipping slot 1
>>> because backend_status = 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_ssl: SSL requested but SSL
>>> support is not available
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length: slot: 0
>>> length: 8
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_do_auth: auth kind:0
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 22
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name:
>>> application_name value:
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 25
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: client_encoding
>>> value: UTF8
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 23
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: DateStyle
>>> value: ISO, MDY
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 25
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name:
>>> integer_datetimes value: on
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 27
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: IntervalStyle
>>> value: postgres
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 20
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: is_superuser
>>> value: on
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 25
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: server_encoding
>>> value: UTF8
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 25
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: server_version
>>> value: 9.1.1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 33
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name:
>>> session_authorization value: foo
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 35
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name:
>>> standard_conforming_strings value: on
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length2: master
>>> slot: 0 length: 30
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: 0 th backend: name: TimeZone value:
>>> Europe/Amsterdam
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length: slot: 0
>>> length: 12
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_do_auth:
>>> cp->info[i]:0x2aacd4239800 pid:24275
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_send_auth_ok: send pid 24275
>>> to frontend
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_command_success: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_writing_transaction: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_failed_transaction: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_transaction_isolation:
>>> done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_unset_skip_reading_from_backends: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_ignore_till_sync: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend Z NUM_BACKENDS: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: Z
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_read_message_length: slot: 0
>>> length: 5
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ReadyForQuery: transaction state:NUL
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend P(50)
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: Parse: statement name <>
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:22 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: Parse: SET extra_float_digits = 3
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend 1 NUM_BACKENDS: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: 1
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_set_command_success: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend B(42)
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: Bind: waiting for master completing
>>> the query
>>> 2011-11-21 23:03:22 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: B message
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend 2 NUM_BACKENDS: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: 2
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_set_command_success: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend E(45)
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: Execute: portal name <>
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: Execute: query: SET
>>> extra_float_digits = 3
>>> 2011-11-21 23:03:22 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: Execute: SET extra_float_digits = 3
>>> 2011-11-21 23:03:22 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend C NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: C
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_command_success: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend S(53)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend Z NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: Z
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_read_message_length: slot: 0
>>> length: 5
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ReadyForQuery: transaction state:I
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_writing_transaction: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend P(50)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: Parse: statement name <>
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: Parse: select nextval('hibernate_sequence')
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend 1 NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: 1
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_add_sent_message: prepared
>>> statement "" already exists
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: can_query_context_destroy: query
>>> context is still used.
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_command_success: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend B(42)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: Bind: waiting for master completing
>>> the query
>>> 2011-11-21 23:03:23 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: B message
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend 2 NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_add_sent_message: portal ""
>>> already exists
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_command_success: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend D(44)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: Describe: waiting for master
>>> completing the query
>>> 2011-11-21 23:03:23 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: D message
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend T NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: T
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend E(45)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: Execute: portal name <>
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: Execute: query: select
>>> nextval('hibernate_sequence')
>>> 2011-11-21 23:03:23 LOG:   pid 30055: DB node id: 0 backend pid: 24275
>>> statement: Execute: select nextval('hibernate_sequence')
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: wait_for_query_response: waiting
>>> for backend 0 completing the query
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend D NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: D
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend C NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: C
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_command_success: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend S(53)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_set_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_set_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: read_kind_from_backend: read kind
>>> from 0 th backend Z NUM_BACKENDS: 2
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessBackendResponse: kind from
>>> backend: Z
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_read_message_length: slot: 0
>>> length: 5
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ReadyForQuery: transaction state:I
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: ProcessFrontendResponse: kind from
>>> frontend X(58)
>>> 2011-11-21 23:03:23 DEBUG: pid 30055:
>>> pool_unset_doing_extended_query_message: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: can_query_context_destroy: query
>>> context is still used.
>>> 2011-11-21 23:03:23 DEBUG: pid 30055: pool_unset_query_in_progress: done
>>
>>
>>