[pgpool-hackers: 2173] Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
Sergey Kim
skim at odin.com
Tue Mar 21 04:54:26 JST 2017
Tatsuo,
the test that reproduces 3 problems is attached.
Besides switches 231 & 271 it has three new switches described below:
1) Switch 'CONN_HANGS'
The test does the sequence of actions:
- start transaction
- send PARSE request and execute it several times
- commit transaction
- executes request "" (empty string) - this type of requests is used by JBoss Application server to do the connections validation
- start transaction
- attempt to send PARSE request <= here is HANGS
2) Switch 'DEALLOCATE'
The test simply performs the following set commands:
- start transaction
- send parser requests 'select id from write_table limit ?'
- bind the value '1' and execute statement
- commit
Pgpool generates the log listed below and it can be seen there is one additional transaction appears!!!
2017-03-20T22:03:15.274645+03:00 OAA-54999c4d7735 pgpool[17914]: [6-1] LOG: new connection received
2017-03-20T22:03:15.274976+03:00 OAA-54999c4d7735 pgpool[17914]: [6-2] DETAIL: connecting host=10.194.250.82 port=60782
2017-03-20T22:03:15.275161+03:00 OAA-54999c4d7735 pgpool[17914]: [6-3] LOCATION: child.c:2163
2017-03-20T22:03:15.530151+03:00 OAA-54999c4d7735 pgpool[17914]: [7-1] LOG: DB node id: 0 backend pid: 18084 statement: Parse: SET extra_float_digits = 3
2017-03-20T22:03:15.530403+03:00 OAA-54999c4d7735 pgpool[17914]: [7-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.530583+03:00 OAA-54999c4d7735 pgpool[17914]: [8-1] LOG: DB node id: 1 backend pid: 2938 statement: Parse: SET extra_float_digits = 3
2017-03-20T22:03:15.530751+03:00 OAA-54999c4d7735 pgpool[17914]: [8-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.530920+03:00 OAA-54999c4d7735 pgpool[17914]: [9-1] LOG: DB node id: 0 backend pid: 18084 statement: B message
2017-03-20T22:03:15.531110+03:00 OAA-54999c4d7735 pgpool[17914]: [9-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.531260+03:00 OAA-54999c4d7735 pgpool[17914]: [10-1] LOG: DB node id: 1 backend pid: 2938 statement: B message
2017-03-20T22:03:15.531415+03:00 OAA-54999c4d7735 pgpool[17914]: [10-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.531597+03:00 OAA-54999c4d7735 pgpool[17914]: [11-1] LOG: DB node id: 0 backend pid: 18084 statement: Execute: SET extra_float_digits = 3
2017-03-20T22:03:15.531765+03:00 OAA-54999c4d7735 pgpool[17914]: [11-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.531930+03:00 OAA-54999c4d7735 pgpool[17914]: [12-1] LOG: DB node id: 1 backend pid: 2938 statement: Execute: SET extra_float_digits = 3
2017-03-20T22:03:15.532121+03:00 OAA-54999c4d7735 pgpool[17914]: [12-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.616709+03:00 OAA-54999c4d7735 pgpool[17914]: [13-1] LOG: DB node id: 0 backend pid: 18084 statement: Parse: BEGIN
2017-03-20T22:03:15.616892+03:00 OAA-54999c4d7735 pgpool[17914]: [13-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.617068+03:00 OAA-54999c4d7735 pgpool[17914]: [14-1] LOG: DB node id: 1 backend pid: 2938 statement: Parse: BEGIN
2017-03-20T22:03:15.617253+03:00 OAA-54999c4d7735 pgpool[17914]: [14-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.617415+03:00 OAA-54999c4d7735 pgpool[17914]: [15-1] LOG: DB node id: 0 backend pid: 18084 statement: B message
2017-03-20T22:03:15.617601+03:00 OAA-54999c4d7735 pgpool[17914]: [15-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.617765+03:00 OAA-54999c4d7735 pgpool[17914]: [16-1] LOG: DB node id: 1 backend pid: 2938 statement: B message
2017-03-20T22:03:15.617933+03:00 OAA-54999c4d7735 pgpool[17914]: [16-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.618112+03:00 OAA-54999c4d7735 pgpool[17914]: [17-1] LOG: DB node id: 0 backend pid: 18084 statement: Execute: BEGIN
2017-03-20T22:03:15.618271+03:00 OAA-54999c4d7735 pgpool[17914]: [17-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.618417+03:00 OAA-54999c4d7735 pgpool[17914]: [18-1] LOG: DB node id: 1 backend pid: 2938 statement: Execute: BEGIN
2017-03-20T22:03:15.618607+03:00 OAA-54999c4d7735 pgpool[17914]: [18-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.618777+03:00 OAA-54999c4d7735 pgpool[17914]: [19-1] LOG: DB node id: 0 backend pid: 18084 statement: SELECT count(*) from (SELECT has_function_privilege('oss', 'to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
2017-03-20T22:03:15.618949+03:00 OAA-54999c4d7735 pgpool[17914]: [19-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.619695+03:00 OAA-54999c4d7735 pgpool[17914]: [20-1] LOG: DB node id: 0 backend pid: 18084 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
2017-03-20T22:03:15.619869+03:00 OAA-54999c4d7735 pgpool[17914]: [20-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.620516+03:00 OAA-54999c4d7735 pgpool[17914]: [21-1] LOG: DB node id: 0 backend pid: 18084 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = to_regclass('"write_table"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2017-03-20T22:03:15.620705+03:00 OAA-54999c4d7735 pgpool[17914]: [21-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.621695+03:00 OAA-54999c4d7735 pgpool[17914]: [22-1] LOG: DB node id: 1 backend pid: 2938 statement: Parse: select id from write_table limit $1
2017-03-20T22:03:15.621893+03:00 OAA-54999c4d7735 pgpool[17914]: [22-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.622066+03:00 OAA-54999c4d7735 pgpool[17914]: [23-1] LOG: DB node id: 1 backend pid: 2938 statement: B message
2017-03-20T22:03:15.622252+03:00 OAA-54999c4d7735 pgpool[17914]: [23-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.622411+03:00 OAA-54999c4d7735 pgpool[17914]: [24-1] LOG: DB node id: 1 backend pid: 2938 statement: D message
2017-03-20T22:03:15.622664+03:00 OAA-54999c4d7735 pgpool[17914]: [24-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.622883+03:00 OAA-54999c4d7735 pgpool[17914]: [25-1] LOG: DB node id: 1 backend pid: 2938 statement: Execute: select id from write_table limit $1
2017-03-20T22:03:15.623136+03:00 OAA-54999c4d7735 pgpool[17914]: [25-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.779150+03:00 OAA-54999c4d7735 pgpool[17914]: [26-1] LOG: DB node id: 0 backend pid: 18084 statement: Parse: COMMIT
2017-03-20T22:03:15.779483+03:00 OAA-54999c4d7735 pgpool[17914]: [26-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.779730+03:00 OAA-54999c4d7735 pgpool[17914]: [27-1] LOG: DB node id: 1 backend pid: 2938 statement: Parse: COMMIT
2017-03-20T22:03:15.779962+03:00 OAA-54999c4d7735 pgpool[17914]: [27-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.780187+03:00 OAA-54999c4d7735 pgpool[17914]: [28-1] LOG: DB node id: 0 backend pid: 18084 statement: B message
2017-03-20T22:03:15.780380+03:00 OAA-54999c4d7735 pgpool[17914]: [28-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.780611+03:00 OAA-54999c4d7735 pgpool[17914]: [29-1] LOG: DB node id: 1 backend pid: 2938 statement: B message
2017-03-20T22:03:15.780845+03:00 OAA-54999c4d7735 pgpool[17914]: [29-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.781077+03:00 OAA-54999c4d7735 pgpool[17914]: [30-1] LOG: DB node id: 0 backend pid: 18084 statement: Execute: COMMIT
2017-03-20T22:03:15.781285+03:00 OAA-54999c4d7735 pgpool[17914]: [30-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.781493+03:00 OAA-54999c4d7735 pgpool[17914]: [31-1] LOG: DB node id: 1 backend pid: 2938 statement: Execute: COMMIT
2017-03-20T22:03:15.781847+03:00 OAA-54999c4d7735 pgpool[17914]: [31-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.843148+03:00 OAA-54999c4d7735 pgpool[17914]: [32-1] LOG: DB node id: 0 backend pid: 18084 statement: DISCARD ALL
2017-03-20T22:03:15.843406+03:00 OAA-54999c4d7735 pgpool[17914]: [32-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.843641+03:00 OAA-54999c4d7735 pgpool[17914]: [33-1] LOG: DB node id: 1 backend pid: 2938 statement: DISCARD ALL
2017-03-20T22:03:15.843876+03:00 OAA-54999c4d7735 pgpool[17914]: [33-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.844100+03:00 OAA-54999c4d7735 pgpool[17914]: [34-1] LOG: DB node id: 0 backend pid: 18084 statement: BEGIN
2017-03-20T22:03:15.844339+03:00 OAA-54999c4d7735 pgpool[17914]: [34-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.844560+03:00 OAA-54999c4d7735 pgpool[17914]: [35-1] LOG: DB node id: 1 backend pid: 2938 statement: BEGIN
2017-03-20T22:03:15.844765+03:00 OAA-54999c4d7735 pgpool[17914]: [35-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.844969+03:00 OAA-54999c4d7735 pgpool[17914]: [36-1] LOG: DB node id: 0 backend pid: 18084 statement: DEALLOCATE "S_1"
2017-03-20T22:03:15.845227+03:00 OAA-54999c4d7735 pgpool[17914]: [36-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.845356+03:00 OAA-54999c4d7735 pgpool[17914]: [37-1] LOG: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 18084 statement: "DEALLOCATE "S_1"" message: "prepared statement "S_1" does not exist"
2017-03-20T22:03:15.845489+03:00 OAA-54999c4d7735 pgpool[17914]: [37-2] LOCATION: pool_proto_modules.c:3218
2017-03-20T22:03:15.845649+03:00 OAA-54999c4d7735 pgpool[17914]: [38-1] LOG: DB node id: 1 backend pid: 2938 statement: DEALLOCATE "S_1"
2017-03-20T22:03:15.845804+03:00 OAA-54999c4d7735 pgpool[17914]: [38-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.845948+03:00 OAA-54999c4d7735 pgpool[17914]: [39-1] LOG: pool_send_and_wait: Error or notice message from backend: : DB node id: 1 backend pid: 2938 statement: "DEALLOCATE "S_1"" message: "prepared statement "S_1" does not exist"
2017-03-20T22:03:15.846136+03:00 OAA-54999c4d7735 pgpool[17914]: [39-2] LOCATION: pool_proto_modules.c:3218
2017-03-20T22:03:15.846265+03:00 OAA-54999c4d7735 pgpool[17914]: [40-1] LOG: DB node id: 1 backend pid: 2938 statement: COMMIT
2017-03-20T22:03:15.846392+03:00 OAA-54999c4d7735 pgpool[17914]: [40-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.846559+03:00 OAA-54999c4d7735 pgpool[17914]: [41-1] LOG: DB node id: 0 backend pid: 18084 statement: COMMIT
2017-03-20T22:03:15.846771+03:00 OAA-54999c4d7735 pgpool[17914]: [41-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:03:15.846845+03:00 OAA-54999c4d7735 pgpool[17914]: [42-1] LOG: child exiting, 1 connections reached
2017-03-20T22:03:15.846904+03:00 OAA-54999c4d7735 pgpool[17914]: [42-2] LOCATION: child.c:406
2017-03-20T22:03:15.847065+03:00 OAA-54999c4d7735 pgpool[17896]: [25-1] LOG: child process with pid: 17914 exits with status 256
2017-03-20T22:03:15.847275+03:00 OAA-54999c4d7735 pgpool[17896]: [25-2] LOCATION: pgpool_main.c:2380
2017-03-20T22:03:15.847419+03:00 OAA-54999c4d7735 pgpool[17896]: [26-1] LOG: fork a new child process with pid: 18085
2017-03-20T22:03:15.847608+03:00 OAA-54999c4d7735 pgpool[17896]: [26-2] LOCATION: pgpool_main.c:2466
3) Switch 'SHOW'
The test does:
- start transaction
- request 10 times the SQL 'select server_addr()' and remember the result
- request 'SHOW TRANSACTION ISOLATION LEVEL'
- request 10 times the SQL 'select server_addr()' and remember the result
- commit
if there are servers detected within this test then ends with error. It can be seen that after processing request 'SHOW ...' pgpool forwards all request to the Master DB only. But the following pgpool settings used:
>> backend_hostname0='a.db.node'
>> backend_port0=15432
>> backend_weight0=0
>> backend_data_directory0 = '/var/lib/pgsql/9.6/data'
>> backend_flag0 = 'ALLOW_TO_FAILOVER'
>>
>> backend_hostname1='b.db.node'
>> backend_port1=15432
>> backend_weight1=100
>> backend_data_directory1 = '/var/lib/pgsql/9.6/data'
>> backend_flag1 = 'ALLOW_TO_FAILOVER'
Also the pgpool log is the following:
2017-03-20T22:16:30.826881+03:00 OAA-54999c4d7735 pgpool[17916]: [6-1] LOG: new connection received
2017-03-20T22:16:30.849315+03:00 OAA-54999c4d7735 pgpool[17916]: [6-2] DETAIL: connecting host=10.194.250.82 port=32894
2017-03-20T22:16:30.849495+03:00 OAA-54999c4d7735 pgpool[17916]: [6-3] LOCATION: child.c:2163
2017-03-20T22:16:31.031073+03:00 OAA-54999c4d7735 pgpool[17916]: [7-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: SET extra_float_digits = 3
2017-03-20T22:16:31.031367+03:00 OAA-54999c4d7735 pgpool[17916]: [7-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.031552+03:00 OAA-54999c4d7735 pgpool[17916]: [8-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: SET extra_float_digits = 3
2017-03-20T22:16:31.031809+03:00 OAA-54999c4d7735 pgpool[17916]: [8-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.031984+03:00 OAA-54999c4d7735 pgpool[17916]: [9-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.032175+03:00 OAA-54999c4d7735 pgpool[17916]: [9-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.032334+03:00 OAA-54999c4d7735 pgpool[17916]: [10-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.032510+03:00 OAA-54999c4d7735 pgpool[17916]: [10-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.032697+03:00 OAA-54999c4d7735 pgpool[17916]: [11-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: SET extra_float_digits = 3
2017-03-20T22:16:31.032878+03:00 OAA-54999c4d7735 pgpool[17916]: [11-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.033045+03:00 OAA-54999c4d7735 pgpool[17916]: [12-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: SET extra_float_digits = 3
2017-03-20T22:16:31.033212+03:00 OAA-54999c4d7735 pgpool[17916]: [12-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.095855+03:00 OAA-54999c4d7735 pgpool[17916]: [13-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: BEGIN
2017-03-20T22:16:31.096053+03:00 OAA-54999c4d7735 pgpool[17916]: [13-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.096221+03:00 OAA-54999c4d7735 pgpool[17916]: [14-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: BEGIN
2017-03-20T22:16:31.096381+03:00 OAA-54999c4d7735 pgpool[17916]: [14-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.096576+03:00 OAA-54999c4d7735 pgpool[17916]: [15-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.096829+03:00 OAA-54999c4d7735 pgpool[17916]: [15-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.096997+03:00 OAA-54999c4d7735 pgpool[17916]: [16-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.097172+03:00 OAA-54999c4d7735 pgpool[17916]: [16-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.097332+03:00 OAA-54999c4d7735 pgpool[17916]: [17-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: BEGIN
2017-03-20T22:16:31.097484+03:00 OAA-54999c4d7735 pgpool[17916]: [17-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.097659+03:00 OAA-54999c4d7735 pgpool[17916]: [18-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: BEGIN
2017-03-20T22:16:31.097824+03:00 OAA-54999c4d7735 pgpool[17916]: [18-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.097991+03:00 OAA-54999c4d7735 pgpool[17916]: [19-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.098155+03:00 OAA-54999c4d7735 pgpool[17916]: [19-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.098329+03:00 OAA-54999c4d7735 pgpool[17916]: [20-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.098488+03:00 OAA-54999c4d7735 pgpool[17916]: [20-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.098662+03:00 OAA-54999c4d7735 pgpool[17916]: [21-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.098828+03:00 OAA-54999c4d7735 pgpool[17916]: [21-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.098987+03:00 OAA-54999c4d7735 pgpool[17916]: [22-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.099162+03:00 OAA-54999c4d7735 pgpool[17916]: [22-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.188870+03:00 OAA-54999c4d7735 pgpool[17916]: [23-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.189057+03:00 OAA-54999c4d7735 pgpool[17916]: [23-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.189264+03:00 OAA-54999c4d7735 pgpool[17916]: [24-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.189449+03:00 OAA-54999c4d7735 pgpool[17916]: [24-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.189628+03:00 OAA-54999c4d7735 pgpool[17916]: [25-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.189802+03:00 OAA-54999c4d7735 pgpool[17916]: [25-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.189968+03:00 OAA-54999c4d7735 pgpool[17916]: [26-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.190153+03:00 OAA-54999c4d7735 pgpool[17916]: [26-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.231153+03:00 OAA-54999c4d7735 pgpool[17916]: [27-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.231357+03:00 OAA-54999c4d7735 pgpool[17916]: [27-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.231528+03:00 OAA-54999c4d7735 pgpool[17916]: [28-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.231700+03:00 OAA-54999c4d7735 pgpool[17916]: [28-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.231855+03:00 OAA-54999c4d7735 pgpool[17916]: [29-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.232014+03:00 OAA-54999c4d7735 pgpool[17916]: [29-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.232195+03:00 OAA-54999c4d7735 pgpool[17916]: [30-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.232342+03:00 OAA-54999c4d7735 pgpool[17916]: [30-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.273735+03:00 OAA-54999c4d7735 pgpool[17916]: [31-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.273919+03:00 OAA-54999c4d7735 pgpool[17916]: [31-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.274084+03:00 OAA-54999c4d7735 pgpool[17916]: [32-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.274252+03:00 OAA-54999c4d7735 pgpool[17916]: [32-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.274433+03:00 OAA-54999c4d7735 pgpool[17916]: [33-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.274615+03:00 OAA-54999c4d7735 pgpool[17916]: [33-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.274778+03:00 OAA-54999c4d7735 pgpool[17916]: [34-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.274950+03:00 OAA-54999c4d7735 pgpool[17916]: [34-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.316727+03:00 OAA-54999c4d7735 pgpool[17916]: [35-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.316909+03:00 OAA-54999c4d7735 pgpool[17916]: [35-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.317079+03:00 OAA-54999c4d7735 pgpool[17916]: [36-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.317236+03:00 OAA-54999c4d7735 pgpool[17916]: [36-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.317411+03:00 OAA-54999c4d7735 pgpool[17916]: [37-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.317605+03:00 OAA-54999c4d7735 pgpool[17916]: [37-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.317772+03:00 OAA-54999c4d7735 pgpool[17916]: [38-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.317950+03:00 OAA-54999c4d7735 pgpool[17916]: [38-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.359324+03:00 OAA-54999c4d7735 pgpool[17916]: [39-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.359547+03:00 OAA-54999c4d7735 pgpool[17916]: [39-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.359716+03:00 OAA-54999c4d7735 pgpool[17916]: [40-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.359881+03:00 OAA-54999c4d7735 pgpool[17916]: [40-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.360043+03:00 OAA-54999c4d7735 pgpool[17916]: [41-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.360218+03:00 OAA-54999c4d7735 pgpool[17916]: [41-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.360370+03:00 OAA-54999c4d7735 pgpool[17916]: [42-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.360545+03:00 OAA-54999c4d7735 pgpool[17916]: [42-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.402262+03:00 OAA-54999c4d7735 pgpool[17916]: [43-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.402449+03:00 OAA-54999c4d7735 pgpool[17916]: [43-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.402631+03:00 OAA-54999c4d7735 pgpool[17916]: [44-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.402805+03:00 OAA-54999c4d7735 pgpool[17916]: [44-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.402966+03:00 OAA-54999c4d7735 pgpool[17916]: [45-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.403146+03:00 OAA-54999c4d7735 pgpool[17916]: [45-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.403310+03:00 OAA-54999c4d7735 pgpool[17916]: [46-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.403471+03:00 OAA-54999c4d7735 pgpool[17916]: [46-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.445072+03:00 OAA-54999c4d7735 pgpool[17916]: [47-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.445255+03:00 OAA-54999c4d7735 pgpool[17916]: [47-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.445415+03:00 OAA-54999c4d7735 pgpool[17916]: [48-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.445621+03:00 OAA-54999c4d7735 pgpool[17916]: [48-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.445787+03:00 OAA-54999c4d7735 pgpool[17916]: [49-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.445945+03:00 OAA-54999c4d7735 pgpool[17916]: [49-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.446127+03:00 OAA-54999c4d7735 pgpool[17916]: [50-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.446270+03:00 OAA-54999c4d7735 pgpool[17916]: [50-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.488454+03:00 OAA-54999c4d7735 pgpool[17916]: [51-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.488639+03:00 OAA-54999c4d7735 pgpool[17916]: [51-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.488802+03:00 OAA-54999c4d7735 pgpool[17916]: [52-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.488968+03:00 OAA-54999c4d7735 pgpool[17916]: [52-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.489147+03:00 OAA-54999c4d7735 pgpool[17916]: [53-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.489295+03:00 OAA-54999c4d7735 pgpool[17916]: [53-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.489445+03:00 OAA-54999c4d7735 pgpool[17916]: [54-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.489632+03:00 OAA-54999c4d7735 pgpool[17916]: [54-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.531369+03:00 OAA-54999c4d7735 pgpool[17916]: [55-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.531567+03:00 OAA-54999c4d7735 pgpool[17916]: [55-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.531731+03:00 OAA-54999c4d7735 pgpool[17916]: [56-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:31.531921+03:00 OAA-54999c4d7735 pgpool[17916]: [56-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.532099+03:00 OAA-54999c4d7735 pgpool[17916]: [57-1] LOG: DB node id: 1 backend pid: 2965 statement: D message
2017-03-20T22:16:31.532283+03:00 OAA-54999c4d7735 pgpool[17916]: [57-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.532428+03:00 OAA-54999c4d7735 pgpool[17916]: [58-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.532633+03:00 OAA-54999c4d7735 pgpool[17916]: [58-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.574095+03:00 OAA-54999c4d7735 pgpool[17916]: [59-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: SHOW TRANSACTION ISOLATION LEVEL
2017-03-20T22:16:31.574291+03:00 OAA-54999c4d7735 pgpool[17916]: [59-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.574468+03:00 OAA-54999c4d7735 pgpool[17916]: [60-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.574664+03:00 OAA-54999c4d7735 pgpool[17916]: [60-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.574828+03:00 OAA-54999c4d7735 pgpool[17916]: [61-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.574997+03:00 OAA-54999c4d7735 pgpool[17916]: [61-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.575180+03:00 OAA-54999c4d7735 pgpool[17916]: [62-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: SHOW TRANSACTION ISOLATION LEVEL
2017-03-20T22:16:31.575321+03:00 OAA-54999c4d7735 pgpool[17916]: [62-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.617144+03:00 OAA-54999c4d7735 pgpool[17916]: [63-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.617394+03:00 OAA-54999c4d7735 pgpool[17916]: [63-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.617589+03:00 OAA-54999c4d7735 pgpool[17916]: [64-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.617766+03:00 OAA-54999c4d7735 pgpool[17916]: [64-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.617932+03:00 OAA-54999c4d7735 pgpool[17916]: [65-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.618131+03:00 OAA-54999c4d7735 pgpool[17916]: [65-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.618278+03:00 OAA-54999c4d7735 pgpool[17916]: [66-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.618421+03:00 OAA-54999c4d7735 pgpool[17916]: [66-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.659516+03:00 OAA-54999c4d7735 pgpool[17916]: [67-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.659706+03:00 OAA-54999c4d7735 pgpool[17916]: [67-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.659882+03:00 OAA-54999c4d7735 pgpool[17916]: [68-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.660070+03:00 OAA-54999c4d7735 pgpool[17916]: [68-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.660235+03:00 OAA-54999c4d7735 pgpool[17916]: [69-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.660385+03:00 OAA-54999c4d7735 pgpool[17916]: [69-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.660589+03:00 OAA-54999c4d7735 pgpool[17916]: [70-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.660769+03:00 OAA-54999c4d7735 pgpool[17916]: [70-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.701764+03:00 OAA-54999c4d7735 pgpool[17916]: [71-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.701954+03:00 OAA-54999c4d7735 pgpool[17916]: [71-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.702128+03:00 OAA-54999c4d7735 pgpool[17916]: [72-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.702288+03:00 OAA-54999c4d7735 pgpool[17916]: [72-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.702452+03:00 OAA-54999c4d7735 pgpool[17916]: [73-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.702636+03:00 OAA-54999c4d7735 pgpool[17916]: [73-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.702836+03:00 OAA-54999c4d7735 pgpool[17916]: [74-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.702995+03:00 OAA-54999c4d7735 pgpool[17916]: [74-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.744789+03:00 OAA-54999c4d7735 pgpool[17916]: [75-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.744974+03:00 OAA-54999c4d7735 pgpool[17916]: [75-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.745139+03:00 OAA-54999c4d7735 pgpool[17916]: [76-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.745335+03:00 OAA-54999c4d7735 pgpool[17916]: [76-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.745552+03:00 OAA-54999c4d7735 pgpool[17916]: [77-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.745736+03:00 OAA-54999c4d7735 pgpool[17916]: [77-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.745902+03:00 OAA-54999c4d7735 pgpool[17916]: [78-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.746073+03:00 OAA-54999c4d7735 pgpool[17916]: [78-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.787533+03:00 OAA-54999c4d7735 pgpool[17916]: [79-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.787731+03:00 OAA-54999c4d7735 pgpool[17916]: [79-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.787907+03:00 OAA-54999c4d7735 pgpool[17916]: [80-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.788087+03:00 OAA-54999c4d7735 pgpool[17916]: [80-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.788244+03:00 OAA-54999c4d7735 pgpool[17916]: [81-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.788410+03:00 OAA-54999c4d7735 pgpool[17916]: [81-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.788592+03:00 OAA-54999c4d7735 pgpool[17916]: [82-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.788764+03:00 OAA-54999c4d7735 pgpool[17916]: [82-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.830181+03:00 OAA-54999c4d7735 pgpool[17916]: [83-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.830359+03:00 OAA-54999c4d7735 pgpool[17916]: [83-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.830549+03:00 OAA-54999c4d7735 pgpool[17916]: [84-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.830713+03:00 OAA-54999c4d7735 pgpool[17916]: [84-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.830882+03:00 OAA-54999c4d7735 pgpool[17916]: [85-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.831064+03:00 OAA-54999c4d7735 pgpool[17916]: [85-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.831220+03:00 OAA-54999c4d7735 pgpool[17916]: [86-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.831363+03:00 OAA-54999c4d7735 pgpool[17916]: [86-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.872765+03:00 OAA-54999c4d7735 pgpool[17916]: [87-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.872944+03:00 OAA-54999c4d7735 pgpool[17916]: [87-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.873129+03:00 OAA-54999c4d7735 pgpool[17916]: [88-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.873315+03:00 OAA-54999c4d7735 pgpool[17916]: [88-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.873496+03:00 OAA-54999c4d7735 pgpool[17916]: [89-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.873668+03:00 OAA-54999c4d7735 pgpool[17916]: [89-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.873850+03:00 OAA-54999c4d7735 pgpool[17916]: [90-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.874022+03:00 OAA-54999c4d7735 pgpool[17916]: [90-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.915383+03:00 OAA-54999c4d7735 pgpool[17916]: [91-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.915649+03:00 OAA-54999c4d7735 pgpool[17916]: [91-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.915829+03:00 OAA-54999c4d7735 pgpool[17916]: [92-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.916012+03:00 OAA-54999c4d7735 pgpool[17916]: [92-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.916216+03:00 OAA-54999c4d7735 pgpool[17916]: [93-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.916388+03:00 OAA-54999c4d7735 pgpool[17916]: [93-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.916597+03:00 OAA-54999c4d7735 pgpool[17916]: [94-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.916778+03:00 OAA-54999c4d7735 pgpool[17916]: [94-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.957764+03:00 OAA-54999c4d7735 pgpool[17916]: [95-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:31.957944+03:00 OAA-54999c4d7735 pgpool[17916]: [95-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.958132+03:00 OAA-54999c4d7735 pgpool[17916]: [96-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:31.958317+03:00 OAA-54999c4d7735 pgpool[17916]: [96-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.958475+03:00 OAA-54999c4d7735 pgpool[17916]: [97-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:31.958669+03:00 OAA-54999c4d7735 pgpool[17916]: [97-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:31.958835+03:00 OAA-54999c4d7735 pgpool[17916]: [98-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:31.958993+03:00 OAA-54999c4d7735 pgpool[17916]: [98-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.000442+03:00 OAA-54999c4d7735 pgpool[17916]: [99-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: select inet_server_addr()
2017-03-20T22:16:32.000649+03:00 OAA-54999c4d7735 pgpool[17916]: [99-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.000830+03:00 OAA-54999c4d7735 pgpool[17916]: [100-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:32.000992+03:00 OAA-54999c4d7735 pgpool[17916]: [100-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.001173+03:00 OAA-54999c4d7735 pgpool[17916]: [101-1] LOG: DB node id: 0 backend pid: 18139 statement: D message
2017-03-20T22:16:32.001330+03:00 OAA-54999c4d7735 pgpool[17916]: [101-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.001483+03:00 OAA-54999c4d7735 pgpool[17916]: [102-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: select inet_server_addr()
2017-03-20T22:16:32.001664+03:00 OAA-54999c4d7735 pgpool[17916]: [102-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.043716+03:00 OAA-54999c4d7735 pgpool[17916]: [103-1] LOG: DB node id: 0 backend pid: 18139 statement: Parse: COMMIT
2017-03-20T22:16:32.043923+03:00 OAA-54999c4d7735 pgpool[17916]: [103-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.044136+03:00 OAA-54999c4d7735 pgpool[17916]: [104-1] LOG: DB node id: 1 backend pid: 2965 statement: Parse: COMMIT
2017-03-20T22:16:32.044309+03:00 OAA-54999c4d7735 pgpool[17916]: [104-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.044472+03:00 OAA-54999c4d7735 pgpool[17916]: [105-1] LOG: DB node id: 0 backend pid: 18139 statement: B message
2017-03-20T22:16:32.044647+03:00 OAA-54999c4d7735 pgpool[17916]: [105-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.044822+03:00 OAA-54999c4d7735 pgpool[17916]: [106-1] LOG: DB node id: 1 backend pid: 2965 statement: B message
2017-03-20T22:16:32.044985+03:00 OAA-54999c4d7735 pgpool[17916]: [106-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.045170+03:00 OAA-54999c4d7735 pgpool[17916]: [107-1] LOG: DB node id: 0 backend pid: 18139 statement: Execute: COMMIT
2017-03-20T22:16:32.045331+03:00 OAA-54999c4d7735 pgpool[17916]: [107-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.045521+03:00 OAA-54999c4d7735 pgpool[17916]: [108-1] LOG: DB node id: 1 backend pid: 2965 statement: Execute: COMMIT
2017-03-20T22:16:32.045698+03:00 OAA-54999c4d7735 pgpool[17916]: [108-2] LOCATION: pool_proto_modules.c:3202
2017-03-20T22:16:32.101469+03:00 OAA-54999c4d7735 pgpool[17916]: [109-1] LOG: child exiting, 1 connections reached
2017-03-20T22:16:32.101677+03:00 OAA-54999c4d7735 pgpool[17916]: [109-2] LOCATION: child.c:256
2017-03-20T22:16:32.102676+03:00 OAA-54999c4d7735 pgpool[17896]: [27-1] LOG: child process with pid: 17916 exits with status 256
2017-03-20T22:16:32.102899+03:00 OAA-54999c4d7735 pgpool[17896]: [27-2] LOCATION: pgpool_main.c:2380
2017-03-20T22:16:32.103101+03:00 OAA-54999c4d7735 pgpool[17896]: [28-1] LOG: fork a new child process with pid: 18140
2017-03-20T22:16:32.103294+03:00 OAA-54999c4d7735 pgpool[17896]: [28-2] LOCATION: pgpool_main.c:2466
________________________________
From: Sergey Kim
Sent: Monday, March 20, 2017 3:05 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,
give this day. I think tomorrow I will provide a deeper investigation result.
The fact is that when there is no pgpool between application and DB the application starts and acts ok.
Sergey.
________________________________
From: Tatsuo Ishii <ishii at sraoss.co.jp>
Sent: Monday, March 20, 2017 2:46:08 PM
To: Sergey Kim
Cc: pgpool-hackers at pgpool.net; Boris Voskanov
Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
Sergey,
> Tatsuo,
>
>
> created tests for issues #231 and #271 are being run OK. Later I will confirm their results.
>
>
> Meanwhile I identified 3 suspicious facts:
>
> 1) our system (uses jdbc) sometimes hangs on attempt to obtain a DB connection from Pgpool. It doesn't happen with the stable 3.6.1 version of pgpool.
>
> I'm not sure how to reproduce it. Both DB backends being run OK and no errors found in their logs.
Are you sure that your apps are blocked at the connection time?
> 2) obviously the request "SHOW TRANSACTION ISOLATION LEVEL" is considered by pgpool as a Modification request. Is it correct?
No, currently only SELECTs and some forms of COPY can be load
balanced. SHOW commands are not load balanced, because SHOW is not
heavily used and it's not worth to load balance it, I think.
> 2017-03-20T13:43:56.865363+03:00 OAA-54999c4d7735 pgpool[13051]: [17-1] LOG: DB node id: 0 backend pid: 13165 statement: Execute: BEGIN
> 2017-03-20T13:43:56.865551+03:00 OAA-54999c4d7735 pgpool[13051]: [17-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.865725+03:00 OAA-54999c4d7735 pgpool[13051]: [18-1] LOG: DB node id: 1 backend pid: 546 statement: Execute: BEGIN
> 2017-03-20T13:43:56.865878+03:00 OAA-54999c4d7735 pgpool[13051]: [18-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.866031+03:00 OAA-54999c4d7735 pgpool[13051]: [19-1] LOG: DB node id: 0 backend pid: 13165 statement: Parse: SHOW TRANSACTION ISOLATION LEVEL
> 2017-03-20T13:43:56.866206+03:00 OAA-54999c4d7735 pgpool[13051]: [19-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.866359+03:00 OAA-54999c4d7735 pgpool[13051]: [20-1] LOG: DB node id: 0 backend pid: 13165 statement: B message
> 2017-03-20T13:43:56.866528+03:00 OAA-54999c4d7735 pgpool[13051]: [20-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.866700+03:00 OAA-54999c4d7735 pgpool[13051]: [21-1] LOG: DB node id: 0 backend pid: 13165 statement: D message
> 2017-03-20T13:43:56.866869+03:00 OAA-54999c4d7735 pgpool[13051]: [21-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.867018+03:00 OAA-54999c4d7735 pgpool[13051]: [22-1] LOG: DB node id: 0 backend pid: 13165 statement: Execute: SHOW TRANSACTION ISOLATION LEVEL
> 2017-03-20T13:43:56.867191+03:00 OAA-54999c4d7735 pgpool[13051]: [22-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.911542+03:00 OAA-54999c4d7735 pgpool[13051]: [23-1] LOG: DB node id: 0 backend pid: 13165 statement: Parse: select current_schema()
> 2017-03-20T13:43:56.911776+03:00 OAA-54999c4d7735 pgpool[13051]: [23-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.911934+03:00 OAA-54999c4d7735 pgpool[13051]: [24-1] LOG: DB node id: 0 backend pid: 13165 statement: B message
> 2017-03-20T13:43:56.912106+03:00 OAA-54999c4d7735 pgpool[13051]: [24-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.912273+03:00 OAA-54999c4d7735 pgpool[13051]: [25-1] LOG: DB node id: 0 backend pid: 13165 statement: D message
> 2017-03-20T13:43:56.912428+03:00 OAA-54999c4d7735 pgpool[13051]: [25-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.912681+03:00 OAA-54999c4d7735 pgpool[13051]: [26-1] LOG: DB node id: 0 backend pid: 13165 statement: Execute: select current_schema()
> 2017-03-20T13:43:56.912840+03:00 OAA-54999c4d7735 pgpool[13051]: [26-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.963406+03:00 OAA-54999c4d7735 pgpool[13051]: [27-1] LOG: DB node id: 0 backend pid: 13165 statement: Parse: select current_schema()
> 2017-03-20T13:43:56.963691+03:00 OAA-54999c4d7735 pgpool[13051]: [27-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.963857+03:00 OAA-54999c4d7735 pgpool[13051]: [28-1] LOG: DB node id: 0 backend pid: 13165 statement: B message
> 2017-03-20T13:43:56.964022+03:00 OAA-54999c4d7735 pgpool[13051]: [28-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.964189+03:00 OAA-54999c4d7735 pgpool[13051]: [29-1] LOG: DB node id: 0 backend pid: 13165 statement: D message
> 2017-03-20T13:43:56.964327+03:00 OAA-54999c4d7735 pgpool[13051]: [29-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:56.964508+03:00 OAA-54999c4d7735 pgpool[13051]: [30-1] LOG: DB node id: 0 backend pid: 13165 statement: Execute: select current_schema()
> 2017-03-20T13:43:56.964677+03:00 OAA-54999c4d7735 pgpool[13051]: [30-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.011840+03:00 OAA-54999c4d7735 pgpool[13051]: [31-1] LOG: DB node id: 0 backend pid: 13165 statement: Parse: COMMIT
> 2017-03-20T13:43:57.012015+03:00 OAA-54999c4d7735 pgpool[13051]: [31-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.012175+03:00 OAA-54999c4d7735 pgpool[13051]: [32-1] LOG: DB node id: 1 backend pid: 546 statement: Parse: COMMIT
>
>
>
>
> 3) Error in pgpool log:
>
> 2017-03-20T13:43:57.216594+03:00 OAA-54999c4d7735 pgpool[13051]: [60-1] LOG: DB node id: 0 backend pid: 13165 statement: B message
> 2017-03-20T13:43:57.216756+03:00 OAA-54999c4d7735 pgpool[13051]: [60-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.216921+03:00 OAA-54999c4d7735 pgpool[13051]: [61-1] LOG: DB node id: 0 backend pid: 13165 statement: D message
> 2017-03-20T13:43:57.217106+03:00 OAA-54999c4d7735 pgpool[13051]: [61-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.217254+03:00 OAA-54999c4d7735 pgpool[13051]: [62-1] LOG: DB node id: 0 backend pid: 13165 statement: Execute: select current_schema()
> 2017-03-20T13:43:57.217393+03:00 OAA-54999c4d7735 pgpool[13051]: [62-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.260149+03:00 OAA-54999c4d7735 pgpool[13051]: [63-1] LOG: DB node id: 0 backend pid: 13165 statement: DISCARD ALL
> 2017-03-20T13:43:57.260374+03:00 OAA-54999c4d7735 pgpool[13051]: [63-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.260547+03:00 OAA-54999c4d7735 pgpool[13051]: [64-1] LOG: DB node id: 1 backend pid: 546 statement: DISCARD ALL
> 2017-03-20T13:43:57.260712+03:00 OAA-54999c4d7735 pgpool[13051]: [64-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.260879+03:00 OAA-54999c4d7735 pgpool[13051]: [65-1] LOG: DB node id: 0 backend pid: 13165 statement: BEGIN
> 2017-03-20T13:43:57.261037+03:00 OAA-54999c4d7735 pgpool[13051]: [65-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.261196+03:00 OAA-54999c4d7735 pgpool[13051]: [66-1] LOG: DB node id: 1 backend pid: 546 statement: BEGIN
> 2017-03-20T13:43:57.261362+03:00 OAA-54999c4d7735 pgpool[13051]: [66-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.261515+03:00 OAA-54999c4d7735 pgpool[13051]: [67-1] LOG: DB node id: 0 backend pid: 13165 statement: DEALLOCATE "S_1"
> 2017-03-20T13:43:57.261692+03:00 OAA-54999c4d7735 pgpool[13051]: [67-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.261855+03:00 OAA-54999c4d7735 pgpool[13051]: [68-1] LOG: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 13165 statement: "DEALLOCATE "S_1"" message: "prepared statement "S_1" does not exist"
> 2017-03-20T13:43:57.262021+03:00 OAA-54999c4d7735 pgpool[13051]: [68-2] LOCATION: pool_proto_modules.c:3218
> 2017-03-20T13:43:57.262177+03:00 OAA-54999c4d7735 pgpool[13051]: [69-1] LOG: DB node id: 1 backend pid: 546 statement: DEALLOCATE "S_1"
> 2017-03-20T13:43:57.262325+03:00 OAA-54999c4d7735 pgpool[13051]: [69-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.262470+03:00 OAA-54999c4d7735 pgpool[13051]: [70-1] LOG: pool_send_and_wait: Error or notice message from backend: : DB node id: 1 backend pid: 546 statement: "DEALLOCATE "S_1"" message: "prepared statement "S_1" does not exist"
> 2017-03-20T13:43:57.262642+03:00 OAA-54999c4d7735 pgpool[13051]: [70-2] LOCATION: pool_proto_modules.c:3218
> 2017-03-20T13:43:57.262736+03:00 OAA-54999c4d7735 pgpool[13051]: [71-1] LOG: DB node id: 1 backend pid: 546 statement: COMMIT
> 2017-03-20T13:43:57.262812+03:00 OAA-54999c4d7735 pgpool[13051]: [71-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.262879+03:00 OAA-54999c4d7735 pgpool[13051]: [72-1] LOG: DB node id: 0 backend pid: 13165 statement: COMMIT
> 2017-03-20T13:43:57.262944+03:00 OAA-54999c4d7735 pgpool[13051]: [72-2] LOCATION: pool_proto_modules.c:3202
> 2017-03-20T13:43:57.263014+03:00 OAA-54999c4d7735 pgpool[13051]: [73-1] LOG: child exiting, 1 connections reached
> 2017-03-20T13:43:57.263081+03:00 OAA-54999c4d7735 pgpool[13051]: [73-2] LOCATION: child.c:406
> 2017-03-20T13:43:57.263238+03:00 OAA-54999c4d7735 pgpool[13035]: [13-1] LOG: child process with pid: 13051 exits with status 256
> 2017-03-20T13:43:57.263402+03:00 OAA-54999c4d7735 pgpool[13035]: [13-2] LOCATION: pgpool_main.c:2380
> 2017-03-20T13:43:57.263588+03:00 OAA-54999c4d7735 pgpool[13035]: [14-1] LOG: fork a new child process with pid: 13166
> 2017-03-20T13:43:57.263748+03:00 OAA-54999c4d7735 pgpool[13035]: [14-2] LOCATION: pgpool_main.c:2466
>
>
>
> Sergey.
>
> ________________________________
> From: Tatsuo Ishii <ishii at sraoss.co.jp>
> Sent: Monday, March 20, 2017 1:15 PM
> To: Sergey Kim
> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>
> Sergey,
>
> I have fixed a bug revealed by your test case.
>
> (Also pushed to bug271 branch).
>
> Best regards,
> --
> Tatsuo Ishii
> SRA OSS, Inc. Japan
> English: http://www.sraoss.co.jp/index_en.php
> Japanese:http://www.sraoss.co.jp
>
>> Tatsuo,
>>
>>
>> The test that reproduces the issue is attached. Please run it as usually like:
>>
>> java -jar target/tests-1.0-SNAPSHOT-jar-with-dependencies.jar PGPOOL_HOST PGPOOL_PORT DB_NAME DB_USER DB_PASSWORD 231
>>
>> The abstract sequence of commands that reproduces the problem:
>> - open connection
>> - start transaction
>> - do some requests
>> - commit
>> - start transaction
>> - do some requests
>> - commit
>> - so some requests <= mismatch FAIL
>>
>> please review the end of this action as log records, it also can be seen that the PARSE command forwarded to 2 backends:
>> 17-03-20T03:13:05.083338+03:00 OAA-54999c4d7735 pgpool[10035]: [157-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.083532+03:00 OAA-54999c4d7735 pgpool[10035]: [158-1] LOG: DB node id: 1 backend pid: 31628 statement: D message
>> 2017-03-20T03:13:05.083733+03:00 OAA-54999c4d7735 pgpool[10035]: [158-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.083940+03:00 OAA-54999c4d7735 pgpool[10035]: [159-1] LOG: DB node id: 1 backend pid: 31628 statement: Execute: select id,'backend_1' from write_table where id = $1
>> 2017-03-20T03:13:05.084142+03:00 OAA-54999c4d7735 pgpool[10035]: [159-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.135876+03:00 OAA-54999c4d7735 pgpool[10035]: [160-1] LOG: DB node id: 0 backend pid: 10082 statement: B message
>> 2017-03-20T03:13:05.136108+03:00 OAA-54999c4d7735 pgpool[10035]: [160-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.136342+03:00 OAA-54999c4d7735 pgpool[10035]: [161-1] LOG: DB node id: 1 backend pid: 31628 statement: B message
>> 2017-03-20T03:13:05.136687+03:00 OAA-54999c4d7735 pgpool[10035]: [161-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.136932+03:00 OAA-54999c4d7735 pgpool[10035]: [162-1] LOG: DB node id: 0 backend pid: 10082 statement: Execute: COMMIT
>> 2017-03-20T03:13:05.137148+03:00 OAA-54999c4d7735 pgpool[10035]: [162-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.137332+03:00 OAA-54999c4d7735 pgpool[10035]: [163-1] LOG: DB node id: 1 backend pid: 31628 statement: Execute: COMMIT
>> 2017-03-20T03:13:05.137572+03:00 OAA-54999c4d7735 pgpool[10035]: [163-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.184780+03:00 OAA-54999c4d7735 pgpool[10035]: [164-1] LOG: DB node id: 1 backend pid: 31628 statement: Parse: select current_schema()
>> 2017-03-20T03:13:05.185016+03:00 OAA-54999c4d7735 pgpool[10035]: [164-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.185258+03:00 OAA-54999c4d7735 pgpool[10035]: [165-1] LOG: DB node id: 0 backend pid: 10082 statement: Parse: select current_schema()
>> 2017-03-20T03:13:05.185472+03:00 OAA-54999c4d7735 pgpool[10035]: [165-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.185681+03:00 OAA-54999c4d7735 pgpool[10035]: [166-1] LOG: DB node id: 0 backend pid: 10082 statement: B message
>> 2017-03-20T03:13:05.185978+03:00 OAA-54999c4d7735 pgpool[10035]: [166-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.186187+03:00 OAA-54999c4d7735 pgpool[10035]: [167-1] LOG: DB node id: 0 backend pid: 10082 statement: D message
>> 2017-03-20T03:13:05.186366+03:00 OAA-54999c4d7735 pgpool[10035]: [167-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.186583+03:00 OAA-54999c4d7735 pgpool[10035]: [168-1] LOG: DB node id: 0 backend pid: 10082 statement: Execute: select current_schema()
>> 2017-03-20T03:13:05.186708+03:00 OAA-54999c4d7735 pgpool[10035]: [168-2] LOCATION: pool_proto_modules.c:3202
>> 2017-03-20T03:13:05.186825+03:00 OAA-54999c4d7735 pgpool[10035]: [169-1] FATAL: failed to read kind from backend
>> 2017-03-20T03:13:05.186929+03:00 OAA-54999c4d7735 pgpool[10035]: [169-2] DETAIL: kind mismatch among backends. Possible last query was: "select current_schema()" kind details are: 0[Z] 1[1]
>> 2017-03-20T03:13:05.187040+03:00 OAA-54999c4d7735 pgpool[10035]: [169-3] HINT: check data consistency among db nodes
>> 2017-03-20T03:13:05.187161+03:00 OAA-54999c4d7735 pgpool[10035]: [169-4] LOCATION: pool_process_query.c:3731
>> 2017-03-20T03:13:05.187359+03:00 OAA-54999c4d7735 pgpool[9563]: [153-1] LOG: child process with pid: 10035 exits with status 512
>> 2017-03-20T03:13:05.187634+03:00 OAA-54999c4d7735 pgpool[9563]: [153-2] LOCATION: pgpool_main.c:2380
>> 2017-03-20T03:13:05.187803+03:00 OAA-54999c4d7735 pgpool[9563]: [154-1] LOG: fork a new child process with pid: 10083
>> 2017-03-20T03:13:05.187970+03:00 OAA-54999c4d7735 pgpool[9563]: [154-2] LOCATION: pgpool_main.c:2466
>>
>>
>>
>> ===
>>
>>
>> Also please review the attached log file of pgpool for a concrete process (
>>
>> We have deeply analyzed its contents:
>>
>> 1) At the very beginning it can be seen the pgpool violates balancing rules listed below. SELECT requests are forwarded to the node #0, which should not happen.
>>
>>
>> backend_hostname0='a.db.node'
>> backend_port0=15432
>> backend_weight0=0
>> backend_data_directory0 = '/var/lib/pgsql/9.6/data'
>> backend_flag0 = 'ALLOW_TO_FAILOVER'
>>
>> backend_hostname1='b.db.node'
>> backend_port1=15432
>> backend_weight1=100
>> backend_data_directory1 = '/var/lib/pgsql/9.6/data'
>> backend_flag1 = 'ALLOW_TO_FAILOVER'
>>
>>
>> This is because the first issued request is "SHOW TRANSACTION ISOLATION LEVEL". Is it considered as a WRITE/UPDATE request?
>>
>>
>>
>> Sergey.
>> ________________________________
>> From: Sergey Kim
>> Sent: Friday, March 17, 2017 11:22 AM
>> To: Tatsuo Ishii
>> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
>> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>>
>> These thoughts appeared in my head because I'm trynig to analyse the current problems:
>> 1. balanced selects after modification is performed
>> 2. "kind mismatch" errors
>>
>> To me it seems the questions are fundamental. Pgpool is a kind of balancing proxy but since the protocol that it deals to is session based we face the current problems. This is a state machine after all. My role in Odin Ingram company - investigation anc POCs tasks. I dive into the problem now and read documentation regarding postgres. ...just let me to read the Pgpool's code more a little bit..
>>
>>
>> Sergey.
>> ________________________________
>> From: Tatsuo Ishii <ishii at sraoss.co.jp>
>> Sent: Friday, March 17, 2017 9:48:52 AM
>> To: Sergey Kim
>> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
>> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>>
>>> Tatsuo,
>>>
>>> I'm not sure my understanding of your current patches is correct, but to me it seems that the concept is the following:
>>
>> Probably you'd better to study the extended query section of the
>> PostgreSQL's frontend/backend protocol document to understand what
>> Pgpool-II tries to do. Anyway,
>>
>>> Pgpool saves all prepared statements (SQL statements) mapped to their codes (e.g. S_1 mapped to SELECT name FROM TABLE where ID = ? ). So after any UPDATE request is completely processed and another statement execution request received, and if explicit transaction exists, then pgpool verifies:
>>>
>>> 1) if the request is a previously PARSED message then the mapped SQL statement it taken from some memory store and send for parsing to the Master backend. Where the parsing is complete pgpool performs binding and execution of the primary request
>>
>> I'm not sure what "the request" means here. PostgreSQL sends each
>> request separately, namely parse/bind/describe/execute/close. I assume
>> "the request" means a bind request for now. A bind message can only be
>> distinguished by the statement name like "S_1" which was given to the
>> previous parse request. There are two types of statements: named
>> statement and unnamed statement. "S_1" is a named statement and will
>> last until explicitly closed by a close request. So Pgpool-II needs
>> to remember the named statement S_1 until explicitly closed (more
>> precisely, there are "unnamed statement" and and "unnamed
>> portal". Those behave differently from named statements and named
>> portal. But I don't want to confuse you and I will not explain them
>> for now). A bind request accepts at least two parameters: a statement
>> name and a portal name. A bind request binds the statement and the
>> portal along with query parameters if any.
>>
>> Execution is another story. It can be done by "execute"
>> request. Execute accepts parameter "portal" which is previous created
>> by the bind request.
>>
>>> 2) if the request is not a parsed SQL statement then it is simply forwarded to the master backend
>>
>> What is "the request" exactly? Parse, bind, describe, execute or close?
>>
>>> Correct me if I'm wrong but wouldn't it be better not save the described mapping but simply replicate all PARSE requests?
>>
>> No. Remember that Pgpool-II needs to take care of two or more
>> PostgreSQL servers. For example, BEGIN or COMMIT must be sent to both
>> PostgreSQL servers. A DML/DDL statement must be sent to primary. A
>> pure read only SELECT can be sent to either primary or standby.
>>
>> So Pgpool-II always need to remember to which PostgreSQL server the
>> request message was sent. Otherwise Pgpool-II cannot decicde which
>> socket corresponding to PostgreSQL needs to be read while expecting
>> responses from PostgreSQL servers. If a PostgreSQL server does not
>> send response, Pgpool-II will wait the socket forever, which is
>> often seen as a "hang up".
>>
>> Another thing Pgpool-II needs to be careful is, "sync" message. Until
>> sync message is sent to backend, PostgreSQL will not return any reply.
>>
>> Also Pgpool-II needs to remember the exact sequence of sent messages
>> to backend. For example, if pase(BEGIN), bind(BEGIN), execute(BEGIN),
>> parse(SELECT), bind(SELECT), execute(SELECT), syncw were sent to
>> backend, The reply will be arrive in the order:
>>
>> parse complete(comes from both backend)
>> bind complete(comes from both backend)
>> command complete(comes from both backend)
>> parse complete(comes from only standby)
>> bind complete(comes from only standby)
>> command complete(comes from only standby)
>>
>>> - There is one CONTRA in this proposal - performance. But from my perspective it is not very critical because usually there are not many parsed (prepared from Java perspective) requests of different types in one transaction. It the transaction is long then the logic simply expects some delays, and any way the parse message is already being sent the selected backend.
>>>
>>> - The very big PRO here is that the logic of Pgpool will be very Straightforward and you will not be managing extra IFs in the code, one day possibly you will face the 'spaghetti code' problem. This is what you are fighting to now as it seems to me.
>>
>> Right.
>>
>>> We are ready to perform investigation and provide you the performance test results - compare execution times for PARSED messages against NOT PARSED messages. I believe the proposed by me concept was implemented earlier in 3.4.X versions of Pgpool.
>>
>> No. 3.4 version or beofore Pgpool sends a sync (more precisely a
>> variand of sync, called "flush") message to backend each time
>> parse/bind/describe/execute. This produces lots of packet exchange
>> between Pgpool and PostgreSQL, which makes the performance was pretty
>> bad.
>>
>>> To be honest we have several C++ clients for Postgres and after deep investigation we switched off PARSED messages in favor of 'Simple queries'. This is because we were not satisfied with execution plans created by Postgres.
>>
>> To be honest, extended query message was not well designed in
>> PostgreSQL in the first place. I recommend to use simple query
>> protocol.
>>
>>> P/S: These are just my thoughts.
>>>
>>>
>>> Best Regards,
>>>
>>> Sergey.
>>>
>>> ________________________________
>>> From: Sergey Kim
>>> Sent: Friday, March 17, 2017 8:30 AM
>>> To: Tatsuo Ishii
>>> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
>>> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>>>
>>>
>>> Tatsuo,
>>>
>>> the problem is reproduced with this patch (((
>>>
>>>
>>> There are also 2 strange facts:
>>>
>>> 1) Pgpool forwards all requests to backend 0 nevertheless the next configuration is in place:
>>>
>>> backend_hostname0='a.db.node'
>>> backend_port0=15432
>>> backend_weight0=0
>>> backend_data_directory0 = '/var/lib/pgsql/9.6/data'
>>> backend_flag0 = 'ALLOW_TO_FAILOVER'
>>>
>>> backend_hostname1='b.db.node'
>>> backend_port1=15432
>>> backend_weight1=100
>>> backend_data_directory1 = '/var/lib/pgsql/9.6/data'
>>> backend_flag1 = 'ALLOW_TO_FAILOVER'
>>>
>>> Created by me test #271 easily confirms this fact.
>>>
>>> 2) We didn't detect the clean root cause but our system 'hangs' on startup until we kill (killall -9 pgpool) pgpool processes. Only after that killing it continues starting with error
>>>
>>> When this 'hang' happens we the following pgpool log:
>>>
>>> 2017-03-17T08:28:31.249651+03:00 OAA-54999c4d7735 pgpool[25614]: [3620-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.249954+03:00 OAA-54999c4d7735 pgpool[25614]: [3621-1] LOG: DB node id: 0 backend pid: 25808 statement: B message
>>> 2017-03-17T08:28:31.250122+03:00 OAA-54999c4d7735 pgpool[25614]: [3621-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.250285+03:00 OAA-54999c4d7735 pgpool[25614]: [3622-1] LOG: DB node id: 0 backend pid: 25808 statement: D message
>>> 2017-03-17T08:28:31.250467+03:00 OAA-54999c4d7735 pgpool[25614]: [3622-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.250623+03:00 OAA-54999c4d7735 pgpool[25614]: [3623-1] LOG: DB node id: 0 backend pid: 25808 statement: Execute: select 1 from domain_registration_tlds where tld_name = 'ac'
>>> 2017-03-17T08:28:31.250799+03:00 OAA-54999c4d7735 pgpool[25614]: [3623-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.255389+03:00 OAA-54999c4d7735 pgpool[25614]: [3624-1] LOG: DB node id: 0 backend pid: 25808 statement: B message
>>> 2017-03-17T08:28:31.255628+03:00 OAA-54999c4d7735 pgpool[25614]: [3624-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.255852+03:00 OAA-54999c4d7735 pgpool[25614]: [3625-1] LOG: DB node id: 1 backend pid: 23137 statement: B message
>>> 2017-03-17T08:28:31.256071+03:00 OAA-54999c4d7735 pgpool[25614]: [3625-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.256306+03:00 OAA-54999c4d7735 pgpool[25614]: [3626-1] LOG: DB node id: 0 backend pid: 25808 statement: Execute: COMMIT
>>> 2017-03-17T08:28:31.256511+03:00 OAA-54999c4d7735 pgpool[25614]: [3626-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:31.256681+03:00 OAA-54999c4d7735 pgpool[25614]: [3627-1] LOG: DB node id: 1 backend pid: 23137 statement: Execute: COMMIT
>>> 2017-03-17T08:28:31.256847+03:00 OAA-54999c4d7735 pgpool[25614]: [3627-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:34.977877+03:00 OAA-54999c4d7735 pgpool[25614]: [3628-1] LOG: DB node id: 1 backend pid: 23137 statement: Parse:
>>> 2017-03-17T08:28:34.978159+03:00 OAA-54999c4d7735 pgpool[25614]: [3628-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:34.978405+03:00 OAA-54999c4d7735 pgpool[25614]: [3629-1] LOG: DB node id: 0 backend pid: 25808 statement: Parse:
>>> 2017-03-17T08:28:34.978694+03:00 OAA-54999c4d7735 pgpool[25614]: [3629-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:34.978952+03:00 OAA-54999c4d7735 pgpool[25614]: [3630-1] LOG: DB node id: 0 backend pid: 25808 statement: B message
>>> 2017-03-17T08:28:34.979191+03:00 OAA-54999c4d7735 pgpool[25614]: [3630-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:34.979434+03:00 OAA-54999c4d7735 pgpool[25614]: [3631-1] LOG: DB node id: 0 backend pid: 25808 statement: D message
>>> 2017-03-17T08:28:34.979679+03:00 OAA-54999c4d7735 pgpool[25614]: [3631-2] LOCATION: pool_proto_modules.c:3202
>>> 2017-03-17T08:28:34.979929+03:00 OAA-54999c4d7735 pgpool[25614]: [3632-1] LOG: DB node id: 0 backend pid: 25808 statement: Execute:
>>> 2017-03-17T08:28:34.980171+03:00 OAA-54999c4d7735 pgpool[25614]: [3632-2] LOCATION: pool_proto_modules.c:3202
>>>
>>> Sergey.
>>>
>>>
>>> ________________________________
>>> From: Tatsuo Ishii <ishii at sraoss.co.jp>
>>> Sent: Friday, March 17, 2017 5:24 AM
>>> To: Sergey Kim
>>> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
>>> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>>>
>>> Sergey,
>>>
>>> Thanks for the testing.
>>>
>>>> It seems the pgpool forwards the "parse" message to the backend
>>>> #0. But it seems this should not happen.
>>>
>>> Yes, you are right.
>>>
>>> I found a bug with the code which could cause the problem.
>>>
>>> Execute() mistakenly set the writing transaction flag even if a write
>>> query is issued (in particular case, "BEGIN"). The reason why it did
>>> not found before was, the code path only works when the transaction
>>> state is 'T' (in transaction). Before it was only set at
>>> CommandComplete but previous commit set the state at Execute(). This
>>> leads to a SELECT not being load balanced.
>>>
>>> Attached patch tries to fix the problem. I also pushed the changes to
>>> the git repository.
>>>
>>> Best regards,
>>> --
>>> Tatsuo Ishii
>>> SRA OSS, Inc. Japan
>>> English: http://www.sraoss.co.jp/index_en.php
>>> Japanese:http://www.sraoss.co.jp
>>>
>>>> Tatsuo,
>>>>
>>>>
>>>> We performed series of different tests, and every time application fails in different cases. But having compared the failed cases against their normal executions we extracted the following log case(s):
>>>>
>>>> It seems the pgpool forwards the "parse" message to the backend #0. But it seems this should not happen.
>>>>
>>>>
>>>> Log of normal execution:
>>>>
>>>> 2017-03-16T17:07:45.250703+03:00 OAA-54999c4d7735 pgpool[16386]: [4643-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: Execute: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T17:07:45.251667+03:00 OAA-54999c4d7735 pgpool[16386]: [4643-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.251849+03:00 OAA-54999c4d7735 pgpool[16386]: [4644-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: B message
>>>> 2017-03-16T17:07:45.252098+03:00 OAA-54999c4d7735 pgpool[16386]: [4644-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.252252+03:00 OAA-54999c4d7735 pgpool[16386]: [4645-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: Execute: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T17:07:45.253172+03:00 OAA-54999c4d7735 pgpool[16386]: [4645-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.253326+03:00 OAA-54999c4d7735 pgpool[16386]: [4646-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 1 backend pid: 20117 statement: Parse: select current_schema()
>>>> 2017-03-16T17:07:45.253470+03:00 OAA-54999c4d7735 pgpool[16386]: [4646-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.253628+03:00 OAA-54999c4d7735 pgpool[16386]: [4647-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 1 backend pid: 20117 statement: B message
>>>> 2017-03-16T17:07:45.253791+03:00 OAA-54999c4d7735 pgpool[16386]: [4647-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.253947+03:00 OAA-54999c4d7735 pgpool[16386]: [4648-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 1 backend pid: 20117 statement: D message
>>>> 2017-03-16T17:07:45.254093+03:00 OAA-54999c4d7735 pgpool[16386]: [4648-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.254239+03:00 OAA-54999c4d7735 pgpool[16386]: [4649-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 1 backend pid: 20117 statement: Execute: select current_schema()
>>>> 2017-03-16T17:07:45.254385+03:00 OAA-54999c4d7735 pgpool[16386]: [4649-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.254540+03:00 OAA-54999c4d7735 pgpool[16386]: [4650-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: Parse: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'
>>>> 2017-03-16T17:07:45.254693+03:00 OAA-54999c4d7735 pgpool[16386]: [4650-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.254855+03:00 OAA-54999c4d7735 pgpool[16386]: [4651-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: B message
>>>> 2017-03-16T17:07:45.255015+03:00 OAA-54999c4d7735 pgpool[16386]: [4651-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.255169+03:00 OAA-54999c4d7735 pgpool[16386]: [4652-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: D message
>>>> 2017-03-16T17:07:45.255308+03:00 OAA-54999c4d7735 pgpool[16386]: [4652-2] 2017-03-16 17:07:45: pid 16386:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:07:45.255445+03:00 OAA-54999c4d7735 pgpool[16386]: [4653-1] 2017-03-16 17:07:45: pid 16386:LOG: DB node id: 0 backend pid: 17303 statement: Execute: SELECT t.typname,t.oid FROM pg_catalog.pg_type t JOIN pg_catalog.pg_namespace n ON (t.typnamespace = n.oid) WHERE n.nspname != 'pg_toast'
>>>>
>>>>
>>>> The failed execution:
>>>>
>>>> FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T17:49:42.503476+03:00 OAA-54999c4d7735 pgpool[21183]: [3116-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.503643+03:00 OAA-54999c4d7735 pgpool[21183]: [3117-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 0 backend pid: 21241 statement: B message
>>>> 2017-03-16T17:49:42.503858+03:00 OAA-54999c4d7735 pgpool[21183]: [3117-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.504016+03:00 OAA-54999c4d7735 pgpool[21183]: [3118-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 0 backend pid: 21241 statement: Execute: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T17:49:42.504765+03:00 OAA-54999c4d7735 pgpool[21183]: [3118-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.574664+03:00 OAA-54999c4d7735 pgpool[21183]: [3119-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 1 backend pid: 21152 statement: Parse: select current_schema()
>>>> 2017-03-16T17:49:42.574941+03:00 OAA-54999c4d7735 pgpool[21183]: [3119-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.575109+03:00 OAA-54999c4d7735 pgpool[21183]: [3120-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 0 backend pid: 21241 statement: Parse: select current_schema()
>>>> 2017-03-16T17:49:42.575286+03:00 OAA-54999c4d7735 pgpool[21183]: [3120-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.575455+03:00 OAA-54999c4d7735 pgpool[21183]: [3121-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 0 backend pid: 21241 statement: B message
>>>> 2017-03-16T17:49:42.575630+03:00 OAA-54999c4d7735 pgpool[21183]: [3121-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.575790+03:00 OAA-54999c4d7735 pgpool[21183]: [3122-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 0 backend pid: 21241 statement: D message
>>>> 2017-03-16T17:49:42.575931+03:00 OAA-54999c4d7735 pgpool[21183]: [3122-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.576082+03:00 OAA-54999c4d7735 pgpool[21183]: [3123-1] 2017-03-16 17:49:42: pid 21183:LOG: DB node id: 0 backend pid: 21241 statement: Execute: select current_schema()
>>>> 2017-03-16T17:49:42.576230+03:00 OAA-54999c4d7735 pgpool[21183]: [3123-2] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T17:49:42.576376+03:00 OAA-54999c4d7735 pgpool[21183]: [3124-1] 2017-03-16 17:49:42: pid 21183:FATAL: failed to read kind from backend
>>>> 2017-03-16T17:49:42.576522+03:00 OAA-54999c4d7735 pgpool[21183]: [3124-2] 2017-03-16 17:49:42: pid 21183:DETAIL: kind mismatch among backends. Possible last query was: "select current_schema()" kind details are: 0[Z] 1[1]
>>>> 2017-03-16T17:49:42.576676+03:00 OAA-54999c4d7735 pgpool[21183]: [3124-3] 2017-03-16 17:49:42: pid 21183:HINT: check data consistency among db nodes
>>>> 2017-03-16T17:49:42.576815+03:00 OAA-54999c4d7735 pgpool[21183]: [3124-4] 2017-03-16 17:49:42: pid 21183:LOCATION: pool_process_query.c:3731
>>>> 2017-03-16T17:49:42.580320+03:00 OAA-54999c4d7735 pgpool[21175]: [9-1] 2017-03-16 17:49:42: pid 21175:LOG: child process with pid: 21183 exits with status 512
>>>>
>>>>
>>>> ________________________________
>>>> From: Sergey Kim
>>>> Sent: Thursday, March 16, 2017 2:48 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,
>>>>
>>>>
>>>> we continue attempts to reproduce the problem in a self contained test.
>>>>
>>>>
>>>> BTW plese see the attached log file of pgpool. Probably it can help.
>>>>
>>>>
>>>>
>>>> Sergey.
>>>>
>>>>
>>>> ________________________________
>>>> From: Sergey Kim
>>>> Sent: Thursday, March 16, 2017 11:31 AM
>>>> To: Tatsuo Ishii
>>>> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
>>>> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>>>>
>>>>
>>>> Hi Tatsuo,
>>>>
>>>>
>>>> the verification failed again (((
>>>>
>>>>
>>>> Though test created tests could pass smoothly the system failed to start with error (kind mismatch among backends. Possible last query was: "select current_schema()" kind details are: 0[Z] 1[1]) which is detected in pgpool logs. Now we are fighting to create the artificial test.
>>>>
>>>>
>>>> See the pgpool logs:
>>>>
>>>> 2017-03-16T11:20:56.401312+03:00 OAA-54999c4d7735 pgpool[1213]: [25442-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: B message
>>>> 2017-03-16T11:20:56.401450+03:00 OAA-54999c4d7735 pgpool[1213]: [25442-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.401586+03:00 OAA-54999c4d7735 pgpool[1213]: [25443-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: Execute: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T11:20:56.402316+03:00 OAA-54999c4d7735 pgpool[1213]: [25443-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.402462+03:00 OAA-54999c4d7735 pgpool[1213]: [25444-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: B message
>>>> 2017-03-16T11:20:56.402608+03:00 OAA-54999c4d7735 pgpool[1213]: [25444-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.402745+03:00 OAA-54999c4d7735 pgpool[1213]: [25445-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: Execute: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T11:20:56.403474+03:00 OAA-54999c4d7735 pgpool[1213]: [25445-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.403614+03:00 OAA-54999c4d7735 pgpool[1213]: [25446-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: B message
>>>> 2017-03-16T11:20:56.403748+03:00 OAA-54999c4d7735 pgpool[1213]: [25446-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.403884+03:00 OAA-54999c4d7735 pgpool[1213]: [25447-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: Execute: SELECT typinput='array_in'::regproc, typtype FROM pg_catalog.pg_type LEFT JOIN (select ns.oid as nspoid, ns.nspname, r.r from pg_namespace as ns join ( select s.r, (current_schemas(false))[s.r] as nspname from generate_series(1, array_upper(current_schemas(false), 1)) as s(r) ) as r using ( nspname ) ) as sp ON sp.nspoid = typnamespace WHERE typname = $1 ORDER BY sp.r, pg_type.oid DESC LIMIT 1
>>>> 2017-03-16T11:20:56.404543+03:00 OAA-54999c4d7735 pgpool[1213]: [25447-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.404612+03:00 OAA-54999c4d7735 pgpool[1213]: [25448-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 1 backend pid: 12520 statement: Parse: select current_schema()
>>>> 2017-03-16T11:20:56.404678+03:00 OAA-54999c4d7735 pgpool[1213]: [25448-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.404736+03:00 OAA-54999c4d7735 pgpool[1213]: [25449-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: Parse: select current_schema()
>>>> 2017-03-16T11:20:56.404839+03:00 OAA-54999c4d7735 pgpool[1213]: [25449-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.404899+03:00 OAA-54999c4d7735 pgpool[1213]: [25450-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: B message
>>>> 2017-03-16T11:20:56.404957+03:00 OAA-54999c4d7735 pgpool[1213]: [25450-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.405013+03:00 OAA-54999c4d7735 pgpool[1213]: [25451-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: D message
>>>> 2017-03-16T11:20:56.405069+03:00 OAA-54999c4d7735 pgpool[1213]: [25451-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.405144+03:00 OAA-54999c4d7735 pgpool[1213]: [25452-1] 2017-03-16 11:20:56: pid 1213:LOG: DB node id: 0 backend pid: 1708 statement: Execute: select current_schema()
>>>> 2017-03-16T11:20:56.405219+03:00 OAA-54999c4d7735 pgpool[1213]: [25452-2] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_proto_modules.c:3211
>>>> 2017-03-16T11:20:56.405282+03:00 OAA-54999c4d7735 pgpool[1213]: [25453-1] 2017-03-16 11:20:56: pid 1213:FATAL: failed to read kind from backend
>>>> 2017-03-16T11:20:56.405346+03:00 OAA-54999c4d7735 pgpool[1213]: [25453-2] 2017-03-16 11:20:56: pid 1213:DETAIL: kind mismatch among backends. Possible last query was: "select current_schema()" kind details are: 0[Z] 1[1]
>>>> 2017-03-16T11:20:56.405400+03:00 OAA-54999c4d7735 pgpool[1213]: [25453-3] 2017-03-16 11:20:56: pid 1213:HINT: check data consistency among db nodes
>>>> 2017-03-16T11:20:56.405483+03:00 OAA-54999c4d7735 pgpool[1213]: [25453-4] 2017-03-16 11:20:56: pid 1213:LOCATION: pool_process_query.c:3731
>>>> 2017-03-16T11:20:56.405643+03:00 OAA-54999c4d7735 pgpool[10877]: [22781-1] 2017-03-16 11:20:56: pid 10877:LOG: child process with pid: 1213 exits with status 512
>>>>
>>>>
>>>>
>>>> Sergey.
>>>> ________________________________
>>>> From: Tatsuo Ishii <ishii at sraoss.co.jp>
>>>> Sent: Thursday, March 16, 2017 8:29 AM
>>>> To: Sergey Kim
>>>> Cc: pgpool-hackers at pgpool.net; Boris Voskanov
>>>> Subject: Re: [pgpool-committers: 3836] pgpool: Branch refs/heads/bug271 was created
>>>>
>>>> Hi Sergey,
>>>>
>>>> Attached is a patch against master branch as usual.
>>>> I also push the changes to the git repository.
>>>>
>>>> https://git.postgresql.org/gitweb/?p=pgpool2.git;a=shortlog;h=refs/heads/bug271
>>>>
>>>> When an INSERT is executed in a transaction, a "writing_transaction"
>>>> is set. The flag is checked by a succeeding SELECT to decide if
>>>> parse_before_bind (which resend the parse message to primary node if
>>>> it is executed on the standby) needs to be executed. The flag is
>>>> reset when a command complete message for BEGIN is arrived. Problem
>>>> is, it is possible that the command complete message could arrive
>>>> before the bind for the SELECT is executed, and at this point the flag
>>>> is already cleared.
>>>>
>>>> Solution is, do not reset the flag when the command complete message
>>>> arrives if in streaming replication mode.
>>>>
>>>> I tested using your tool and the test case #231 and #271 have been
>>>> passed here.
>>>>
>>>> Best regards,
>>>> --
>>>> Tatsuo Ishii
>>>> SRA OSS, Inc. Japan
>>>> English: http://www.sraoss.co.jp/index_en.php
SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
www.sraoss.co.jp
We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
> SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
www.sraoss.co.jp
We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
> www.sraoss.co.jp<http://www.sraoss.co.jp>
> We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
>
>
>
>>>> Japanese:http://www.sraoss.co.jp
>>>>
>>>>> 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
> SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
www.sraoss.co.jp
We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
> www.sraoss.co.jp<http://www.sraoss.co.jp>
SRA OSS, Inc. ???? - PostgreSQL ???????????????????????????<http://www.sraoss.co.jp/>
www.sraoss.co.jp
sra oss ??????????????????????????????????????????????? ...
> We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
>
>
>
>> SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
www.sraoss.co.jp
We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
>> www.sraoss.co.jp<http://www.sraoss.co.jp>
SRA OSS, Inc. ???? - PostgreSQL ???????????????????????????<http://www.sraoss.co.jp/>
www.sraoss.co.jp
sra oss ??????????????????????????????????????????????? ...
>> We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
>>
>>
>>
>>> SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
www.sraoss.co.jp
We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
> SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
SRA OSS, Inc. Japan<http://www.sraoss.co.jp/index_en.php>
www.sraoss.co.jp
We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
> www.sraoss.co.jp<http://www.sraoss.co.jp>
SRA OSS, Inc. ???? - PostgreSQL ???????????????????????????<http://www.sraoss.co.jp/>
www.sraoss.co.jp
sra oss ??????????????????????????????????????????????? ...
> We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
>
>
>
>>> www.sraoss.co.jp<http://www.sraoss.co.jp>
SRA OSS, Inc. ???? - PostgreSQL ???????????????????????????<http://www.sraoss.co.jp/>
www.sraoss.co.jp
sra oss ??????????????????????????????????????????????? ...
> SRA OSS, Inc. ???? - PostgreSQL ???????????????????????????<http://www.sraoss.co.jp/>
> www.sraoss.co.jp<http://www.sraoss.co.jp>
SRA OSS, Inc. ???? - PostgreSQL ???????????????????????????<http://www.sraoss.co.jp/>
www.sraoss.co.jp
sra oss ??????????????????????????????????????????????? ...
> sra oss ??????????????????????????????????????????????? ...
>
>
>
>>> We, SRA OSS, Inc., as a total solution supplier of open source software, provide consulting, software support and training services, as well as supply the PostgreSQL ...
>>>
>>>
>>>
>>>>> 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/20170320/d3e62559/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pgpool_test.tar.gz
Type: application/gzip
Size: 686005 bytes
Desc: pgpool_test.tar.gz
URL: <http://www.sraoss.jp/pipermail/pgpool-hackers/attachments/20170320/d3e62559/attachment-0001.bin>
More information about the pgpool-hackers
mailing list