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

Thu Nov 24 08:59:54 UTC 2011

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
> >>
> >>
> >>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://pgfoundry.org/pipermail/pgpool-general/attachments/20111124/5373dde9/attachment-0001.html>