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

Fri Nov 25 07:47:09 UTC 2011

On Thu, 24 Nov 2011 18:19:11 +0900 (JST)
Tatsuo Ishii <ishii at sraoss.co.jp> wrote:

> I'm not sure why pgpool need to wait for backend response here. Maybe
> Toshihiro has some idea about this. Toshihiro?

I guess that the implementation for extended query protocol only succeeded
to the simple design which relay a message at every message.

I think that pgpool doesn't need to wait for backend response until Sync
message, if frontend is JDBC driver. However, it might cause problem with
the other drivers.

-- 
Toshihiro Kitagawa
SRA OSS, Inc. Japan

> --
> 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
> >> >>
> >> >>
> >> >>
> >>
> 