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
