Subject: Re: Built-in connection pooler
To: Tomas Vondra <tomas.vondra@2ndquadrant.com>
Cc: Ryan Lambert <ryan@rustprooflabs.com>,
 Thomas Munro <thomas.munro@gmail.com>,
 PostgreSQL Hackers <pgsql-hackers@postgresql.org>,
 Bruce Momjian <bruce@momjian.us>, Dimitri Fontaine <dim@tapoueh.org>
References: <139e59f5-15bc-13ff-58e2-7a2229041236@postgrespro.ru>
 <CA+hUKGJ-mm50BXGgo-w2AnnPJTCydbzJifSHUOSimBfcG1Xw=g@mail.gmail.com>
 <fb171cef-95ad-af8b-e38d-e52eb84dae6b@postgrespro.ru>
 <78d43611-668e-a4e2-4796-dbffccc2512d@postgrespro.ru>
 <CAN-V+g8h5HFQj_Y7HzFvcuCzOL=F8VDadNxCwQ8exkKOYB8KJA@mail.gmail.com>
 <da9d967a-e5ef-1966-6f75-71d0e3bb7f4d@postgrespro.ru>
 <CAN-V+g--21y8=GhWFoTGqU0UKxSgp0ZFKAMZM2KbcDjey-Ty8w@mail.gmail.com>
 <a162afc7-09be-9596-41c3-2576412c3f81@postgrespro.ru>
 <CAN-V+g99RvCr5GCRkn_H6k2Mom76HcAqFrfzQxuFNEa-Hip5Mw@mail.gmail.com>
 <42c78b0e-e2ad-7920-3b31-37a81c9ba83b@postgrespro.ru>
 <20190726202437.2svtvcisiujqaoky@development>
From: Konstantin Knizhnik <k.knizhnik@postgrespro.ru>
Message-ID: <e51f30ca-92e8-49ab-16ac-9ded35c8f8fd@postgrespro.ru>
Date: Tue, 30 Jul 2019 14:06:38 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101
 Thunderbird/60.2.1
MIME-Version: 1.0
In-Reply-To: <20190726202437.2svtvcisiujqaoky@development>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8bit
Content-Language: en-US
Precedence: bulk


On 26.07.2019 23:24, Tomas Vondra wrote:
> Secondly, when trying this
>  pgbench -p 5432 -U x -i -s 1 test
>  pgbench -p 6543 -U x -c 24 -C -T 10 test
>
> it very quickly locks up, with plenty of non-granted locks in pg_locks,
> but I don't see any interventions by deadlock detector so I presume
> the issue is somewhere else. I don't see any such issues whe running
> without the connection pool or without the -C option:
>
>  pgbench -p 5432 -U x -c 24 -C -T 10 test
>  pgbench -p 6543 -U x -c 24 -T 10 test
>
> This is with default postgresql.conf, except for
>
>  connection_proxies = 4
>

After some investigation I tend to think that it is problem of pgbench.
It synchronously establishes new connection:

#0  0x00007f022edb7730 in __poll_nocancel () at 
../sysdeps/unix/syscall-template.S:84
#1  0x00007f022f7ceb77 in pqSocketPoll (sock=4, forRead=1, forWrite=0, 
end_time=-1) at fe-misc.c:1164
#2  0x00007f022f7cea32 in pqSocketCheck (conn=0x1273bf0, forRead=1, 
forWrite=0, end_time=-1) at fe-misc.c:1106
#3  0x00007f022f7ce8f2 in pqWaitTimed (forRead=1, forWrite=0, 
conn=0x1273bf0, finish_time=-1) at fe-misc.c:1038
#4  0x00007f022f7c0cdb in connectDBComplete (conn=0x1273bf0) at 
fe-connect.c:2029
#5  0x00007f022f7be71f in PQconnectdbParams (keywords=0x7ffc1add5640, 
values=0x7ffc1add5680, expand_dbname=1) at fe-connect.c:619
#6  0x0000000000403a4e in doConnect () at pgbench.c:1185
#7  0x0000000000407715 in advanceConnectionState (thread=0x1268570, 
st=0x1261778, agg=0x7ffc1add5880) at pgbench.c:2919
#8  0x000000000040f1b1 in threadRun (arg=0x1268570) at pgbench.c:6121
#9  0x000000000040e59d in main (argc=10, argv=0x7ffc1add5f98) at 
pgbench.c:5848

I.e. is starts normal transaction in one connection (few 
select/update/insert statement which are part of pgbench standard 
transaction)
and at the same time tries to establish new connection.
As far as built-in connection pooler performs transaction level 
scheduling, first session is grabbing backend until end of transaction. 
So until this transaction is
completed backend will not be able to process some other transaction or 
accept new connection. But pgbench is completing this transaction 
because it is blocked
in waiting response for new connection.

The problem can be easily reproduced with just two connections if 
connection_proxies=1 and session_pool_size=1:

  pgbench -p 6543 -n -c 2 -C -T 10 postgres
<hanged>

knizhnik@knizhnik:~/postgrespro.ee11$ ps aux | fgrep postgres
knizhnik 14425  0.0  0.1 172220 17540 ?        Ss   09:48   0:00 
/home/knizhnik/postgresql.builtin_pool/dist/bin/postgres -D pgsql.proxy
knizhnik 14427  0.0  0.0 183440  5052 ?        Ss   09:48   0:00 
postgres: connection proxy
knizhnik 14428  0.0  0.0 172328  4580 ?        Ss   09:48   0:00 
postgres: checkpointer
knizhnik 14429  0.0  0.0 172220  4892 ?        Ss   09:48   0:00 
postgres: background writer
knizhnik 14430  0.0  0.0 172220  7692 ?        Ss   09:48   0:00 
postgres: walwriter
knizhnik 14431  0.0  0.0 172760  5640 ?        Ss   09:48   0:00 
postgres: autovacuum launcher
knizhnik 14432  0.0  0.0  26772  2292 ?        Ss   09:48   0:00 
postgres: stats collector
knizhnik 14433  0.0  0.0 172764  5884 ?        Ss   09:48   0:00 
postgres: logical replication launcher
knizhnik 14434  0.0  0.0  22740  3084 pts/21   S+   09:48   0:00 pgbench 
-p 6543 -n -c 2 -C -T 10 postgres
knizhnik 14435  0.0  0.0 173828 13400 ?        Ss   09:48   0:00 
postgres: knizhnik postgres [local] idle in transaction
knizhnik 21927  0.0  0.0  11280   936 pts/19   S+   11:58   0:00 grep -F 
--color=auto postgres

But if you run each connection in separate thread, then this test is 
normally completed:

nizhnik@knizhnik:~/postgresql.builtin_pool$ pgbench -p 6543 -n -j 2 -c 2 
-C -T 10 postgres
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: simple
number of clients: 2
number of threads: 2
duration: 10 s
number of transactions actually processed: 9036
latency average = 2.214 ms
tps = 903.466234 (including connections establishing)
tps = 1809.317395 (excluding connections establishing)


-- 

Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company