pgbouncer and slow server pool increase

This post is about an issue I ran into when trying to use pgbouncer in front of Yugabyte YSQL, the postgres layer yugabyte reuses for handling relational data.

pgbouncer: https://www.pgbouncer.org

yugabyte: https://www.yugabyte.com

postgres: https://www.postgresql.org

The case for pgbouncer.

Pgbouncer is a connectionpool for postgres databases. It’s a process sitting in between the client and the actual postgres server, and separates clients from a postgres server connection by keeping a pool of connections from the clients (the socalled clients pool), and keeping a pool of connections to the postgres server (the socalled servers pool).

A postgres database connection is forked from the postmaster as an independent process when a client connects, and executes the queries on the client’s behalf. Creating a process is a timetaking and “costly” action for a computer system. The most ideal way of using postgres is to logon once with all the needed connections, and use and reuse these connections.

Sadly, a lot of database clients do not take using the database in the most ideal way into account, and perform database unfriendly connection management, such as creating and dropping connections really quick or creating an high amount of connections, or both.

pgbouncer helps in such cases with the aforementioned separation of clients and servers, and linking a client with a server connection based on the set pool mode, which can be session (a client uses a database connection for the duration of the session until disconnect), transaction (a client uses a database connection for the duration of a transaction) or statement (a client uses a database connection for each query).

The default setting for pool mode is session, based on testing it seems pgbouncer functions most optimal when using transaction mode, so (varying/huge numbers of) client connections can use a lower amount of (dedicated/steady) database connections.

The encountered issue.

I used a default Centos 8.3 image I created myself using packer, using vagrant and virtualbox. This means a lot of the machine configuration is default, using packer means the image is created using scripts. In other words: there was no configuration done by myself or someone else without me knowing it.

The server was functioning correctly, and added pgbouncer (pgbouncer is a package in EPEL), configured it and ran it. I configured pgbouncer to allow 1000 client connections (max_client_conn), and create 100 database connections (default_pool_size,min_pool_size). The way pgbouncer works is that the connections are not created when pgbouncer starts, but per database when a client requests the database from pgbouncer for the first time. I manually connected through pgbouncer and it functioned correctly. So far, so good.

Then I tested it with a synthetic load:

for n in $(1 200) do; ysqlsh -h localhost -p 6432 -c "select pg_sleep(60);" & done

What should happen is that all 200 connections get connected to pgbouncer, and pgbouncer creates 100 connections, to which 100 clients get connected and execute, and 100 clients should remain waiting to be serviced.

However, I noticed that there were only a couple of connections created to the database server, something like 2 or 3, and the amount was slowly increasing. It also lead to pgbouncer eventually killing the connections, because query_wait_timeout is set to 120 (seconds) by default, and with the low number of connections, some sessions do exceed that time waiting and thus are stopped by pgbouncer.

The investigation.

The first thing I did was google the issue. No hits that I could find that actually described my issue.

To validate why I couldn’t find this issue, I setup a machine with vanilla postgres and added pgbouncer to it with the same configuration and performed the same test. In that situation pgbouncer build the server connections really quick, and everything worked as I wanted it to work, meaning that pgbouncer connected all the client connections, and executed the queries using the statically set number of connections to the postgres server.

At that point I started thinking the modifications yugabyte made to the postgres layer might have an impact on this.

But it’s clear, I need additional information to understand where I needed to look.

Looking more deeply into the configuration of pgbouncer I found the option “verbose”, and set it to 5 to get more information, and ran the test against the yugabyte ysql server again. I found the following messages in the pgbouncer log:

2021-04-08 16:59:49.839 UTC [22773] DEBUG sbuf_after_connect_check: pending error: Connection refused

2021-04-08 16:59:49.839 UTC [22773] LOG S-0x563bd3657a80: yugabyte/yugabyte@[::1]:5433 closing because: connect failed (age=0s)

2021-04-08 16:59:49.839 UTC [22773] NOISE safe_close(35) = 0

2021-04-08 16:59:50.174 UTC [22773] DEBUG launching new connection to satisfy min_pool_size

2021-04-08 16:59:50.174 UTC [22773] DEBUG launch_new_connection: last failed, not launching new connection yet, still waiting 14 s

2021-04-08 16:59:50.505 UTC [22773] DEBUG launching new connection to satisfy min_pool_size

2021-04-08 16:59:50.505 UTC [22773] DEBUG launch_new_connection: last failed, not launching new connection yet, still waiting 14 s

2021-04-08 16:59:50.841 UTC [22773] DEBUG launching new connection to satisfy min_pool_size

2021-04-08 16:59:50.841 UTC [22773] DEBUG launch_new_connection: last failed, not launching new connection yet, still waiting 13 s

So pgbouncer encountered a connection refused error, and therefore closes/stops the attempt to add a connection, and then waits for 15 seconds before trying again. Why would it encounter a connection refused, which it didn’t encounter with vanilla postgres?

To be more practical, there also is a setting that allows tweaking the back-off time for the connection refused issue: server_login_retry. When I set it to 0, I still do get the error, but pgbouncer then builds up the server connections.

But it’s not very satisfactory to have this rather blunt workaround. I would like get the issue solved!

Looking deeper.

I decided I need to get this solved. Because this is a connection refused error, it’s logical to look at networking. A really good tool for this case is tcpdump. tcpdump allows (a superuser/root) to capture network traffic and visualise it. For the investigation, I setup the server to have no other connections to the database, pgbouncer freshly started so no connection are built up yet, and then connect to pgbouncer to trigger it to build the connections.

First regular postgres:

