Hi Alexander, I was able to reproduce the issue. I'm investigating it now. However, I think we cannnot fix it with version 3.0.3. Because we do not have time to remain to release.
Regards, -- Toshihiro Kitagawa SRA OSS, Inc. Japan On Wed, 23 Feb 2011 08:36:50 +0900 (JST) Tatsuo Ishii <[email protected]> wrote: > 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 > > [email protected] > > http://pgfoundry.org/mailman/listinfo/pgpool-general > _______________________________________________ > Pgpool-general mailing list > [email protected] > http://pgfoundry.org/mailman/listinfo/pgpool-general > _______________________________________________ Pgpool-general mailing list [email protected] http://pgfoundry.org/mailman/listinfo/pgpool-general
