[Pgpool-general] Issue with pgpool-II-3.0.3-beta1 prepared statements execution
Alexander Zhuravlev
a.zhuravlev at gmail.com
Tue Feb 22 10:55:25 UTC 2011
Hello,
I am trying to use pgpool as a load balancer. However it looks like it
does not handle prepared statements processing correctly, because when I
issue a prepared statement from erlang pgsql client
(https://github.com/wg/epgsql) to pgpool, it hangs and does not return
anything back to erlang.
When I try to execute the same query using the same erlang pgsql client
against stock postgresql 9.0.3 or postgresql 9.0.3 sitting behind pgbouncer, I
receive correct reply. Thus I assume I am hitting some kind of a bug in pgpool.
More detailed explanation.
My setup: FreeBSD 8.0 with PostgreSQL 9.0.3 and pgpool-II-3.0.3-beta1.
Client: Erlang R13B04 with epgsql client library
(https://github.com/wg/epgsql) which speaks PostgreSQL Frontend/Backend
protocol version 3.
I am trying to execute pgsql stored procedure with an argument using the
following code:
{ok, Connection} = postgresql:get_connection('storage1'). % 'storage1' is a reference to a 'structure' containing connection info
pgsql:equery(Connection, "SELECT ItemDelete($1)", ["//example.com"]).
In a nutshell, the equery erlang function asks pgsql server to parse the
query and return types of the arguments. Then the function performs
"extended query", which prepares arguments using the type information
from the parse stage, and executes the query by sending 'B', 'E', 'C',
'S' messages to the server and reading the server response.
When I run the function against pgsql 9.0.3 or pgbouncer I immediately get
a response and can see the following debug output from the
library:
===========================================================
ready equery Statement: {statement,[],
[{column,<<"itemdelete">>,int4,4,-1,1}],
[varchar]}; Parameters: [{varchar,
"//example.com"}]
send to server. Type: 66; Data: [[],0,[],0,
<<0,1,0,1,0,1,0,0,0,13,47,47,101,120,97,109,
112,108,101,46,99,111,109>>,
<<0,1,0,1>>]
sent $B['', 0, [], 0, <<0,1,0,1,0,1,0,0,0,13,47,47,101,120,97,109,112,108,101,
46,99,111,109>>, <<0,1,0,1>>]
send to server. Type: 69; Data: [[],0,<<0,0,0,0>>]
sent $E['', 0, 0]
send to server. Type: 67; Data: [83,[],0]
sent $C[$S, '', 0]
send to server. Type: 83; Data: []
sent $S
...
read from server. bin: <<90,0,0,0,5,73>>
query type $D
notify. Pid: <0.14266.4>; Msg: {data,{0}}
*DBG* <0.14528.4> switched to state querying
*DBG* <0.14528.4> got event {67,<<83,69,76,69,67,84,32,49,0>>} in state querying
query type $C
notify. Pid: <0.14266.4>; Msg: {complete,select}
...
*DBG* <0.14528.4> got event {90,<<"I">>} in state querying
query type $Z
notify. Pid: <0.14266.4>; Msg: done
Result: {ok,[{column,<<"itemdelete">>,int4,4,-1,1}],[{0}]}
===========================================================
and the following info from pgsql server:
Feb 22 13:10:09 zaa postgres[13575]: [1492-1] DEBUG: 00000: parse <unnamed>: SELECT ItemDelete($1)
Feb 22 13:10:09 zaa postgres[13575]: [1492-2] LOCATION: exec_parse_message, postgres.c:1184
Feb 22 13:10:09 zaa postgres[13575]: [1492-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:10:09 zaa postgres[13575]: [1493-1] DEBUG: 00000: StartTransactionCommand
Feb 22 13:10:09 zaa postgres[13575]: [1493-2] LOCATION: start_xact_command, postgres.c:2464
Feb 22 13:10:09 zaa postgres[13575]: [1493-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:10:09 zaa postgres[13575]: [1494-1] DEBUG: 00000: StartTransaction
Feb 22 13:10:09 zaa postgres[13575]: [1494-2] LOCATION: ShowTransactionState, xact.c:4245
Feb 22 13:10:09 zaa postgres[13575]: [1494-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:10:09 zaa postgres[13575]: [1495-1] DEBUG: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Feb 22 13:10:09 zaa postgres[13575]: [1495-2] LOCATION: ShowTransactionStateRec, xact.c:4283
Feb 22 13:10:09 zaa postgres[13575]: [1495-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:10:09 zaa postgres[13575]: [1496-1] LOG: 00000: duration: 0.731 ms
Feb 22 13:10:09 zaa postgres[13575]: [1496-2] LOCATION: exec_parse_message, postgres.c:1415
Feb 22 13:10:09 zaa postgres[13575]: [1497-1] DEBUG: 00000: bind <unnamed> to <unnamed>
Feb 22 13:10:09 zaa postgres[13575]: [1497-2] LOCATION: exec_bind_message, postgres.c:1467
Feb 22 13:10:09 zaa postgres[13575]: [1498-1] LOG: 00000: duration: 0.234 ms
Feb 22 13:10:09 zaa postgres[13575]: [1498-2] LOCATION: exec_bind_message, postgres.c:1832
Feb 22 13:10:09 zaa postgres[13575]: [1499-1] LOG: 00000: execute <unnamed>: SELECT ItemDelete($1)
Feb 22 13:10:09 zaa postgres[13575]: [1499-2] DETAIL: parameters: $1 = '//example.com'
Feb 22 13:10:09 zaa postgres[13575]: [1499-3] LOCATION: exec_execute_message, postgres.c:1978
Feb 22 13:10:09 zaa postgres[13575]: [1500-1] LOG: 00000: duration: 7.611 ms
Feb 22 13:10:09 zaa postgres[13575]: [1500-2] LOCATION: exec_execute_message, postgres.c:2049
Feb 22 13:10:09 zaa postgres[13575]: [1501-1] DEBUG: 00000: CommitTransactionCommand
Feb 22 13:10:09 zaa postgres[13575]: [1501-2] LOCATION: finish_xact_command, postgres.c:2488
Feb 22 13:10:09 zaa postgres[13575]: [1502-1] DEBUG: 00000: CommitTransaction
Feb 22 13:10:09 zaa postgres[13575]: [1502-2] LOCATION: ShowTransactionState, xact.c:4245
Feb 22 13:10:09 zaa postgres[13575]: [1503-1] DEBUG: 00000: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/5, nestlvl: 1, children:
Feb 22 13:10:09 zaa postgres[13575]: [1503-2] LOCATION: ShowTransactionStateRec, xact.c:4283
However, when I run the function against pgpool-II-3.0.3-beta1, I see
that the function sends request to pgpool, but then erlang sits waiting for response (there
is nothing to read from socket):
ready equery Statement: {statement,[],
[{column,<<"itemdelete">>,int4,4,-1,1}],
[varchar]}; Parameters: [{varchar,
"//example.com"}]
send to server. Type: 66; Data: [[],0,[],0,
<<0,1,0,1,0,1,0,0,0,13,47,47,101,120,97,109,
112,108,101,46,99,111,109>>,
<<0,1,0,1>>]
sent $B['', 0, [], 0, <<0,1,0,1,0,1,0,0,0,13,47,47,101,120,97,109,112,108,101,
46,99,111,109>>, <<0,1,0,1>>]
send to server. Type: 69; Data: [[],0,<<0,0,0,0>>]
sent $E['', 0, 0]
send to server. Type: 67; Data: [83,[],0]
sent $C[$S, '', 0]
send to server. Type: 83; Data: []
sent $S
...
At the same time pgpool and postgresql log the following information:
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessFrontendResponse: kind from frontend P(50)
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_unset_doing_extended_query_message: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_set_doing_extended_query_message: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_set_query_in_progress: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: Parse: statement name <>
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_set_query_in_progress: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 LOG: pid 1618: DB node id: 0 backend pid: 17797 statement:
Feb 22 13:46:02 zaa postgres[17797]: [1968-1] DEBUG: 00000: parse <unnamed>: SELECT ItemDelete($1)
Feb 22 13:46:02 zaa postgres[17797]: [1968-2] LOCATION: exec_parse_message, postgres.c:1184
Feb 22 13:46:02 zaa postgres[17797]: [1968-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: wait_for_query_response: waiting for backend 0 completing the query
Feb 22 13:46:02 zaa postgres[17797]: [1969-1] DEBUG: 00000: StartTransactionCommand
Feb 22 13:46:02 zaa postgres[17797]: [1969-2] LOCATION: start_xact_command, postgres.c:2464
Feb 22 13:46:02 zaa postgres[17797]: [1969-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:46:02 zaa postgres[17797]: [1970-1] DEBUG: 00000: StartTransaction
Feb 22 13:46:02 zaa postgres[17797]: [1970-2] LOCATION: ShowTransactionState, xact.c:4245
Feb 22 13:46:02 zaa postgres[17797]: [1970-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:46:02 zaa postgres[17797]: [1971-1] DEBUG: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Feb 22 13:46:02 zaa postgres[17797]: [1971-2] LOCATION: ShowTransactionStateRec, xact.c:4283
Feb 22 13:46:02 zaa postgres[17797]: [1971-3] STATEMENT: SELECT ItemDelete($1)
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 LOG: pid 1618: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 17797 statement: message: parse <unnamed>: SELECT ItemDelete($1)
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: N
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: N
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: N
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: N
Feb 22 13:46:02 zaa postgres[17797]: [1972-1] LOG: 00000: duration: 0.988 ms
Feb 22 13:46:02 zaa postgres[17797]: [1972-2] LOCATION: exec_parse_message, postgres.c:1415
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend 1 NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_unset_query_in_progress: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend N NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: N
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessFrontendResponse: kind from frontend D(44)
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_unset_doing_extended_query_message: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_set_doing_extended_query_message: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_set_query_in_progress: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: Describe: waiting for master completing the query
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 LOG: pid 1618: DB node id: 0 backend pid: 17797 statement: S
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: wait_for_query_response: waiting for backend 0 completing the query
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend t NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: t
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 1
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessBackendResponse: kind from backend: T
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_unset_query_in_progress: done
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: ProcessFrontendResponse: kind from frontend H(48)
Feb 22 13:46:02 zaa pgpool: 2011-02-22 13:46:02 DEBUG: pid 1618: pool_unset_doing_extended_query_message: done
It looks like pgpool does not perform bind message or something like this, because
the log message from correct call above proceeds with exec_bind_message after
the exec_parse_message call.
Could someone please shed some light on what might be causing the
issue?
Thank you.
--
Alexander Zhuravlev
http://ikato.com/
More information about the Pgpool-general
mailing list