View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000377 | Pgpool-II | Bug | public | 2018-01-16 18:15 | 2018-01-18 22:13 |
| Reporter | ancoron | Assigned To | t-ishii | ||
| Priority | normal | Severity | major | Reproducibility | sometimes |
| Status | resolved | Resolution | open | ||
| Product Version | 3.6.7 | ||||
| Target Version | 3.6.9 | ||||
| Summary | 0000377: Getting stuck on waiting on wrong backend for kind | ||||
| Description | I am running pgpool + PostgreSQL (currently 9.4.15) at 4 nodes (each node contains pgpool + pg) and a virtual IP to determine master. pgpool config excerpt: ~~~ replication_mode = on load_balance_mode = on num_init_children = 100 max_pool = 4 child_life_time = 300 child_max_connections = 0 connection_life_time = 0 client_idle_limit = 120 connection_cache = on memory_cache_enabled = off use_watchdog = on ~~~ The symptom that I am experiencing is that after some time of running the setup (usually a few hours), a certain kind of transaction gets stuck always at the very same query in the same way, just as if it would be an application-level issue - which I looked at first in-depth to exclude it being at fault. Other transactions with different queries are totally fine. It somehow seems to relate to a "SELECT FOR UPDATE", which is weird and would be a regression. I just recently upgraded the systems from Debian 8 with the official (ancient) pgpool 3.3.4 to Debian 9 and pgpool/PostgreSQL from the PGDG repositories. With pgpool 3.3.4 I did not have this kind of problem and the application was running fine for months (pgpool and PostgreSQL configuration did not change during the upgrade - only required renaming applied). The application I am running are multiple Camunda BPM instances using Apache Commons DBCP2 for connection pooling and hence, the access method is JDBC using extended queries and explicit prepared statements in most cases. The transaction that gets stuck has a series of queries as follows: ```sql BEGIN -- ...some simple SELECT's... -- pessimistic locking for coordination at application-side SELECT * FROM ACT_GE_PROPERTY WHERE NAME_ = 'deployment.lock' for update; -- next query is still fine: select B.* from ACT_GE_BYTEARRAY B inner join ( select B.NAME_, MAX(D.DEPLOY_TIME_) DEPLOY_TIME_ from ACT_GE_BYTEARRAY B inner join ACT_RE_DEPLOYMENT D on B.DEPLOYMENT_ID_ = D.ID_ where D.NAME_ = $1 and ( D.SOURCE_ is null or D.SOURCE_ = $2 ) and B.NAME_ in ($3) group by B.NAME_ ) LAST_RESOURCE on B.NAME_ = LAST_RESOURCE.NAME_ inner join ACT_RE_DEPLOYMENT D on B.DEPLOYMENT_ID_ = D.ID_ and D.DEPLOY_TIME_ = LAST_RESOURCE.DEPLOY_TIME_ and D.NAME_ = $4 and ( D.SOURCE_ is null or D.SOURCE_ = $5 ) and D.TENANT_ID_ is null ; -- the following query gets stuck: select * from ACT_RE_PROCDEF RES where KEY_ = $1 and TENANT_ID_ is null and VERSION_ = ( select max(VERSION_) from ACT_RE_PROCDEF where KEY_ = $2 and TENANT_ID_ is null ) ; ``` The thing that worries me is that the PostgreSQL backend process shows up in state "PARSE": ~~~ PID TIME CMD 22792 00:00:03 postgres: svc_bpm camunda 172.25.2.95(38334) PARSE ~~~ TCP dump reveals that PGPool does not continue to send a BIND after PostgreSQL node has sent back the completion for parse command (PGPool > PostgreSQL): ~~~ <Z >P/H <1 > ACK(<1) ~~~ The corresponding pgpool process shows the following backtrace: ~~~ #0 0x00007ffb0697f3d3 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:84 0000001 0x000055e43cff2527 in pool_check_fd (cp=cp@entry=0x55e43d559b38) at protocol/pool_process_query.c:647 0000002 0x000055e43cff2896 in pool_check_fd (cp=cp@entry=0x55e43d559b38) at protocol/pool_process_query.c:679 0000003 0x000055e43d0267c8 in pool_read (cp=0x55e43d559b38, buf=buf@entry=0x7ffffdd7de55, len=len@entry=1) at utils/pool_stream.c:163 0000004 0x000055e43cff7efc in read_kind_from_backend (frontend=frontend@entry=0x55e43d565718, backend=backend@entry=0x55e43d555708, decided_kind=decided_kind@entry=0x7ffffdd7e31f "") at protocol/pool_process_query.c:3250 0000005 0x000055e43cffe4cc in parse_before_bind (frontend=frontend@entry=0x55e43d565718, backend=backend@entry=0x55e43d555708, message=message@entry=0x55e43d5aaad8, bind_message=<optimized out>, bind_message=<optimized out>) at protocol/pool_proto_modules.c:3273 0000006 0x000055e43d0009a1 in Bind (frontend=frontend@entry=0x55e43d565718, backend=backend@entry=0x55e43d555708, len=<optimized out>, contents=contents@entry=0x55e43d56b738 "") at protocol/pool_proto_modules.c:1359 0000007 0x000055e43d0051d7 in ProcessFrontendResponse (frontend=frontend@entry=0x55e43d565718, backend=backend@entry=0x55e43d555708) at protocol/pool_proto_modules.c:2380 0000008 0x000055e43cff654d in read_packets_and_process (frontend=frontend@entry=0x55e43d565718, backend=backend@entry=0x55e43d555708, reset_request=reset_request@entry=0, state=state@entry=0x7ffffdd7eb8c, num_fields=num_fields@entry=0x7ffffdd7eb8a, cont=cont@entry=0x7ffffdd7eb94 "\001U") at protocol/pool_process_query.c:4721 0000009 0x000055e43cff7174 in pool_process_query (frontend=0x55e43d565718, backend=0x55e43d555708, reset_request=reset_request@entry=0) at protocol/pool_process_query.c:274 0000010 0x000055e43cff11c1 in do_child (fds=fds@entry=0x55e43d540130) at protocol/child.c:381 0000011 0x000055e43cfd3fb7 in fork_a_child (fds=0x55e43d540130, id=86) at main/pgpool_main.c:755 0000012 0x000055e43cfd7221 in failover () at main/pgpool_main.c:2099 0000013 0x000055e43cfd7de6 in sigusr1_interrupt_processor () at main/pgpool_main.c:1563 0000014 0x000055e43cfd7fed in pool_sleep (second=<optimized out>) at main/pgpool_main.c:2727 0000015 0x000055e43cfda35f in PgpoolMain (discard_status=<optimized out>, clear_memcache_oidmaps=<optimized out>) at main/pgpool_main.c:536 0000016 0x000055e43cfd258b in main (argc=<optimized out>, argv=0x7ffffdd8a578) at main/main.c:317 ~~~ This looks like pretty normal, actually, but evaluating some variables made me think there is a confusion on which backend to wait for (variables inside pool_check_fd): ~~~ (gdb) print fd $1 = 12 (gdb) print cp->db_node_id $2 = 2 (gdb) print cp->con_info->backend_id $3 = 0 (gdb) print cp->con_info->load_balancing_node $4 = 3 ~~~ ??? The only backend that it should be using (after determining a write transaction) is master node 0. At least that is where the two SELECT queries after the FOR UPDATE actually go. File descriptors for the pgpool process: ~~~ pgpool 15244 postgres 0r CHR 1,3 0t0 1028 /dev/null pgpool 15244 postgres 1u unix 0xffff8c0369050000 0t0 56506 type=STREAM pgpool 15244 postgres 2u unix 0xffff8c0369050000 0t0 56506 type=STREAM pgpool 15244 postgres 3r REG 253,0 275 129879 /etc/pgpool2/pool_passwd pgpool 15244 postgres 4u unix 0xffff8c0367de2400 0t0 42769 /var/run/postgresql/.s.PGSQL.5433 type=STREAM pgpool 15244 postgres 5u unix 0xffff8c0367e9e400 0t0 42756 type=DGRAM pgpool 15244 postgres 6u IPv4 42774 0t0 TCP *:5433 (LISTEN) pgpool 15244 postgres 7u IPv6 42775 0t0 TCP *:5433 (LISTEN) pgpool 15244 postgres 8u IPv4 1283577 0t0 TCP 172.25.2.49:5433->172.25.2.48:38450 (ESTABLISHED) pgpool 15244 postgres 9u IPv4 1283578 0t0 TCP 172.25.2.95:38334->172.25.2.44:postgresql (CLOSE_WAIT) pgpool 15244 postgres 10u unix 0xffff8c036a3d7400 0t0 42777 /var/run/postgresql/.s.PGSQL.9898 type=STREAM pgpool 15244 postgres 11u IPv4 42779 0t0 TCP *:9898 (LISTEN) pgpool 15244 postgres 12u IPv4 1283579 0t0 TCP 172.25.2.95:41724->172.25.2.46:postgresql (ESTABLISHED) pgpool 15244 postgres 13u IPv4 1283580 0t0 TCP 172.25.2.95:32786->172.25.2.95:postgresql (ESTABLISHED) ~~~ So, fd number 12 is actually unexpected here. Attached debug4 log from master pgpool instance for further evaluation. | ||||
| Additional Information | I am currently running with load-balancing mode OFF and it indeed seems to provide a workaround. | ||||
| Tags | extended queries, load balancing, pgpool in load balancing mode | ||||
|
|
|
|
|
I think I've found the error: While reading kind from backends, it iterates over all backends in read_kind_from_backend, which tests the backend using "VALID_BACKEND(i)". However, in the special case of parse_before_bind, executing the "P" against the master backend is not considered as "in progress": ~~~ (gdb) print session_context->in_progress $11 = 0 '\000' ~~~ This leads to "pool_is_node_to_be_sent_in_current_query" to return true for more than the backends which are "active" as per "query_context->where_to_send[i]" - it just falls through to "true" (= valid). |
|
|
Attached patch fixes the problem for me. However, IDK if this is the proper way to implement it. Would be nice to see a fix for 3.6.9 and 3.7.2. |
|
|
Thank you for an excellent analysis. I think your fix is correct.I will apply it to all supported branches (master, 3.7, 3.6, 3.5, 3.4 and 3.3) with a slight change to match with our coding standard (it's same as PostgreSQL). BTW, minimum requirements to trigger the bug are: replication mode, start transaction, write query, select query using same portal. number of DB nodes > 1. backend weight set to 1 makes sure that the bug is triggered. Also sync is necessary after BEGIN and write query. Attached is the data file for pgproto (https://github.com/tatsuo-ishii/pgproto) to reproduce the problem. |
|
|
|
|
|
I noticed that your patch uses "pool_unset_query_in_progress()". The function not only just reset the flag but also does some house keeping tasks. I think it's safer not to call it because pool_set_query_in_progress is called later on anyway. Also the call to pool_set_query_in_progress can be moved to parase_before_bind(), which looks better because only replication mode needs the flag set before executing the loop using read_kind_from_backend(). Attached is the new patch. It would be nice to know if the patch solves your problem. |
|
|
Thank you for looking into this. This was my very first patch and I didn't actually concern much about the coding standards, sorry for that. However, I can confirm that your new patch is also fixing the problem for me. |
|
|
Thank you for confirmation. Thank you again for the great analysis and initial patch! Without them the problem could not be solved. I will commit/push the patch to supported branches along with your credit. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2018-01-16 18:15 | ancoron | New Issue | |
| 2018-01-16 18:15 | ancoron | File Added: pgpool.log | |
| 2018-01-16 18:16 | ancoron | Tag Attached: extended queries | |
| 2018-01-16 18:16 | ancoron | Tag Attached: load balancing | |
| 2018-01-16 18:16 | ancoron | Tag Attached: pgpool in load balancing mode | |
| 2018-01-17 01:50 | ancoron | Note Added: 0001897 | |
| 2018-01-17 03:05 | ancoron | File Added: 0001-Fix-queries-hanging-in-parse_before_bind-with-extend.patch | |
| 2018-01-17 03:05 | ancoron | Note Added: 0001898 | |
| 2018-01-17 10:24 | t-ishii | Assigned To | => t-ishii |
| 2018-01-17 10:24 | t-ishii | Status | new => assigned |
| 2018-01-18 10:31 | t-ishii | Note Added: 0001902 | |
| 2018-01-18 10:33 | t-ishii | File Added: 1.data | |
| 2018-01-18 11:30 | t-ishii | File Added: parse_before_bind.diff | |
| 2018-01-18 11:30 | t-ishii | Note Added: 0001903 | |
| 2018-01-18 11:31 | t-ishii | Status | assigned => feedback |
| 2018-01-18 18:01 | ancoron | Note Added: 0001904 | |
| 2018-01-18 18:01 | ancoron | Status | feedback => assigned |
| 2018-01-18 18:36 | t-ishii | Note Added: 0001905 | |
| 2018-01-18 22:13 | t-ishii | Status | assigned => resolved |
| 2018-01-18 22:13 | t-ishii | Target Version | => 3.6.9 |
