[Pgpool-general] Lockup while using pgbouncer + pgpool

Josh Berkus josh at agliodbs.com
Fri Aug 13 23:25:02 UTC 2010 

Ok, I'm testing pgbouncer + pgpool using pgreplay.  There was some kind
of failure which either caused pgpool to stop processing queries, or for
pgreplay to think that it had.  Below is the debug log from pgpool.
Note that after 18:44, no more queries were being sent to the database
servers.

pgreplay waits for a response on each connection before sending the next
query, so it's possible that the failure was a response not being sent
back rather than pgpool not processing queries.

BTW, how can I get a count of how many pgpool connections are *active*?
 pcp_proc_count gives me all of the processes, whether they're connected
to a backend DB or not.

2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19597: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19597: statement2: SELECT 'DBD::Pg ping test'
2010-08-13 18:44:25 DEBUG: pid 19597: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend T NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: T
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend D NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: D
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend C NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19597: end_load_balance: end load balance
mode
2010-08-13 18:44:25 DEBUG: pid 19597: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19597: statement2: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19597: SimpleQuery: set master_slave_dml
query: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19597: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19597: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19597: statement2: SELECT 'DBD::Pg ping test'
2010-08-13 18:44:25 DEBUG: pid 19597: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend T NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: T
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend D NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: D
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend C NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 1
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19597: end_load_balance: end load balance
mode
2010-08-13 18:44:25 DEBUG: pid 19597: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19597: statement2: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19597: SimpleQuery: set master_slave_dml
query: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19597: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19755: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19755: statement2: SELECT 'DBD::Pg ping test'
2010-08-13 18:44:25 DEBUG: pid 19755: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19597: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend T NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: T
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend D NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: D
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19755: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19755: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19755: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19755: end_load_balance: end load balance
mode
2010-08-13 18:44:25 DEBUG: pid 19755: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19755: statement2: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19755: SimpleQuery: set master_slave_dml
query: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19755: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19689: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19689: statement2: SELECT 'DBD::Pg ping test'
2010-08-13 18:44:25 DEBUG: pid 19689: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19755: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19755: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19755: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19755: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19755: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend T NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: T
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19597: read_kind_from_backend: read kind
from 0 2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend:
read kind from 0 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: parameter
name: is_superuser value: off
DS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19597: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th 2010-08-13 18:44:25 DEBUG: pid 19689:
pool_read_message_length: slot: 1 length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19597: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: end_load_balance: end load balance
mode
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19755: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: statement2: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19755: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: SimpleQuery: set master_slave_dml
query: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19755: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19689: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 0 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19689: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19689: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19689: statement2: SELECT 'DBD::Pg ping test'
2010-08-13 18:44:25 DEBUG: pid 19689: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend T NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: T
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend D NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: D
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19689: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19689: end_load_balance: end load balance
mode
2010-08-13 18:44:25 DEBUG: pid 19689: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19689: statement2: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19689: SimpleQuery: set master_slave_dml
query: DISCARD ALL;
2010-08-13 18:44:25 DEBUG: pid 19689: wait_for_query_response: waiting
for backend 0 completing the query
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: detect_error: kind: S
2010-08-13 18:44:25 DEBUG: pid 19689: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 0 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: is_superuser value: off
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: parameter
name: session_authorization value: at
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 0 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19689: pool_process_query: kind from
backend: Z
2010-08-13 18:44:25 DEBUG: pid 19689: pool_read_message_length: slot: 0
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: pool_read_message_length: slot: 1
length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: message length: 5
2010-08-13 18:44:25 DEBUG: pid 19689: ReadyForQuery: transaction state: I
2010-08-13 18:44:25 DEBUG: pid 19689: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19755: read kind from frontend Q(51)
2010-08-13 18:44:25 DEBUG: pid 19689: statement2: select 1, parent from
account where account_id = 123412390141
2010-08-13 18:44:25 DEBUG: pid 19755: statement2: SELECT 'DBD::Pg ping test'
2010-08-13 18:44:25 DEBUG: pid 19755: wait_for_query_response: waiting
for backend 1 completing the query
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend T NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: T
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend D NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: D
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend C NUM_BACKENDS: 2
2010-08-13 18:44:25 DEBUG: pid 19755: pool_process_query: kind from
backend: C
2010-08-13 18:44:25 DEBUG: pid 19755: read_kind_from_backend: read kind
from 1 th backend Z NUM_BACKENDS: 2




-- 
                                  -- Josh Berkus
                                     PostgreSQL Experts Inc.
                                     http://www.pgexperts.com

More information about the Pgpool-general mailing list