[Pgpool-general] Error in pgpool

Thu Mar 26 17:01:51 UTC 2009

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