[Pgpool-general] General pgpool locking issues
Tatsuo Ishii
ishii at sraoss.co.jp
Fri Aug 11 01:13:27 UTC 2006
> Here is another syslog excerpt with postgres debugging messages. This one is newer but without the pgpool messages, maybe that will help also.
Hum. I see a query was canceled by a user at 2006-08-01 13:58:55 . Is
this an intended operation? It seems a kind mismatch error happend
wight after the canceling operation.
> postgres[3188]: [6073-1] <SmartMaz172.25.242.201(51558)2006-08-01 13:58:55 CEST>ERROR: 57014: canceling query due to user request
> postgres[3188]: [6073-2] <SmartMaz172.25.242.201(51558)2006-08-01 13:58:55 CEST>LOCATION: ProcessInterrupts, postgres.c:2107
>
> pgpool: 2006-08-01 13:58:57 ERROR: pid 32617: pool_process_query: kind does not match between backends master(E) secondary(D)
> I also issued the select statement straigth to the db. It took about 65 sec.
After 65 sec do you see errors on either master or secondary?
> Could it be a timing problem?
I don't think so.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
> Log:
>
> postgres[32739]: [15945-1] <SmartMaz172.25.242.201(44975)2006-08-01 13:42:48 CEST>WARNING: 25P01: there is no transaction in progress
> postgres[32739]: [15945-2] <SmartMaz172.25.242.201(44975)2006-08-01 13:42:48 CEST>LOCATION: UserAbortTransactionBlock, xact.c:2656
> postgres[15513]: [2-1] <template1172.25.242.201(53944)2006-08-01 13:44:21 CEST>LOG: 08006: could not receive data from client: Connection
> reset by
> postgres[15513]: [2-2] peer
> postgres[15513]: [2-3] <template1172.25.242.201(53944)2006-08-01 13:44:21 CEST>LOCATION: pq_recvbuf, pqcomm.c:704
> postgres[15513]: [3-1] <template1172.25.242.201(53944)2006-08-01 13:44:21 CEST>LOG: 08P01: unexpected EOF within message length word
> postgres[15513]: [3-2] <template1172.25.242.201(53944)2006-08-01 13:44:21 CEST>LOCATION: pq_getmessage, pqcomm.c:897
>
> pgpool: 2006-08-01 13:44:21 LOG: pid 32616: starting health checking
>
> postgres[32739]: [15946-1] <SmartMaz172.25.242.201(44975)2006-08-01 13:47:49 CEST>WARNING: 25P01: there is no transaction in progress
> postgres[32739]: [15946-2] <SmartMaz172.25.242.201(44975)2006-08-01 13:47:49 CEST>LOCATION: UserAbortTransactionBlock, xact.c:2656
> postgres[9085]: [2566-1] <SmartMaz172.25.242.201(42513)2006-08-01 13:49:37 CEST>WARNING: 25P01: there is no transaction in progress
> postgres[9085]: [2566-2] <SmartMaz172.25.242.201(42513)2006-08-01 13:49:37 CEST>LOCATION: UserAbortTransactionBlock, xact.c:2656
> cron[15516]: (root) CMD (test -x /usr/sbin/run-crons && /usr/sbin/run-crons )
> postgres[15527]: [2-1] <template1172.25.242.201(34289)2006-08-01 13:54:21 CEST>LOG: 08006: could not receive data from client: Connection
> reset by
> postgres[15527]: [2-2] peer
> postgres[15527]: [2-3] <template1172.25.242.201(34289)2006-08-01 13:54:21 CEST>LOCATION: pq_recvbuf, pqcomm.c:704
> postgres[15527]: [3-1] <template1172.25.242.201(34289)2006-08-01 13:54:21 CEST>LOG: 08P01: unexpected EOF within message length word
> postgres[15527]: [3-2] <template1172.25.242.201(34289)2006-08-01 13:54:21 CEST>LOCATION: pq_getmessage, pqcomm.c:897
> pgpool: 2006-08-01 13:54:21 LOG: pid 32616: starting health checking
> postgres[3188]: [6073-1] <SmartMaz172.25.242.201(51558)2006-08-01 13:58:55 CEST>ERROR: 57014: canceling query due to user request
> postgres[3188]: [6073-2] <SmartMaz172.25.242.201(51558)2006-08-01 13:58:55 CEST>LOCATION: ProcessInterrupts, postgres.c:2107
>
> pgpool: 2006-08-01 13:58:57 ERROR: pid 32617: pool_process_query: kind does not match between backends master(E) secondary(D)
>
> postgres[15533]: [2-1] <template1172.25.242.201(45742)2006-08-01 13:58:58 CEST>LOG: 08006: could not receive data from client: Connection
> reset by
> postgres[15533]: [2-2] peer
> postgres[15533]: [2-3] <template1172.25.242.201(45742)2006-08-01 13:58:58 CEST>LOCATION: pq_recvbuf, pqcomm.c:704
> postgres[15533]: [3-1] <template1172.25.242.201(45742)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF within message length word
> postgres[15533]: [3-2] <template1172.25.242.201(45742)2006-08-01 13:58:58 CEST>LOCATION: pq_getmessage, pqcomm.c:897
> postgres[3188]: [6074-1] <SmartMaz172.25.242.201(51558)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[3198]: [2-1] <SmartMaz172.25.242.201(34436)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[3201]: [6-1] <SmartMaz172.25.242.201(34439)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[3188]: [6074-2] <SmartMaz172.25.242.201(51558)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[3198]: [2-2] <SmartMaz172.25.242.201(34436)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[3201]: [6-2] <SmartMaz172.25.242.201(34439)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[8967]: [2-1] <SmartMaz172.25.242.201(55747)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[8990]: [2-1] <SmartMaz172.25.242.201(35210)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[9085]: [2567-1] <SmartMaz172.25.242.201(42513)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[24418]: [2-1] <SmartMaz172.25.242.201(53612)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[24420]: [7-1] <SmartMaz172.25.242.201(47167)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[2381]: [2-1] <SmartMaz172.25.242.201(59978)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[2782]: [6114-1] <SmartMaz172.25.242.201(48147)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[26907]: [2-1] <SmartMaz172.25.242.201(56750)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[1202]: [4-1] <SmartMaz172.25.242.201(37539)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[3187]: [10916-1] <SmartMaz172.25.242.201(51556)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[8757]: [2-1] <SmartMaz172.25.242.201(36997)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[548]: [2-1] <SmartMaz172.25.242.201(54573)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[625]: [1177-1] <SmartMaz172.25.242.201(52386)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[717]: [2-1] <SmartMaz172.25.242.201(49552)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[32739]: [15947-1] <SmartMaz172.25.242.201(44975)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[391]: [3-1] <SmartMaz172.25.242.201(37160)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[2961]: [2-1] <SmartMaz172.25.242.201(44498)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[32650]: [2-1] <SmartMaz172.25.242.201(44107)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[32738]: [3271-1] <SmartMaz172.25.242.201(44973)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[350]: [2-1] <SmartMaz172.25.242.201(40728)2006-08-01 13:58:58 CEST>LOG: 08P01: unexpected EOF on client connection
> postgres[8967]: [2-2] <SmartMaz172.25.242.201(55747)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[8990]: [2-2] <SmartMaz172.25.242.201(35210)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[9085]: [2567-2] <SmartMaz172.25.242.201(42513)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[24418]: [2-2] <SmartMaz172.25.242.201(53612)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[24420]: [7-2] <SmartMaz172.25.242.201(47167)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[2381]: [2-2] <SmartMaz172.25.242.201(59978)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[2782]: [6114-2] <SmartMaz172.25.242.201(48147)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[26907]: [2-2] <SmartMaz172.25.242.201(56750)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[1202]: [4-2] <SmartMaz172.25.242.201(37539)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[3187]: [10916-2] <SmartMaz172.25.242.201(51556)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[8757]: [2-2] <SmartMaz172.25.242.201(36997)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[548]: [2-2] <SmartMaz172.25.242.201(54573)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[625]: [1177-2] <SmartMaz172.25.242.201(52386)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[717]: [2-2] <SmartMaz172.25.242.201(49552)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[32739]: [15947-2] <SmartMaz172.25.242.201(44975)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[391]: [3-2] <SmartMaz172.25.242.201(37160)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[2961]: [2-2] <SmartMaz172.25.242.201(44498)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[32650]: [2-2] <SmartMaz172.25.242.201(44107)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[32738]: [3271-2] <SmartMaz172.25.242.201(44973)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
> postgres[350]: [2-2] <SmartMaz172.25.242.201(40728)2006-08-01 13:58:58 CEST>LOCATION: SocketBackend, postgres.c:294
>
> pgpool: 2006-08-01 13:58:58 LOG: pid 32617: notice_backend_error: master: 1 fail over request from pid 32617
> pgpool: 2006-08-01 13:58:58 LOG: pid 32616: starting degeneration. shutdown master host clever(5432)
> pgpool: 2006-08-01 13:58:58 LOG: pid 32616: degeneration done. shutdown master host clever(5432)
>
> > > Here is the select version() result:
> > >
> > version
> > >
> > ----------------------------------------------------------------------
> > > -------------------------------------------------------------
> > > PostgreSQL 8.0.4 on i386-pc-linux-gnu, compiled by GCC
> > > i386-pc-linux-gnu-gcc (GCC) 3.4.5 (Gentoo 3.4.5, ssp-3.4.5-1.0,
> > > pie-8.7.9)
> > > (1 row)
> > >
> > > Where in the log did you see that it shoulb be a version
> > older than 7.4?
> >
> > If you show the log when client connects to pgpool it will be
> > cleaner, but just seeing:
> >
> > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899: RowDescription:
> > modifier:
> > 0
> > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > pool_read_string: read all from pending data. po:58 len:965
> >
> > is enough since these debugging messages only appear with pre 7.4.
> >
> > Another possibility is you are using pre 7.4 clients. If you
> > are using psql, type psql --help to see its version. What
> > kind of clients are you using?
> > --
> > Tatsuo Ishii
> > SRA OSS, Inc. Japan
> >
> > > Axel Weber
> > >
> > > > -----Ursprüngliche Nachricht-----
> > > > Von: Tatsuo Ishii [mailto:ishii at sraoss.co.jp]
> > > > Gesendet: Montag, 7. August 2006 14:53
> > > > An: Weber, Axel
> > > > Cc: pgpool-general at pgfoundry.org
> > > > Betreff: Re: AW: [Pgpool-general] General pgpool locking issues
> > > >
> > > > > Thank you for you quick response.
> > > > > I use this environment:
> > > > > Gentoo server
> > > > > [I--] [ ] dev-db/postgresql-8.0.4 (0) [I--] [ ]
> > > > dev-db/pgpool-3.0.1
> > > > > (0)
> > > >
> > > > You'd better to check what version of PostgreSQL you are actually
> > > > using(try "select version();" via pgpool). The pgpool log cleary
> > > > says you are using pre 7.3 version.
> > > > --
> > > > Tatsuo Ishii
> > > > SRA OSS, Inc. Japan
> > > >
> > > > > Sorry for missing the whole log statement, here it is:
> > > > > pgpool: 2006-07-11 11:00:57 ERROR: pid 13899:
> > > > pool_process_query: kind
> > > > > does not match between backends master(E) secondary (D)
> > > > >
> > > > >
> > > > > I will issue the select statement to the db itself as a
> > next step.
> > > > >
> > > > > Axel Weber
> > > > >
> > > > > > You seem to use totally different envrionment this time.
> > > > Last time
> > > > > > you used at least 7.4 or later version of PostgreSQL.
> > > > > > Now you use 7.3 or older version of PostgreSQL. I'm not sure
> > > > > > what version of pgpool now you are using.
> > > > > >
> > > > > > Anyway, because your log seems imcomplete in the most
> > important
> > > > > > line,
> > > > > >
> > > > > > > pgpool: 2006-07-11 11:00:57 ERROR: pid 13899:
> > > > > > pool_process_query: kind
> > > > > > > does not match between backends master(E) secondar
> > > > > >
> > > > > > this is just a guess: it seems your SELECT fails on
> > > > master (the log
> > > > > > says master returns "E", which is an error message
> > packet from
> > > > > > PostgreSQL). I don't know what secondary returned since
> > > > the log ends
> > > > > > in a halfway, but it definitely returns other than error
> > > > packet. You
> > > > > > can issue the select statement to each PostgreSQL directly to
> > > > > > see what happens.
> > > > > > SELECT
> > > > > > maz_media.id,maz_media.kassetten_id,maz_media.beschreibu
> > > > > > ng,maz_media.title,maz_media.mandanten_id,maz_segment.timeanfa
> > > > > > ng,maz_med
> > > > > >
> > > >
> > ia.media_id,maz_media.entrytime,maz_media.entryoper,maz_media.dupop
> > > > > > er,maz_segment.timelaenge,maz_segment.timeende from
> > maz_media,
> > > > > > maz_segment where maz_media.id LIKE '%7%' and
> > > > > > maz_media.mandanten_id='1'
> > > > > > and
> > > > > > maz_media.media_id = maz_segment.media_id
> > > > > > --
> > > > > > Tatsuo Ishii
> > > > > > SRA OSS, Inc. Japan
> > > > > >
> > > > > > > Hi,
> > > > > > >
> > > > > > > I got exactly the same behaviour, as I posted
> > several weeks ago.
> > > > > > > One strange thing about this all is, that the degeneration
> > > > > > happens on
> > > > > > > a regular schedule every 2 1/2 week.
> > > > > > >
> > > > > > > Here you'll find my log and also the pgpool status result,
> > > > > > I hope this
> > > > > > > helps to analyse this.
> > > > > > > I would like to emphasize that this particular select
> > > > > > statement lasts
> > > > > > > about 30 sec.
> > > > > > >
> > > > > > > If you need further information, please don't hesitate to
> > > > > > get in touch
> > > > > > > with me.
> > > > > > >
> > > > > > > Log:
> > > > > > >
> > > > > > > pgpool: 2006-07-11 11:00:24 DEBUG: pid 13899: read kind
> > > > > > from frontend
> > > > > > > Q(51)
> > > > > > > pgpool: 2006-07-11 11:00:24 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:0 len:0
> > > > > > > pgpool: 2006-07-11 11:00:24 DEBUG: pid 13899: Query: SELECT
> > > > > > > maz_media.id,maz_media.kassetten_id,maz_media.beschreibu
> > > > > > >
> > > > > >
> > > >
> > ng,maz_media.title,maz_media.mandanten_id,maz_segment.timeanfang,maz
> > > > > > _m
> > > > > > > ed
> > > > > >
> > > >
> > ia.media_id,maz_media.entrytime,maz_media.entryoper,maz_media.dupop
> > > > > > > er,maz_segment.timelaenge,maz_segment.timeende from
> > maz_media,
> > > > > > > maz_segment where maz_media.id LIKE '%7%' and
> > > > > > maz_media.mandanten_id='1'
> > > > > > > and
> > > > > > > maz_media.media_id = maz_segment.media_id
> > > > > > > pgpool: 2006-07-11 11:00:24 DEBUG: pid 13899: waiting
> > > > for master
> > > > > > > completing the query
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899: read kind
> > > > > > from backend P
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > pool_process_query:
> > > > > > > waiting for secondary for data ready
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_process_query: kind
> > > > > > > from backend: P
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:6 len:1017
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:6 len:1017
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899: read kind
> > > > > > from backend
> > > > > > > pending data T len: 1016 po: 7
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_process_query: kind
> > > > > > > from backend: T
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:12 len:1011
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:12 len:1011
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > RowDescription: type oid:
> > > > > > > 1043
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > RowDescription:
> > > > > > > field
> > > > > > > size: 65535
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > RowDescription: modifier:
> > > > > > > 0
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:35 len:988
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:35 len:988
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > RowDescription: type oid:
> > > > > > > 1043
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > RowDescription:
> > > > > > > field
> > > > > > > size: 65535
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > RowDescription: modifier:
> > > > > > > 0
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:58 len:965
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:58 len:965
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > RowDescription: type oid:
> > > > > > > 1043
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > RowDescription:
> > > > > > > field
> > > > > > > size: 65535
> > > > > > > pgpool: 2006-07-11 11:00:28 DEBUG: pid 13899:
> > > > > > RowDescription: modifier:
> > > > > > > 0
> > > > > > > .
> > > > > > > . (~ 30 sec. for select)
> > > > > > > .
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: read kind
> > > > > > from backend
> > > > > > > pending data D len: 174 po: 476
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899:
> > > > > > pool_process_query: kind
> > > > > > > from backend: D
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > len: 6 data:
> > > > > > > 211678
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > len: 5 data:
> > > > > > > S0671
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > > > len: 23 data:
> > > > > > > T-D1 EINPACKEN MOTIV 67
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > len: 4 data:
> > > > > > > T-D1
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > > > len: 1 data: 1
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > len: 5 data:
> > > > > > > 19955
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > len: 5 data:
> > > > > > > 17136
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > > > len: 22 data:
> > > > > > > 2000-10-26 13:02:00+00
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > > > len: 2 data:
> > > > > > > RC
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > > > len: 3 data:
> > > > > > > 504
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13899: AsciiRow:
> > > > len: 5 data:
> > > > > > > 20459
> > > > > > > pgpool: 2006-07-11 11:00:57 ERROR: pid 13899:
> > > > > > pool_process_query: kind
> > > > > > > does not match between backends master(E) secondar
> > > > > > > pgpool: 2006-07-11 11:00:57 LOG: pid 13899:
> > > > notice_backend_error:
> > > > > > > master: 1 fail over request from pid 13899
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891:
> > > > > > failover_handler called
> > > > > > > pgpool: 2006-07-11 11:00:57 LOG: pid 13891: starting
> > > > degeneration.
> > > > > > > shutdown master host clever(5432)
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13896
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13897
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13898
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13899
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13900
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13901
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13902
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891: kill 13903
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13896: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13897: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13898: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13900: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13901: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13902: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13903: child
> > > > > > receives shutdown
> > > > > > > request signal 3
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31938: I am 31938
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31939: I am 31939
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31940: I am 31940
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31941: I am 31941
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31942: I am 31942
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31943: I am 31943
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31944: I am 31944
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 31945: I am 31945
> > > > > > > pgpool: 2006-07-11 11:00:57 LOG: pid 13891:
> > degeneration done.
> > > > > > > shutdown master host clever(5432)
> > > > > > > pgpool: 2006-07-11 11:00:57 DEBUG: pid 13891:
> > > > reap_handler called
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: I am
> > > > 31945 accept fd
> > > > > > > 6
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: Protocol
> > > > > > Major: 2 Minor:
> > > > > > > 0
> > > > > > > database: SmartMaz user: abit
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: trying clear
> > > > > > > text password authentication
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: read kind
> > > > > > from backend
> > > > > > > pending data Z len: 0 po: 0
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945:
> > > > > > pool_process_query: kind
> > > > > > > from backend: Z
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: read kind
> > > > > > from frontend
> > > > > > > Q(51)
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:0 len:0
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: Query:
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: read kind
> > > > > > from backend I
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945:
> > > > > > pool_process_query: kind
> > > > > > > from backend: I
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: read kind
> > > > > > from backend
> > > > > > > pending data Z len: 0 po: 0
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945:
> > > > > > pool_process_query: kind
> > > > > > > from backend: Z
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: read kind
> > > > > > from frontend
> > > > > > > Q(51)
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945:
> > > > > > pool_read_string: read
> > > > > > > all from pending data. po:0 len:0
> > > > > > > pgpool: 2006-07-11 11:03:53 DEBUG: pid 31945: Query: select
> > > > > > version()
> > > > > > >
> > > > > > >
> > > > > > > Pgpool status:
> > > > > > >
> > > > > > > listen_addresses | *
> > > > > > > | host name(s) or IP address(es) to listen to
> > > > > > > port | 9999
> > > > > > > | pgpool accepting port number
> > > > > > > socket_dir | /tmp
> > > > > > > | pgpool socket directory
> > > > > > > backend_host_name | clever
> > > > > > > | master backend host name
> > > > > > > backend_port | 5432
> > > > > > > | master backend port number
> > > > > > > secondary_backend_host_name | smart
> > > > > > > | secondary backend host name
> > > > > > > secondary_backend_port | 5432
> > > > > > > | secondary backend port number
> > > > > > > num_init_children | 8
> > > > > > > | # of children initially pre-forked
> > > > > > > child_life_time | 0
> > > > > > > | if idle for this seconds, child exits
> > > > > > > connection_life_time | 0
> > > > > > > | if idle for this seconds, connection closes
> > > > > > > child_max_connections | 0
> > > > > > > | if max_connections received, chile exits
> > > > > > > max_pool | 4
> > > > > > > | max # of connection pool per child
> > > > > > > logdir | /var/run
> > > > > > > | logging directory
> > > > > > > backend_socket_dir | /tmp
> > > > > > > | Unix domain socket directory for the PostgreSQL server
> > > > > > > replication_mode | 1
> > > > > > > | non 0 if operating in replication mode
> > > > > > > replication_strict | 1
> > > > > > > | non 0 if operating in strict mode
> > > > > > > replication_timeout | 5000
> > > > > > > | if secondary does not respond in this milli seconds,
> > > > abort the
> > > > > > > | session
> > > > > > > load_balance_mode | 0
> > > > > > > | non 0 if operating in load balancing mode
> > > > > > > weight_master | 0.500000
> > > > > > > | weight of master
> > > > > > > weight_secondary | 0.500000
> > > > > > > | weight of secondary
> > > > > > > replication_stop_on_mismatch | 1
> > > > > > > | stop replication mode on fatal error
> > > > > > > reset_query_list | ABORT; RESET ALL;
> > SET SESSION
> > > > > > > AUTHORIZATION DEFAULT; | queries issued at the end
> > of session
> > > > > > > print_timestamp | 1
> > > > > > > | if true print time stamp to each log line
> > > > > > > master_slave_mode | 0
> > > > > > > | if true, operate in master/slave mode
> > > > > > > connection_cache | 1
> > > > > > > | if true, cache connection pool
> > > > > > > health_check_timeout | 60
> > > > > > > | health check timeout
> > > > > > > health_check_period | 600
> > > > > > > | health check period
> > > > > > > health_check_user | postgres
> > > > > > > | health check user
> > > > > > > insert_lock | 0
> > > > > > > | insert lock
> > > > > > > ignore_leading_white_space | 0
> > > > > > > | ignore leading white spaces
> > > > > > > current_backend_host_name | clever
> > > > > > > | current master host name
> > > > > > > current_backend_port | 5432
> > > > > > > | current master port #
> > > > > > > replication_enabled | 1
> > > > > > > | non 0 if actually operating in replication mode
> > > > > > > master_slave_enabled | 0
> > > > > > > | non 0 if actually operating in master/slave
> > > > > > > num_reset_queries | 3
> > > > > > > | number of queries in reset_query_list
> > > > > > > server_status | master(clever on 5432) up
> > > > > > > secondary(smart on 5432) up | server status
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > > > Thank you very much for the reply. Its helpful.
> > > > > > >
> > > > > > > You are welcome.
> > > > > > >
> > > > > > > > We have now turned on load_balancing and have set the
> > > > weight to
> > > > > > > > 1 and 0 (for db0 and db1). And we still are getting "kind
> > > > > > mismatches".
> > > > > > > >
> > > > > > > > Is this weight distribution of 1/0 valid? Or does 1/0
> > > > > > overwrite the
> > > > > > > load
> > > > > > > > balancing parameter. Is this not a recommended setting?
> > > > > > >
> > > > > > > Let me look into this.
> > > > > > >
> > > > > > > > We do direct SELECT connects to db1 via port
> > 5432, thus we
> > > > > > > > wanted pgpool to just select from db0 vs do a 50/50
> > > > load balancing.
> > > > > > > >
> > > > > > > > If the 1/0 setting is wrong let us know and we will
> > > > > > change it so we
> > > > > > > > will do something like 9/1 type load balancing. If the
> > > > > > 1/0 weight
> > > > > > > > setting is valid why would we still be seeing "kind
> > > > mismatches"
> > > > > > > > on
> > > > > > > selects?
> > > > > > > >
> > > > > > > > Thanks in advance for any suggestions/input here.
> > > > > > >
> > > > > > > Can you please provide debugging out put of pgpool by
> > > > > > turing on -d and
> > > > > > > -n option? We need info for when "kind mismatches"
> > > > erros occures
> > > > > > > in your setting.
> > > > > > > --
> > > > > > > Tatsuo Ishii
> > > > > > > SRA OSS, Inc. Japan
> > > > > > >
> > > > > > > > Thanks,
> > > > > > > > John
> > > > > > > >
> > > > > > > >
> > > > > > > >
> > > > > > > > On 7/30/06, Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> > > > > > > > >
> > > > > > > > > > We have been testing with pgpool for a little
> > > > while here and
> > > > > > > > > > have run
> > > > > > > > > into
> > > > > > > > > > various locking (or lack there of) issues.
> > > > > > > > > >
> > > > > > > > > > Our setup is 2 databases (pg v8.1.4) on seperate
> > > > > > machines with
> > > > > > > > > > all
> > > > > > >
> > > > > > > > > > db connections connected via pgpool. We have
> > run into
> > > > > > > > > > situations where we
> > > > > > > > > the
> > > > > > > > > > 1st or 2nd database was not getting the
> > update or insert
> > > > > > > > > > fast enough,
> > > > > > > > > and a
> > > > > > > > > > select query hitting pgpool at the same time
> > causing the
> > > > > > > > > > a
> > > > > > > "mismatch"
> > > > > > > > > error
> > > > > > > > > > causing pgpool to degrade and stop replicating.
> > > > > > > > > >
> > > > > > > > > > Although I assume this must be quite a normal
> > issue, I
> > > > > > > > > > do not see many people talking about it here.
> > > > > > > > > >
> > > > > > > > > > Can someone give me a basic rundown of the "best
> > > > > > practices" for
> > > > > > > > > > pg
> > > > > > > > > locking
> > > > > > > > > > on a pretty database intensive web app?
> > > > > > > > > >
> > > > > > > > > > On Inserts the best practice is to lock the entire
> > > > > > table (LOCK
> > > > > > > > > > TABLE
> > > > > > > > > ...) ?
> > > > > > > > > >
> > > > > > > > > > On Updates the best practice is to do a row lock
> > > > > > (SELECT ... FOR
> > > > > > > > > UPDATE or
> > > > > > > > > > FOR SHARE) ?
> > > > > > > > > > Should you do some sort of lock on SELECTS?
> > > > > > > > > > Do you recommend everything be wrapped in
> > Transactions?
> > > > > > > > > >
> > > > > > > > > > Any advice is appreciated.
> > > > > > > > > >
> > > > > > > > > > Thank you.
> > > > > > > > >
> > > > > > > > > What you have seen is a table updating timing
> > > > > > difference between
> > > > > > > > > master and secondary as yo suspected. Although there's
> > > > > > no way to
> > > > > > > > > avoid the timing difference itself, I think there are
> > > > > > some ways to
> > > > > > > > > avoid this problem.
> > > > > > > > >
> > > > > > > > > 1) use load balancing. Since this will SELECT one of
> > > > > > the servers,
> > > > > > > > > there will be no chance to see the "kind
> > mismatch error".
> > > > > > > > >
> > > > > > > > > 2) use table locking. This will prevent the SELECT from
> > > > > > seeing yet
> > > > > > > > > updated data in the secondary server.
> > > > > > > > >
> > > > > > > > > I don't think SELECT FOR UPDATE will work, since the
> > > > > > lock does not
> > > > > > > > > block SELECT.
> > > > > > > > > --
> > > > > > > > > Tatsuo Ishii
> > > > > > > > > SRA OSS, Inc. Japan
> > > > > > > > >
> > > > > > >
> > > > > > > _______________________________________________
> > > > > > > Pgpool-general mailing list
> > > > > > > Pgpool-general at pgfoundry.org
> > > > > > > http://pgfoundry.org/mailman/listinfo/pgpool-general
More information about the Pgpool-general
mailing list