[Pgpool-general] Issue with pgpool-II-3.0.3-beta1 prepared statements execution
Toshihiro Kitagawa
kitagawa at sraoss.co.jp
Wed Feb 23 09:11:43 UTC 2011
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 <ishii at sraoss.co.jp> 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
> > Pgpool-general at pgfoundry.org
> > http://pgfoundry.org/mailman/listinfo/pgpool-general
> _______________________________________________
> Pgpool-general mailing list
> Pgpool-general at pgfoundry.org
> http://pgfoundry.org/mailman/listinfo/pgpool-general
>
More information about the Pgpool-general
mailing list