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

Wed Nov 23 18:46:26 UTC 2011

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/20111123/76fe74c3/attachment-0001.html>