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

Mon Nov 21 22:28:15 UTC 2011

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/20111121/0efe8362/attachment-0001.html>