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

Thu Nov 24 09:19:11 UTC 2011

I'm not sure why pgpool need to wait for backend response here. Maybe
Toshihiro has some idea about this. Toshihiro?
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

> Thanks Tatsuo for quick response!
> 
> If it was Java based, I would be much more able to contribute in fixing
> this issue. Child processes which handle connections/communication seem to
> be single threaded. Not sure where does pgpool block, must be somewhere
> when reading and/or sending postgres protocol message. Maybe profiling
> pgpool executable would help - any advices on how to do that properly are
> welcome.
> 
> Is pgpool issue tracker at pgfoundry still being used (
> http://pgfoundry.org/tracker/?atid=298&group_id=1000055&func=browse ) ?
> Checking whether to report this issue there or somewhere else.
> 
> Would this issue even be considered for fixing or is this design decision
> that's not likely to be changed any time soon? Need this info to decide
> whether to stick with pgpool (much preferred) or look for other solutions.
> 
> Regards,
> Stevo.
> 
> 2011/11/24 Tatsuo Ishii <ishii at sraoss.co.jp>
> 
>> > 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
>> >>
>> >>
>> >>
>>