Postgresql – PgBouncer Uncertainties

pgbouncerpostgresqlpython

I'm trying PgBouncer for the first time with a simple Python web application (Flask + psycopg2), and I have a hard time interpreting the meaning of its log messages by simple googling. I'm basically seeing a bunch of:

2014-06-09 09:25:07.867 20980 LOG C-0x1b1b240: vinum/vinum@unix:6432 login attempt: db=vinum user=vinum
2014-06-09 09:25:07.867 20980 LOG S-0x1b38bf0: vinum/vinum@127.0.0.1:5432 new connection to server
2014-06-09 09:25:07.875 20980 LOG C-0x1b1b240: vinum/vinum@unix:6432 closing because: client close request (age=0)
2014-06-09 09:25:15.626 20980 LOG C-0x1b1b240: vinum/vinum@unix:6432 login attempt: db=vinum user=vinum
2014-06-09 09:25:16.058 20980 LOG C-0x1b1b240: vinum/vinum@unix:6432 closing because: client close request (age=0)
2014-06-09 09:25:16.762 20980 LOG C-0x1b1b240: vinum/vinum@unix:6432 login attempt: db=vinum user=vinum
2014-06-09 09:25:16.796 20980 LOG C-0x1b1b3a8: vinum/vinum@unix:6432 login attempt: db=vinum user=vinum
2014-06-09 09:25:16.796 20980 LOG S-0x1b38d58: vinum/vinum@127.0.0.1:5432 new connection to server
2014-06-09 09:25:17.181 20980 LOG C-0x1b1b240: vinum/vinum@unix:6432 closing because: client close request (age=0)
2014-06-09 09:25:17.240 20980 LOG C-0x1b1b3a8: vinum/vinum@unix:6432 closing because: client close request (age=0)

I find these multiple closings with age=0 worrying, do they mean that the connections are always recreated, thus never pooled?

Best Answer

I find these multiple closings with age=0 worrying

No, this whole log looks fine and tends to show that pooling is working.

These entries with age=0 being tagged as LOG C, they concern communication between a client and pgBouncer. age=0 just means that the client used the connection for less than 1 second, which is consistent with the dates with milliseconds appearing in that log.

A line 1, a client connects to pgBouncer.

At line 2, there's a first connection made with a new postgres backend.

At line 3, the client quits.

At line 4, a new client arrives and no new connection is made with a backend, which implies that the previous one is reused as expected.

At line 8, a second server connection (LOG S) is made with a new postgres backend, which is necessary since there are two concurrent clients (see sucessful login attempts on the two previous LOG C lines within the same second).

Then the clients quit, and there's no mention of connections to postgres backends being closed, as expected again. They should be kept open until they reach server_lifetime or server_idle_timeout when idle.

Related Question