vagrant@localhost ~]$ sudo tcpdump -ttt -i lo -n port 5432

dropped privs to tcpdump

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode

listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [S], seq 952020725, win 43690, options [mss 65495,sackOK,TS val 3901196965 ecr 0,nop,wscale 6], length 0

IP 127.0.0.1.postgres > 127.0.0.1.48366: Flags [S.], seq 3702813748, ack 952020726, win 43690, options [mss 65495,sackOK,TS val 3901196965 ecr 3901196965,nop,wscale 6], length 0

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [.], ack 1, win 683, options [nop,nop,TS val 3901196965 ecr 3901196965], length 0

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [P.], seq 1:9, ack 1, win 683, options [nop,nop,TS val 3901197012 ecr 3901196965], length 8

IP 127.0.0.1.postgres > 127.0.0.1.48366: Flags [.], ack 9, win 683, options [nop,nop,TS val 3901197012 ecr 3901197012], length 0

IP 127.0.0.1.postgres > 127.0.0.1.48366: Flags [P.], seq 1:2, ack 9, win 683, options [nop,nop,TS val 3901197012 ecr 3901197012], length 1

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [.], ack 2, win 683, options [nop,nop,TS val 3901197012 ecr 3901197012], length 0

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [P.], seq 9:98, ack 2, win 683, options [nop,nop,TS val 3901197012 ecr 3901197012], length 89

IP 127.0.0.1.postgres > 127.0.0.1.48366: Flags [P.], seq 2:15, ack 98, win 683, options [nop,nop,TS val 3901197013 ecr 3901197012], length 13

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [P.], seq 98:139, ack 15, win 683, options [nop,nop,TS val 3901197013 ecr 3901197013], length 41

IP 127.0.0.1.postgres > 127.0.0.1.48366: Flags [P.], seq 15:342, ack 139, win 683, options [nop,nop,TS val 3901197014 ecr 3901197013], length 327

IP 127.0.0.1.48366 > 127.0.0.1.postgres: Flags [.], ack 342, win 700, options [nop,nop,TS val 3901197053 ecr 3901197014], length 0

In essence there isn’t much noteworthy to see. The first 3 packets are the TCP 3-way handshake, after which we see pgbouncer and postgres getting the connection ready at the other layers.

Now yugabyte:

[vagrant@centos83-yb-1 ~]$ sudo tcpdump -ttt -i lo -n port 5433

dropped privs to tcpdump

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode

listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes

IP 127.0.0.1.37500 > 127.0.0.1.pyrrho: Flags [S], seq 2745440791, win 43690, options [mss 65495,sackOK,TS val 1151235630 ecr 0,nop,wscale 7], length 0

IP 127.0.0.1.pyrrho > 127.0.0.1.37500: Flags [S.], seq 2754397962, ack 2745440792, win 43690, options [mss 65495,sackOK,TS val 1151235630 ecr 1151235630,nop,wscale 7], length 0

IP 127.0.0.1.37500 > 127.0.0.1.pyrrho: Flags [.], ack 1, win 342, options [nop,nop,TS val 1151235630 ecr 1151235630], length 0

IP 127.0.0.1.37500 > 127.0.0.1.pyrrho: Flags [P.], seq 1:42, ack 1, win 342, options [nop,nop,TS val 1151235630 ecr 1151235630], length 41

IP 127.0.0.1.pyrrho > 127.0.0.1.37500: Flags [.], ack 42, win 342, options [nop,nop,TS val 1151235630 ecr 1151235630], length 0

IP 127.0.0.1.pyrrho > 127.0.0.1.37500: Flags [P.], seq 1:332, ack 42, win 342, options [nop,nop,TS val 1151235755 ecr 1151235630], length 331

IP 127.0.0.1.37500 > 127.0.0.1.pyrrho: Flags [.], ack 332, win 350, options [nop,nop,TS val 1151235756 ecr 1151235755], length 0

IP6 ::1.43518 > ::1.pyrrho: Flags [S], seq 2042629123, win 43690, options [mss 65476,sackOK,TS val 2150324005 ecr 0,nop,wscale 7], length 0

IP6 ::1.pyrrho > ::1.43518: Flags [R.], seq 0, ack 2042629124, win 0, length 0

Yugabyte works at port 5433, which tcpdump translates as ‘pyrrho’. Here too the 3-way handshake is visible. And then pgbouncer and yugabyte chatting, until…a packet is sent using IP6 ?!? The packet is sent to the ‘pyrrho’ port, so it means the client (pgbouncer) must be doing this. Quite correctly the server responds to the IP6 packet by telling it the port is not in use (‘R’: reset). That actually fits with what the pgbouncer logging told us.

The solution.

At his point I knew somehow IPv6 (IP6) got involved. It probably has to do with name resolving, because that fits a scenario where something might “spontaneously” resolve as IPv6. And since it’s localhost, it’s not logical this is DNS, this must be something that is local on the machine. Well, if it’s name to address resolving and it can’t be DNS, the most logical thing would be the /etc/hosts file!

Apparently, with a Centos 8 standard installation, localhost is defined in the following way in /etc/hosts:

127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4
::1 localhost localhost.localdomain localhost6 localhost4.localdomain6

And because ‘::1’, the IPv6 address, is the second one, that is the one localhost will resolve to:

ping -c 1 localhost
PING localhost(localhost (::1)) 56 data bytes
64 bytes from localhost (::1): icmp_seq=1 ttl=64 time=0.024 ms

Well, then the solution to fully solve this would be really simple: remove the IPv6 / ::1 line from /etc/hosts. I did that, and indeed, there is no ‘connection refused’ anymore! Problem solved!