Re: [Pgpool-general] Error in pgpool
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 glynast...@yahoo.co.uk wrote: From: Glyn Astill glynast...@yahoo.co.uk Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com, Tatsuo Ishii is...@sraoss.co.jp Cc: pgpool-general@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 is...@sraoss.co.jp wrote: From: Tatsuo Ishii is...@sraoss.co.jp Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com Cc: pgpool-general@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= 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
Re: [Pgpool-general] Error in pgpool
Hi Tatsuo,
Great, I assumed some sort of internal table of prepared statements wasn't
getting cleared out. When you said it was expected behavior it confused me.
I'm trying to patch against the pgpool-II-2.2 source, either I'm either too
much of a cretin to apply it or pool_proto_modules.c has other changes?
xnagios:/usr/pgsql_src/pgpool-II-2.2# patch -p0 --verbose DeAl22.patch
Hmm... Looks like a new-style context diff to me...
The text leading up to this was:
--
|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.c22 Jan 2009 09:16:37 -1.6
|--- pool_proto_modules.c3 Apr 2009 10:35:48 -
--
Patching file pool_proto_modules.c using Plan A...
Hunk #1 FAILED at 141.
Hunk #2 FAILED at 346.
2 out of 2 hunks FAILED -- saving rejects to file pool_proto_modules.c.rej
done
I was just going to edit it by hand but then I couldn't see what was going off
in the patch. The best I could figure was that this if statement wrapping if
(IsA(node, PrepareStmt)) was getting removed
if (frontend)
{
///
}
And the following is now getting declared a bit further up at line 141
POOL_MEMORY_POOL *old_context = NULL;
Portal *portal;
Is that correct?
Thanks
Glyn
--- On Fri, 3/4/09, Tatsuo Ishii is...@sraoss.co.jp wrote:
From: Tatsuo Ishii is...@sraoss.co.jp
Subject: Re: [Pgpool-general] Error in pgpool
To: glynast...@yahoo.co.uk, nimesh.sa...@gmail.com,
pgpool-general@pgfoundry.org
Date: Friday, 3 April, 2009, 11:39 AM
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
___
Pgpool-general mailing list
Pgpool-general@pgfoundry.org
http://pgfoundry.org/mailman/listinfo/pgpool-general
Re: [Pgpool-general] Error in pgpool
Great, I assumed some sort of internal table of prepared statements wasn't
getting cleared out. When you said it was expected behavior it confused me.
Sorry, I was wrong.
I'm trying to patch against the pgpool-II-2.2 source, either I'm either too
much of a cretin to apply it or pool_proto_modules.c has other changes?
The patch was against CVS HEAD. Could you try included new patch? It
was generated using diff -u (previous one was diff -c) and seems to be
nicely applied to 2.2-stable.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
xnagios:/usr/pgsql_src/pgpool-II-2.2# patch -p0 --verbose DeAl22.patch
Hmm... Looks like a new-style context diff to me...
The text leading up to this was:
--
|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.c22 Jan 2009 09:16:37 -1.6
|--- pool_proto_modules.c3 Apr 2009 10:35:48 -
--
Patching file pool_proto_modules.c using Plan A...
Hunk #1 FAILED at 141.
Hunk #2 FAILED at 346.
2 out of 2 hunks FAILED -- saving rejects to file pool_proto_modules.c.rej
done
I was just going to edit it by hand but then I couldn't see what was going
off in the patch. The best I could figure was that this if statement
wrapping if (IsA(node, PrepareStmt)) was getting removed
if (frontend)
{
///
}
And the following is now getting declared a bit further up at line 141
POOL_MEMORY_POOL *old_context = NULL;
Portal *portal;
Is that correct?
Thanks
Glyn
--- On Fri, 3/4/09, Tatsuo Ishii is...@sraoss.co.jp wrote:
From: Tatsuo Ishii is...@sraoss.co.jp
Subject: Re: [Pgpool-general] Error in pgpool
To: glynast...@yahoo.co.uk, nimesh.sa...@gmail.com,
pgpool-general@pgfoundry.org
Date: Friday, 3 April, 2009, 11:39 AM
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
Index: pool_proto_modules.c
===
RCS file: /cvsroot/pgpool/pgpool-II/pool_proto_modules.c,v
retrieving revision 1.6
diff -u -r1.6 pool_proto_modules.c
--- pool_proto_modules.c22 Jan 2009 09:16:37 - 1.6
+++ pool_proto_modules.c3 Apr 2009 13:13:58 -
@@ -141,6 +141,9 @@
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,63 +346,66 @@
if (MASTER_SLAVE TSTATE(backend) != 'E')
force_replication = 1;
- if (frontend)
+ /*
+* 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))
{
- POOL_MEMORY_POOL *old_context = NULL;
- Portal *portal
Re: [Pgpool-general] Error in pgpool
--- On Fri, 3/4/09, Tatsuo Ishii is...@sraoss.co.jp wrote: I'm trying to patch against the pgpool-II-2.2 source, either I'm either too much of a cretin to apply it or pool_proto_modules.c has other changes? The patch was against CVS HEAD. Could you try included new patch? It was generated using diff -u (previous one was diff -c) and seems to be nicely applied to 2.2-stable. Hmm, I still get the same when I try to patch with that. ___ Pgpool-general mailing list Pgpool-general@pgfoundry.org http://pgfoundry.org/mailman/listinfo/pgpool-general
Re: [Pgpool-general] Error in pgpool
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 glynast...@yahoo.co.uk wrote: From: Glyn Astill glynast...@yahoo.co.uk Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com, Tatsuo Ishii is...@sraoss.co.jp Cc: pgpool-general@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 is...@sraoss.co.jp wrote: From: Tatsuo Ishii is...@sraoss.co.jp Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com Cc: pgpool-general@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= 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= 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
Re: [Pgpool-general] Error in pgpool
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. 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? 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' ? --- On Thu, 26/3/09, Glyn Astill glynast...@yahoo.co.uk wrote: From: Glyn Astill glynast...@yahoo.co.uk Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com, Tatsuo Ishii is...@sraoss.co.jp Cc: pgpool-general@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 is...@sraoss.co.jp wrote: From: Tatsuo Ishii is...@sraoss.co.jp Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com Cc: pgpool-general@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= 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= 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
Re: [Pgpool-general] Error in pgpool
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 is...@sraoss.co.jp wrote: From: Tatsuo Ishii is...@sraoss.co.jp Subject: Re: [Pgpool-general] Error in pgpool To: nimesh.sa...@gmail.com Cc: pgpool-general@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= 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= 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
Re: [Pgpool-general] Error in pgpool
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= 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= 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 is...@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
Re: [Pgpool-general] Error in pgpool
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= 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= 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 is...@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
Re: [Pgpool-general] Error in pgpool
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@pgfoundry.org http://pgfoundry.org/mailman/listinfo/pgpool-general
