[pgpool-hackers: 2142] Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created

Sergey Kim skim at odin.com
Wed Mar 15 02:48:46 JST 2017 

Tatsuo,

I have updated the test tool:


There is the 'target' folder in the attached tarball (and source codes). The folder contains jar file that implements tests for #231 & #271  issues.

please run it as:
# java -jar target/tests-1.0-SNAPSHOT-jar-with-dependencies.jar PGPOOL_HOST PGPOOL_PORT DB_NAME DB_USER DB_PASSWORD 271

'271' here means the ID of the test to run, currently there are 2 IDs possible - 231 & 271. Each test launched for 1000 times. This is the code level constant so far.

For example launch for the test 271 on the HEAD of bug271 git branch ends with error:
[skim at localhost pgpool]$ java -jar target/tests-1.0-SNAPSHOT-jar-with-dependencies.jar 10.28.64.176 5432 oss oss WfovD22ufP78Wq 271
Test iteration '0'
Test iteration '1'
Exception in thread "main" java.lang.RuntimeException: Balanced
at com.pgpool.tests.Issue271_SingleThread.runTest(Issue271_SingleThread.java:52)
at com.pgpool.tests.TestStarter.main(TestStarter.java:44)
[skim at localhost pgpool]$ echo $?
1

And the following pgpool log is generated (syslog):

