[Pgpool-general] Error in pgpool

Glyn Astill glynastill at yahoo.co.uk
Fri Mar 27 16:21:50 UTC 2009 

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 <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

More information about the Pgpool-general mailing list