View Revisions: Issue #194

Summary 0000194: "statement timeout" causes kind mismatch errors
Revision 2016-05-06 20:19 by t-ishii
Steps To Reproduce $ pgbench -n -h localhost -p 9999 --protocol=extended -c 3 -t 10 -f sleep.sql

Client 1 aborted in state 16: ERROR: kind mismatch among backends. Possible last query was: "Parse: END;" kind details are: 0[E: canceling statement due to statement timeout] 1[1] 2[1]
HINT: check data consistency among db nodes

pgpool-II log
--------------
May 6 16:19:18 pg1 pgpool[19398]: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 19488 statement: END; message: canceling statement due to statement timeout
May 6 16:19:18 pg1 pgpool[19398]: Parse: Error or notice message from backend: : DB node id: 0 backend pid: 19488 statement: END; message: canceling statement due to statement timeout
May 6 16:19:18 pg1 pgpool[19398]: DB node id: 2 backend pid: 8238 statement: Parse: END;
May 6 16:19:18 pg1 pgpool[19398]: read_kind_from_backend: 2 th kind 1 does not match with master or majority connection kind E
May 6 16:19:18 pg1 pgpool[19398]: kind mismatch among backends. Possible last query was: "Parse: END;" kind details are: 0[E: canceling statement due to statement timeout] 2[1]


PostgreSQL log (2)
------------------
May 6 16:19:03 pg1 postgres[19488]: [35-1] [572c4567.4c20-17][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)DEBUG: parse pgpool19398: SELECT current_setting('transaction_isolation');
May 6 16:19:03 pg1 postgres[19488]: [36-1] [572c4567.4c20-18][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)DEBUG: StartTransactionCommand
May 6 16:19:03 pg1 postgres[19488]: [37-1] [572c4567.4c20-19][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)DEBUG: bind pgpool19398 to pgpool19398
May 6 16:19:03 pg1 postgres[19488]: [38-1] [572c4567.4c20-20][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)LOG: execute pgpool19398/pgpool19398: SELECT current_setting('transaction_isolation');
May 6 16:19:18 pg1 postgres[19488]: [39-1] [572c4567.4c20-21][0][57014](postgres,postgres,10.10.10.103(47899),pgbench)ERROR: canceling statement due to statement timeout


pgpool.conf
-----------
 master_slave_mode = on
 load_balance_mode = on
 debug_level = 1 # (for debug)
 backend_*0 = ... # (more than 2 backends)
 backend_*1 = ...
 backend_*2 = ...

postgresql.conf
---------------
 statement_timeout = 10s
 log_min_messages = debug3 # (for debug)

sleep.sql
---------
BEGIN;
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
END;
Revision 2016-05-06 19:34 by t-ishii
Steps To Reproduce
$ pgbench -n -h localhost -p 9999 --protocol=extended -c 3 -t 10 -f sleep.sql

Client 1 aborted in state 16: ERROR: kind mismatch among backends. Possible last query was: "Parse: END;" kind details are: 0[E: canceling statement due to statement timeout] 1[1] 2[1]
HINT: check data consistency among db nodes

pgpool-II log
--------------
May 6 16:19:18 pg1 pgpool[19398]: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 19488 statement: END; message: canceling statement due to statement timeout
May 6 16:19:18 pg1 pgpool[19398]: Parse: Error or notice message from backend: : DB node id: 0 backend pid: 19488 statement: END; message: canceling statement due to statement timeout
May 6 16:19:18 pg1 pgpool[19398]: DB node id: 2 backend pid: 8238 statement: Parse: END;
May 6 16:19:18 pg1 pgpool[19398]: read_kind_from_backend: 2 th kind 1 does not match with master or majority connection kind E
May 6 16:19:18 pg1 pgpool[19398]: kind mismatch among backends. Possible last query was: "Parse: END;" kind details are: 0[E: canceling statement due to statement timeout] 2[1]


PostgreSQL log (2)
------------------
May 6 16:19:03 pg1 postgres[19488]: [35-1] [572c4567.4c20-17][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)DEBUG: parse pgpool19398: SELECT current_setting('transaction_isolation');
May 6 16:19:03 pg1 postgres[19488]: [36-1] [572c4567.4c20-18][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)DEBUG: StartTransactionCommand
May 6 16:19:03 pg1 postgres[19488]: [37-1] [572c4567.4c20-19][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)DEBUG: bind pgpool19398 to pgpool19398
May 6 16:19:03 pg1 postgres[19488]: [38-1] [572c4567.4c20-20][0][00000](postgres,postgres,10.10.10.103(47899),pgbench)LOG: execute pgpool19398/pgpool19398: SELECT current_setting('transaction_isolation');
May 6 16:19:18 pg1 postgres[19488]: [39-1] [572c4567.4c20-21][0][57014](postgres,postgres,10.10.10.103(47899),pgbench)ERROR: canceling statement due to statement timeout


pgpool.conf
-----------
 master_slave_mode = on
 load_balance_mode = on
 debug_level = 1 # (for debug)
 backend_*0 = ... # (more than 2 backends)
 backend_*1 = ...
 backend_*2 = ...

postgresql.conf
---------------
 statement_timeout = 10s
 log_min_messages = debug3 # (for debug)

sleep.sql
---------
BEGIN;
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
  SELECT pg_sleep(1);
END;