View Issue Details

IDProjectCategoryView StatusLast Update
0000377Pgpool-IIBugpublic2018-01-18 22:13
ReporterancoronAssigned Tot-ishii 
PrioritynormalSeveritymajorReproducibilitysometimes
Status resolvedResolutionopen 
Product Version3.6.7 
Target Version3.6.9Fixed in Version 
Summary0000377: Getting stuck on waiting on wrong backend for kind
DescriptionI 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 InformationI am currently running with load-balancing mode OFF and it indeed seems to provide a workaround.
Tagsextended queries, load balancing, pgpool in load balancing mode

Activities

ancoron

2018-01-16 18:15

reporter  

pgpool.log (224,222 bytes)

ancoron

2018-01-17 01:50

reporter   ~0001897

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).

ancoron

2018-01-17 03:05

reporter   ~0001898

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.

0001-Fix-queries-hanging-in-parse_before_bind-with-extend.patch (1,478 bytes)
From 5b53428280a5d871e505536fbcea02a43d8d5128 Mon Sep 17 00:00:00 2001
From: Ancoron Luciferis <ancoron.luciferis@gmail.com>
Date: Tue, 16 Jan 2018 17:08:47 +0100
Subject: [PATCH] Fix queries hanging in parse_before_bind with extended
 protocol and replication + load-balancing.

In case the client sends a BIND message for a query
that has not yet been parsed by the executing node,
the PARSE will be executed before attempting to BIND
the parameters.

However, during the execution of the PARSE, the session
context is not set to in_progress, which leads to wrong
backend validity tests in read_kind_from_backend which
in turn makes the process wait on a backend which is not
going to send anything.

Fixes bug #377.
---
 src/protocol/pool_proto_modules.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 931e3af6..1021a336 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -1356,8 +1356,12 @@ POOL_STATUS Bind(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
 							   query_context->parse_tree);
 		}
 
-		if (parse_before_bind(frontend, backend, parse_msg, bind_msg) != POOL_CONTINUE)
+		pool_set_query_in_progress();
+		if (parse_before_bind(frontend, backend, parse_msg, bind_msg) != POOL_CONTINUE) {
+			pool_unset_query_in_progress();
 			return POOL_END;
+		}
+		pool_unset_query_in_progress();
 	}
 
 	/*
-- 
2.14.1

t-ishii

2018-01-18 10:31

developer   ~0001902

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.

t-ishii

2018-01-18 10:33

developer  

1.data (1,245 bytes)

t-ishii

2018-01-18 11:30

developer   ~0001903

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.

parse_before_bind.diff (396 bytes)
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 362c108..631fa5d 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -3270,6 +3270,8 @@ static POOL_STATUS parse_before_bind(POOL_CONNECTION *frontend,
 
 	if (!SL_MODE && parse_was_sent)
 	{
+		pool_set_query_in_progress();
+
 		while (kind != '1')
 		{
 			PG_TRY();

ancoron

2018-01-18 18:01

reporter   ~0001904

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.

t-ishii

2018-01-18 18:36

developer   ~0001905

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.

Issue History

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