[Pgpool-general] Error in pgpool
Tatsuo Ishii
ishii at sraoss.co.jp
Fri Apr 3 10:39:21 UTC 2009
I have looked into this and found that it was actually caused by a bug
(this bug has been there since pgpool-II 2.1).
When DISCARD ALL is sent, pgpool forgets all prepared statement in its
internal table. Problem is, this is not done if the query is in
reset_query_list. Included is a patch to solve the problem. Please
try.
By this fix, now reset_query_list should be able to contain "DISCARD
ALL" without any errors in PostgreSQL.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
> > It would appear that switching reset_query_list back from 'ABORT; DISCARD ALL' to 'ABORT; RESET ALL; SET SESSION AUTHORIZATION DEFAULT' stops this happening for us. I'm not 100% sure yet, but since I changed this parameter and reloaded the configuration I've not seen any more of these deallocate errors.
>
> That's expected behavior. DISCARD ALL conflicts pgpool-II's automatic
> DEALLOCATE prepapred statements.
>
> > After I reloaded pgpool I gradually saw less of the errors until they (appear to have) stopped, so I assume the updated parameter is only read by the backend when a client connects?
>
> Yes. Probably it should be documented somewhere though.
>
> > I.e. I presume everyone connected before I reloaded issued an 'ABORT; DISCARD ALL', and anyone connecting afterwards would use 'ABORT; RESET ALL; SET SESSION AUTHORIZATION DEFAULT' ?
>
> Right.
> --
> Tatsuo Ishii
> SRA OSS, Inc. Japan
>
> > --- On Thu, 26/3/09, Glyn Astill <glynastill at yahoo.co.uk> wrote:
> >
> > > From: Glyn Astill <glynastill at yahoo.co.uk>
> > > Subject: Re: [Pgpool-general] Error in pgpool
> > > To: nimesh.satam at gmail.com, "Tatsuo Ishii" <ishii at sraoss.co.jp>
> > > Cc: pgpool-general at pgfoundry.org
> > > Date: Thursday, 26 March, 2009, 5:01 PM
> > > Hi Tatsuo,
> > >
> > > I'm using pgpool 2.2 in connection pool mode, and I see
> > > a similar problem with the deallocate errors. I appear to
> > > get a deallocate error for every prepared statement that the
> > > a particular client made. I've not done a thorough
> > > investigation here however it appears to only be for some
> > > users, perhaps it depends on how they dissconnected/ were
> > > dissconnected?
> > >
> > > E.g I'm seeing lots of the following in my logs since
> > > going from 2.1 -> 2.2
> > >
> > > 2009-03-26 16:51:03 GMT [12164]: [1-1]: [user=rutrupe]:
> > > [host=192.168.1.98]: [db=SEE]:: ERROR: prepared statement
> > > "find_eq_f1_byindx_0_1" does not exist
> > > 2009-03-26 16:51:03 GMT [12164]: [2-1]: [user=rutrupe]:
> > > [host=192.168.1.98]: [db=SEE]:: STATEMENT: DEALLOCATE
> > > "find_eq_f1_byindx_0_1"
> > >
> > >
> > > Any ideas?
> > >
> > > Thanks
> > > Glyn
> > >
> > >
> > > --- On Tue, 24/3/09, Tatsuo Ishii
> > > <ishii at sraoss.co.jp> wrote:
> > >
> > > > From: Tatsuo Ishii <ishii at sraoss.co.jp>
> > > > Subject: Re: [Pgpool-general] Error in pgpool
> > > > To: nimesh.satam at gmail.com
> > > > Cc: pgpool-general at pgfoundry.org
> > > > Date: Tuesday, 24 March, 2009, 3:11 PM
> > > > Thanks but I'm looking for the PostgreSQL *when*
> > > and
> > > > *how* the
> > > > prepared statement (in this case S_4) was created.
> > > Probably
> > > > that can be
> > > > found a little bit earlier in the PostgreSQL log.
> > > > --
> > > > Tatsuo Ishii
> > > > SRA OSS, Inc. Japan
> > > >
> > > > > Tatsuo,
> > > > >
> > > > > Here are the db and pgpool logs at the time of
> > > > failure. (Pgpool finds
> > > > > the prepared statement S-4 on one server but
> > > fails to
> > > > find one on the
> > > > > other server. As a result pgpool exits the child
> > > with
> > > > Kind mis-match
> > > > > error) Let us know if this helps or you need
> > > further
> > > > information.
> > > > >
> > > > > Db log on master:
> > > > >
> > > > > 2009-03-23 09:49:42 PDT [13934]: [165-1] LOG:
> > > > duration: 0.054 ms
> > > > > statement: RESET ALL
> > > > > 2009-03-23 09:49:42 PDT [13934]: [166-1] LOG:
> > > > duration: 0.021 ms
> > > > > statement: SET SESSION AUTHORIZATION DEFAULT
> > > > > 2009-03-23 09:49:42 PDT [13934]: [167-1] LOG:
> > > > duration: 0.025 ms
> > > > > statement: DEALLOCATE "S_1"
> > > > > 2009-03-23 09:49:42 PDT [13934]: [168-1] LOG:
> > > > duration: 0.014 ms
> > > > > statement: DEALLOCATE "S_4"
> > > > > 2009-03-23 09:49:42 PDT [13934]: [169-1] LOG:
> > > > unexpected EOF on
> > > > > client connection
> > > > > 2009-03-23 09:49:42 PDT [13934]: [170-1] LOG:
> > > > disconnection: session
> > > > > time: 1:12:54.620 user=aaaa database=test
> > > > host=xx.xx.xx.xx port=53261
> > > > >
> > > > > Db log on slave:
> > > > >
> > > > > 2009-03-23 09:49:42 PDT [8827]: [9-1] LOG:
> > > duration:
> > > > 0.037 ms
> > > > > statement: RESET ALL
> > > > > 2009-03-23 09:49:42 PDT [8827]: [10-1] LOG:
> > > duration:
> > > > 0.034 ms
> > > > > statement: SET SESSION AUTHORIZATION DEFAULT
> > > > > 2009-03-23 09:49:42 PDT [2838]: [192-1] LOG:
> > > > duration: 0.042 ms
> > > > > statement: RESET ALL
> > > > > 2009-03-23 09:49:42 PDT [2838]: [193-1] LOG:
> > > > duration: 0.030 ms
> > > > > statement: SET SESSION AUTHORIZATION DEFAULT
> > > > > 2009-03-23 09:49:42 PDT [2838]: [194-1] LOG:
> > > > duration: 0.028 ms
> > > > > statement: DEALLOCATE "S_1"
> > > > > 2009-03-23 09:49:42 PDT [2838]: [195-1] ERROR:
> > > > prepared statement
> > > > > "S_4" does not exist
> > > > > 2009-03-23 09:49:42 PDT [2838]: [196-1]
> > > STATEMENT:
> > > > DEALLOCATE "S_4"
> > > > > 2009-03-23 09:49:42 PDT [2838]: [197-1] LOG:
> > > > unexpected EOF on client
> > > > > connection
> > > > > 2009-03-23 09:49:42 PDT [2838]: [198-1] LOG:
> > > > disconnection: session
> > > > > time: 1:12:54.619 user=aaaa database=test
> > > > host=xx.xx.xx.zz port=52815
> > > > >
> > > > > pgpool logs:
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: statement2:
> > > > DEALLOCATE "S_1"
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: SimpleQuery:
> > > set
> > > > master_slave_dml
> > > > > query: DEALLOCATE "S_1"
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for
> > > > backend 0 completing the query
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for
> > > > backend 1 completing the query
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > read_kind_from_backend: read kind
> > > > > from 0 th backend C NUM_BACKENDS: 2
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > read_kind_from_backend: read kind
> > > > > from 1 th backend C NUM_BACKENDS: 2
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > pool_process_query: kind from backend: C
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > read_kind_from_backend: read kind
> > > > > from 0 th backend Z NUM_BACKENDS: 2
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > read_kind_from_backend: read kind
> > > > > from 1 th backend Z NUM_BACKENDS: 2
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > pool_process_query: kind from backend: Z
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > pool_read_message_length: slot: 0 length: 5
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > pool_read_message_length: slot: 1 length: 5
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > ReadyForQuery:
> > > > message length: 5
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > ReadyForQuery:
> > > > transaction state: I
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: statement2:
> > > > DEALLOCATE "S_4"
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: SimpleQuery:
> > > set
> > > > master_slave_dml
> > > > > query: DEALLOCATE "S_4"
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for
> > > > backend 0 completing the query
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218: waiting for
> > > > backend 1 completing the query
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > read_kind_from_backend: read kind
> > > > > from 0 th backend C NUM_BACKENDS: 2
> > > > > 2009-03-23 09:49:42 DEBUG: pid 1218:
> > > > read_kind_from_backend: read kind
> > > > > from 1 th backend E NUM_BACKENDS: 2
> > > > > 2009-03-23 09:49:42 ERROR: pid 1218:
> > > > pool_process_query: 1 th kind E
> > > > > does not match with master connection kind C
> > > > >
> > > > > Regards,
> > > > > Nimesh.
> > > > >
> > > > >
> > > > >
> > > > > On Tue, Mar 24, 2009 at 6:12 AM, Tatsuo Ishii
> > > > <ishii at sraoss.co.jp> wrote:
> > > > > >> All
> > > > > >>
> > > > > >> We are facing problem with pgpool where
> > > the
> > > > java application fails in
> > > > > >> certain situation I/o problem.
> > > > > >>
> > > > > >> When we see these problem we see in the
> > > db
> > > > logs error statement like:
> > > > > >>
> > > > > >> "ERROR: prepared statement
> > > > "S_3" does not exist".
> > > > > >> "LOG: unexpected EOF on client
> > > > connection"
> > > > > >>
> > > > > >> We get the following log output in the
> > > pgpool
> > > > log files:
> > > > > >>
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > detect_error: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: kind: Z
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > pool_read_message_length: slot:
> > > > > >> 0 length: 5
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > pool_read_message_length: slot:
> > > > > >> 1 length: 5
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > ReadyForQuery: message length: 5
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > ReadyForQuery: transaction state: I
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > statement2: DEALLOCATE "S_3"
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > SimpleQuery: set
> > > > > >> master_slave_dml query: DEALLOCATE
> > > > "S_3"
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: Query: BEGIN
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > detect_error: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: kind: Z
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: transaction state: T
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: Query: BEGIN
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > detect_error: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: kind: Z
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > do_command: transaction state: T
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > waiting
> > > > for backend 0 completing the query
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > detect_error: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > detect_error: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > detect_error: kind: C
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > waiting
> > > > for backend 1 completing the query
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > read_kind_from_backend: read
> > > > > >> kind from 0 th backend C NUM_BACKENDS: 2
> > > > > >> 2009-03-17 12:24:56 DEBUG: pid 27834:
> > > > read_kind_from_backend: read
> > > > > >> kind from 1 th backend E NUM_BACKENDS: 2
> > > > > >> 2009-03-17 12:24:56 ERROR: pid 27834:
> > > > read_kind_from_backend: 1 th
> > > > > >> kind E does not match with master or
> > > majority
> > > > connection k
> > > > > >> ind C
> > > > > >> 2009-03-17 12:24:56 ERROR: pid 27834:
> > > kind
> > > > mismatch among backends.
> > > > > >> Possible last query was:
> > > "DEALLOCATE
> > > > "S_3"" kind details
> > > > > >> are: 0[C] 1[E]
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834: I
> > > am
> > > > 27834 accept fd 5
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > Protocol Major: 3 Minor: 0
> > > > > >> database: rpt_production user: chakra
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > new_connection: connecting 0 backend
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > new_connection: connecting 1 backend
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > pool_read_message_length: slot:
> > > > > >> 0 length: 8
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > pool_read_message_length: slot:
> > > > > >> 1 length: 8
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > pool_read_message_length2:
> > > > > >> master slot: 0 length: 28
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834:
> > > > pool_read_message_length2:
> > > > > >> master slot: 1 length: 28
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834: 0
> > > th
> > > > backend: name:
> > > > > >> client_encoding value: UNICODE
> > > > > >> 2009-03-17 12:24:58 DEBUG: pid 27834: 1
> > > th
> > > > backend: name:
> > > > > >> client_encoding value: UNICODE
> > > > > >>
> > > > > >> Why does pgpool try to DEALLOCATE a
> > > prepare
> > > > statement on both the
> > > > > >> database servers, when pgpool is set in
> > > > Matser/slave mode. Can any
> > > > > >> body high light how this issue can be
> > > solved.
> > > > Will really appreciate
> > > > > >> your inputs in this.
> > > > > >
> > > > > > Even if you are in master/slave mode, you
> > > need to
> > > > send prepare to both
> > > > > > nodes for BEGIN statement. That's the
> > > reason
> > > > why DEALLOCATE has been
> > > > > > sent to both nodes.
> > > > > >
> > > > > > BTW, can you send us PostgreSQL log with
> > > > statement logging enabled? It
> > > > > > will help to investigate why you are seeing
> > > error
> > > > regarding S_3.
> > > > > > --
> > > > > > Tatsuo Ishii
> > > > > > SRA OSS, Inc. Japan
> > > > > >
> > > > _______________________________________________
> > > > 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
> >
> _______________________________________________
> Pgpool-general mailing list
> Pgpool-general at pgfoundry.org
> http://pgfoundry.org/mailman/listinfo/pgpool-general
-------------- next part --------------
Index: pool_proto_modules.c
===================================================================
RCS file: /cvsroot/pgpool/pgpool-II/pool_proto_modules.c,v
retrieving revision 1.6
diff -c -r1.6 pool_proto_modules.c
*** pool_proto_modules.c 22 Jan 2009 09:16:37 -0000 1.6
--- pool_proto_modules.c 3 Apr 2009 10:35:48 -0000
***************
*** 141,146 ****
--- 141,149 ----
int deadlock_detected = 0;
int active_sql_transaction_error = 0;
+ POOL_MEMORY_POOL *old_context = NULL;
+ Portal *portal;
+
force_replication = 0;
if (query == NULL) /* need to read query from frontend? */
{
***************
*** 343,405 ****
if (MASTER_SLAVE && TSTATE(backend) != 'E')
force_replication = 1;
! if (frontend)
{
! POOL_MEMORY_POOL *old_context = NULL;
! Portal *portal;
! if (IsA(node, PrepareStmt))
{
! pending_function = add_prepared_list;
! portal = create_portal();
! if (portal == NULL)
! {
! pool_error("SimpleQuery: create_portal() failed");
! return POOL_END;
! }
! /* switch memory context */
! old_context = pool_memory;
! pool_memory = portal->prepare_ctxt;
!
! portal->portal_name = NULL;
! portal->stmt = copyObject(node);
! portal->sql_string = NULL;
! pending_prepared_portal = portal;
! }
! else if (IsA(node, DeallocateStmt))
! {
! pending_function = del_prepared_list;
! portal = create_portal();
! if (portal == NULL)
! {
! pool_error("SimpleQuery: create_portal() failed");
! return POOL_END;
! }
! /* switch memory context */
! old_context = pool_memory;
! pool_memory = portal->prepare_ctxt;
!
! portal->portal_name = NULL;
! portal->stmt = copyObject(node);
! portal->sql_string = NULL;
! pending_prepared_portal = portal;
! }
! else if (IsA(node, DiscardStmt))
{
! DiscardStmt *stmt = (DiscardStmt *)node;
! if (stmt->target == DISCARD_ALL || stmt->target == DISCARD_PLANS)
! {
! pending_function = delete_all_prepared_list;
! pending_prepared_portal = NULL;
! }
}
-
- /* switch old memory context */
- if (old_context)
- pool_memory = old_context;
}
}
if (frontend && IsA(node, ExecuteStmt))
--- 346,411 ----
if (MASTER_SLAVE && TSTATE(backend) != 'E')
force_replication = 1;
! /*
! * Before we do followings only when frontend == NULL,
! * which was wrong since if, for example, reset_query_list
! * contains "DISCARD ALL", then it does not register
! * pending function and it causes trying to DEALLOCATE non
! * existing prepared statment(2009/4/3 Tatsuo).
! */
! if (IsA(node, PrepareStmt))
{
! pending_function = add_prepared_list;
! portal = create_portal();
! if (portal == NULL)
! {
! pool_error("SimpleQuery: create_portal() failed");
! return POOL_END;
! }
! /* switch memory context */
! old_context = pool_memory;
! pool_memory = portal->prepare_ctxt;
!
! portal->portal_name = NULL;
! portal->stmt = copyObject(node);
! portal->sql_string = NULL;
! pending_prepared_portal = portal;
! }
! else if (IsA(node, DeallocateStmt))
! {
! pending_function = del_prepared_list;
! portal = create_portal();
! if (portal == NULL)
{
! pool_error("SimpleQuery: create_portal() failed");
! return POOL_END;
! }
! /* switch memory context */
! old_context = pool_memory;
! pool_memory = portal->prepare_ctxt;
! portal->portal_name = NULL;
! portal->stmt = copyObject(node);
! portal->sql_string = NULL;
! pending_prepared_portal = portal;
! }
! else if (IsA(node, DiscardStmt))
! {
! DiscardStmt *stmt = (DiscardStmt *)node;
! if (stmt->target == DISCARD_ALL || stmt->target == DISCARD_PLANS)
{
! pending_function = delete_all_prepared_list;
! pending_prepared_portal = NULL;
}
}
+
+ /* switch old memory context */
+ if (old_context)
+ pool_memory = old_context;
+
+ /* end of wrong if (see 2009/4/3 comment above) */
}
if (frontend && IsA(node, ExecuteStmt))
More information about the Pgpool-general
mailing list