[Pgpool-general] Issue with pgpool-II-3.0.3-beta1 prepared statements execution
Tatsuo Ishii
ishii at sraoss.co.jp
Tue Feb 22 23:36:50 UTC 2011
Again, thanks for the report.
Toshiiro, what do you think?
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp
> 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/
> _______________________________________________
> Pgpool-general mailing list
> Pgpool-general at pgfoundry.org
> http://pgfoundry.org/mailman/listinfo/pgpool-general
More information about the Pgpool-general
mailing list