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

Thu Nov 24 08:29:16 UTC 2011

As temporary solution, is it possible to force pgpool to use v2 protocol
when communicating with backend?

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/34330ed8/attachment-0001.html>