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ć <[email protected]> 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@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@7f05238] > 23:03:23.150 (1) simple execute, > handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@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@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
_______________________________________________ Pgpool-general mailing list [email protected] http://pgfoundry.org/mailman/listinfo/pgpool-general
