I'm not sure why pgpool need to wait for backend response here. Maybe Toshihiro has some idea about this. Toshihiro? -- Tatsuo Ishii SRA OSS, Inc. Japan English: http://www.sraoss.co.jp/index_en.php Japanese: http://www.sraoss.co.jp
> Thanks Tatsuo for quick response! > > If it was Java based, I would be much more able to contribute in fixing > this issue. Child processes which handle connections/communication seem to > be single threaded. Not sure where does pgpool block, must be somewhere > when reading and/or sending postgres protocol message. Maybe profiling > pgpool executable would help - any advices on how to do that properly are > welcome. > > Is pgpool issue tracker at pgfoundry still being used ( > http://pgfoundry.org/tracker/?atid=298&group_id=1000055&func=browse ) ? > Checking whether to report this issue there or somewhere else. > > Would this issue even be considered for fixing or is this design decision > that's not likely to be changed any time soon? Need this info to decide > whether to stick with pgpool (much preferred) or look for other solutions. > > Regards, > Stevo. > > 2011/11/24 Tatsuo Ishii <[email protected]> > >> > As temporary solution, is it possible to force pgpool to use v2 protocol >> > when communicating with backend? >> >> No. >> -- >> Tatsuo Ishii >> SRA OSS, Inc. Japan >> English: http://www.sraoss.co.jp/index_en.php >> Japanese: http://www.sraoss.co.jp >> >> > If yes, can pgpool at the same time use v3 protocol to communicate with >> the >> > clients (postgresql jdbc driver)? >> > >> > Regards, >> > Stevo. >> > >> > On Wed, Nov 23, 2011 at 11:46 AM, Stevo Slavić <[email protected]> >> 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ć <[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
