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 [email protected] http://pgfoundry.org/mailman/listinfo/pgpool-general