2017-03-14T20:44:09.859057+03:00 OAA-54999c4d7735 pgpool[1041]: [129385-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: Parse: BEGIN
2017-03-14T20:44:09.859206+03:00 OAA-54999c4d7735 pgpool[1041]: [129385-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.859385+03:00 OAA-54999c4d7735 pgpool[1041]: [129386-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: Parse: BEGIN
2017-03-14T20:44:09.859558+03:00 OAA-54999c4d7735 pgpool[1041]: [129386-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.859702+03:00 OAA-54999c4d7735 pgpool[1041]: [129387-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: B message
2017-03-14T20:44:09.859856+03:00 OAA-54999c4d7735 pgpool[1041]: [129387-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.860000+03:00 OAA-54999c4d7735 pgpool[1041]: [129388-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: B message
2017-03-14T20:44:09.860158+03:00 OAA-54999c4d7735 pgpool[1041]: [129388-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.860323+03:00 OAA-54999c4d7735 pgpool[1041]: [129389-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: Execute: BEGIN
2017-03-14T20:44:09.860557+03:00 OAA-54999c4d7735 pgpool[1041]: [129389-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.860778+03:00 OAA-54999c4d7735 pgpool[1041]: [129390-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: Execute: BEGIN
2017-03-14T20:44:09.860992+03:00 OAA-54999c4d7735 pgpool[1041]: [129390-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.861217+03:00 OAA-54999c4d7735 pgpool[1041]: [129391-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: Parse: insert into write_table(id) values($1)
2017-03-14T20:44:09.861423+03:00 OAA-54999c4d7735 pgpool[1041]: [129391-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.861686+03:00 OAA-54999c4d7735 pgpool[1041]: [129392-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: B message
2017-03-14T20:44:09.861904+03:00 OAA-54999c4d7735 pgpool[1041]: [129392-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.862148+03:00 OAA-54999c4d7735 pgpool[1041]: [129393-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: D message
2017-03-14T20:44:09.862360+03:00 OAA-54999c4d7735 pgpool[1041]: [129393-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.862592+03:00 OAA-54999c4d7735 pgpool[1041]: [129394-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: Execute: insert into write_table(id) values($1)
2017-03-14T20:44:09.862826+03:00 OAA-54999c4d7735 pgpool[1041]: [129394-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.863058+03:00 OAA-54999c4d7735 pgpool[1041]: [129395-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: B message
2017-03-14T20:44:09.863306+03:00 OAA-54999c4d7735 pgpool[1041]: [129395-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.863502+03:00 OAA-54999c4d7735 pgpool[1041]: [129396-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: Execute: select id from write_table where id = $1
2017-03-14T20:44:09.863665+03:00 OAA-54999c4d7735 pgpool[1041]: [129396-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.864601+03:00 OAA-54999c4d7735 pgpool[1041]: [129397-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: ABORT
2017-03-14T20:44:09.864761+03:00 OAA-54999c4d7735 pgpool[1041]: [129397-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.864914+03:00 OAA-54999c4d7735 pgpool[1041]: [129398-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: ABORT
2017-03-14T20:44:09.865097+03:00 OAA-54999c4d7735 pgpool[1041]: [129398-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.865322+03:00 OAA-54999c4d7735 pgpool[1041]: [129399-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 0 backend pid: 1513 statement: DISCARD ALL
2017-03-14T20:44:09.865606+03:00 OAA-54999c4d7735 pgpool[1041]: [129399-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.865844+03:00 OAA-54999c4d7735 pgpool[1041]: [129400-1] 2017-03-14 20:44:09: pid 1041:LOG:  DB node id: 1 backend pid: 28847 statement: DISCARD ALL
2017-03-14T20:44:09.866101+03:00 OAA-54999c4d7735 pgpool[1041]: [129400-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  pool_proto_modules.c:3208
2017-03-14T20:44:09.866976+03:00 OAA-54999c4d7735 pgpool[1041]: [129401-1] 2017-03-14 20:44:09: pid 1041:LOG:  child exiting, 1 connections reached
2017-03-14T20:44:09.867095+03:00 OAA-54999c4d7735 pgpool[1041]: [129401-2] 2017-03-14 20:44:09: pid 1041:LOCATION:  child.c:406


If you wish I can put the source codes into some git repository.


Sergey.
________________________________
From: Sergey Kim
Sent: Tuesday, March 14, 2017 4:19 PM
To: Tatsuo Ishii
Cc: pgpool-hackers at pgpool.net; Boris Voskanov
Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created


Tatsuo,


this time all previously created tests succeeded but out application failed to start. So we started searching for the problem and could reproduce "balanced select problem". The test can run for minutes before reproduction of the problem (((

I'm not sure if it can help but please pay attention that time lag between insert is select requests is very small.


Please see the pgpool logs:

2017-03-14T16:06:37.889485+03:00 OAA-54999c4d7735 pgpool[25595]: [79-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: B message
2017-03-14T16:06:37.889702+03:00 OAA-54999c4d7735 pgpool[25595]: [79-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.889924+03:00 OAA-54999c4d7735 pgpool[25595]: [80-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 1 backend pid: 27691 statement: B message
2017-03-14T16:06:37.890090+03:00 OAA-54999c4d7735 pgpool[25595]: [80-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.890248+03:00 OAA-54999c4d7735 pgpool[25595]: [81-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: Execute: BEGIN
2017-03-14T16:06:37.890378+03:00 OAA-54999c4d7735 pgpool[25595]: [81-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.890535+03:00 OAA-54999c4d7735 pgpool[25595]: [82-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 1 backend pid: 27691 statement: Execute: BEGIN
2017-03-14T16:06:37.890693+03:00 OAA-54999c4d7735 pgpool[25595]: [82-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.890863+03:00 OAA-54999c4d7735 pgpool[25595]: [83-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: Parse: insert into write_table(id) values($1)
2017-03-14T16:06:37.891144+03:00 OAA-54999c4d7735 pgpool[25595]: [83-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.891390+03:00 OAA-54999c4d7735 pgpool[25595]: [84-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: B message
2017-03-14T16:06:37.891637+03:00 OAA-54999c4d7735 pgpool[25595]: [84-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.891895+03:00 OAA-54999c4d7735 pgpool[25595]: [85-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: D message
2017-03-14T16:06:37.892091+03:00 OAA-54999c4d7735 pgpool[25595]: [85-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.892272+03:00 OAA-54999c4d7735 pgpool[25595]: [86-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: Execute: insert into write_table(id) values($1)
2017-03-14T16:06:37.892442+03:00 OAA-54999c4d7735 pgpool[25595]: [86-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.892642+03:00 OAA-54999c4d7735 pgpool[25595]: [87-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 1 backend pid: 27691 statement: B message
2017-03-14T16:06:37.892828+03:00 OAA-54999c4d7735 pgpool[25595]: [87-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.892998+03:00 OAA-54999c4d7735 pgpool[25595]: [88-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 1 backend pid: 27691 statement: Execute: select id from write_table where id = $1
2017-03-14T16:06:37.893187+03:00 OAA-54999c4d7735 pgpool[25595]: [88-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.893359+03:00 OAA-54999c4d7735 pgpool[25595]: [89-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 1 backend pid: 27691 statement: ABORT
2017-03-14T16:06:37.893584+03:00 OAA-54999c4d7735 pgpool[25595]: [89-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.893839+03:00 OAA-54999c4d7735 pgpool[25595]: [90-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: ABORT
2017-03-14T16:06:37.894039+03:00 OAA-54999c4d7735 pgpool[25595]: [90-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.894220+03:00 OAA-54999c4d7735 pgpool[25595]: [91-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 0 backend pid: 25885 statement: DISCARD ALL
2017-03-14T16:06:37.894403+03:00 OAA-54999c4d7735 pgpool[25595]: [91-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.894587+03:00 OAA-54999c4d7735 pgpool[25595]: [92-1] 2017-03-14 16:06:37: pid 25595:LOG:  DB node id: 1 backend pid: 27691 statement: DISCARD ALL
2017-03-14T16:06:37.894753+03:00 OAA-54999c4d7735 pgpool[25595]: [92-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  pool_proto_modules.c:3208
2017-03-14T16:06:37.894944+03:00 OAA-54999c4d7735 pgpool[25595]: [93-1] 2017-03-14 16:06:37: pid 25595:LOG:  child exiting, 1 connections reached
2017-03-14T16:06:37.895079+03:00 OAA-54999c4d7735 pgpool[25595]: [93-2] 2017-03-14 16:06:37: pid 25595:LOCATION:  child.c:406
2017-03-14T16:06:37.895371+03:00 OAA-54999c4d7735 pgpool[25566]: [47-1] 2017-03-14 16:06:37: pid 25566:LOG:  child process with pid: 25595 exits with status 256
2017-03-14T16:06:37.895635+03:00 OAA-54999c4d7735 pgpool[25566]: [47-2] 2017-03-14 16:06:37: pid 25566:LOCATION:  pgpool_main.c:2380
2017-03-14T16:06:37.895943+03:00 OAA-54999c4d7735 pgpool[25566]: [48-1] 2017-03-14 16:06:37: pid 25566:LOG:  fork a new child process with pid: 25887
2017-03-14T16:06:37.896174+03:00 OAA-54999c4d7735 pgpool[25566]: [48-2] 2017-03-14 16:06:37: pid 25566:LOCATION:  pgpool_main.c:2466



And java client logs:
16:06:37.890 (2) simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler at 689604d9, maxRows=0, fetchSize=0, flags=1
16:06:37.890 (2)  FE=> Parse(stmt=null,query="BEGIN",oids={})
16:06:37.890 (2)  FE=> Bind(stmt=null,portal=null)
16:06:37.890 (2)  FE=> Execute(portal=null,limit=0)
16:06:37.890 (2)  FE=> Parse(stmt=null,query="insert into write_table(id) values($1)",oids={23})
16:06:37.890 (2)  FE=> Bind(stmt=null,portal=null,$1=<-613120604>)
16:06:37.890 (2)  FE=> Describe(portal=null)
16:06:37.890 (2)  FE=> Execute(portal=null,limit=0)
16:06:37.890 (2)  FE=> Sync
16:06:37.892 (2)  <=BE ParseComplete [null]
16:06:37.892 (2)  <=BE BindComplete [unnamed]
16:06:37.892 (2)  <=BE CommandStatus(BEGIN)
16:06:37.892 (2)  <=BE ParseComplete [null]
16:06:37.892 (2)  <=BE BindComplete [unnamed]
16:06:37.892 (2)  <=BE NoData
16:06:37.892 (2)  <=BE CommandStatus(INSERT 0 1)
16:06:37.893 (2)  <=BE ReadyForQuery(T)
16:06:37.893 (2) simple execute, handler=org.postgresql.jdbc.PgStatement$StatementResultHandler at 18078bef, maxRows=0, fetchSize=0, flags=0
16:06:37.893 (2)  FE=> Bind(stmt=S_1,portal=null,$1=<-613120604>)
16:06:37.893 (2)  FE=> Execute(portal=null,limit=0)
16:06:37.893 (2)  FE=> Sync
16:06:37.895 (2)  <=BE BindComplete [unnamed]
16:06:37.895 (2)  <=BE CommandStatus(SELECT 0)
16:06:37.895 (2)  <=BE ReadyForQuery(T)
16:06:37.895 (2)  FE=> Terminate
Exception in thread "main" java.lang.RuntimeException: Balanced
at com.pgpool.tests.Issue271_SingleThread.runTest(Issue271_SingleThread.java:57)
at com.pgpool.tests.TestStarter.main(TestStarter.java:37)


The java test is attached:

P/S:
Pgpool was build from branch bug271:
[root at OAA-54999c4d7735 pgpool2]# git log -2
commit 0955a22fb7f30c5b9c1fabe2873c09246453ee50
Author: Tatsuo Ishii <ishii at postgresql.org>
Date:   Tue Mar 14 19:03:02 2017 +0900

    Fix problem described in [pgpool-hackers: 2125].

    Two problems are fixed:

    - The writing_transaction flag is not reset at transaction
      committed/aborted. Before it was done in CommandComplete but now it
      is possible that we need to check the flag before a command complete
      message arrives. So at Execute, it is taken care by
      handle_query_context() which used to be a static function in
      CommandComplete.c. Also the session context memory is always cleared
      before start a session context.

    - Ready for query Re-sync code path in read_kind_from_backend did not
      work. The pending message corresponding to the ready for query
      message could be a sync message, which does not have query
      context. But before we checked if there's a query context
      exists. The check is bogus and removed.

commit 7c955b2a2dfb77623055b5eae9afe041de3105ee
Author: Tatsuo Ishii <ishii at postgresql.org>
Date:   Sun Mar 12 10:19:34 2017 +0900

    Downgrade 1 more ereport from LOG to DEBUG1.




Sergey
________________________________
From: Tatsuo Ishii <ishii at sraoss.co.jp>
Sent: Tuesday, March 14, 2017 1:28 PM
To: Sergey Kim
Cc: pgpool-hackers at pgpool.net
Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created

Hi Sergey,

I have created a new branch named "bug271" which has been used to
develop the patch for bug 271 on private git repository. Now you could
use either the email attached patches or the branch if it's
convieninet for you. The branch was created against the master
branch. I will occasionaly rebase it with the master branch. In the
near future the branch will be merged into the master branch (and I
plan to back-patch it to 3.6 stable tree).

Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp

From: pgpool-committers-bounces at pgpool.net
Subject: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
Date: Tue, 14 Mar 2017 10:19:33 +0000
Message-ID: <E1cnjYD-0005zz-GZ at gothos.postgresql.org>

> Branch refs/heads/bug271 was created.
>
> View: http://git.postgresql.org/gitweb?p=pgpool2.git;a=shortlog;h=refs/heads/bug271
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-hackers/attachments/20170314/b37b39bf/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pgpool_tests.tar.gz
Type: application/gzip
Size: 690230 bytes
Desc: pgpool_tests.tar.gz
URL: <http://www.sraoss.jp/pipermail/pgpool-hackers/attachments/20170314/b37b39bf/attachment-0001.bin>

More information about the pgpool-hackers mailing list