3

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/[email protected]: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/[email protected]: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?

Improve this question
1
  • Those look like logs from your application container, not PostgreSQL. I don't know if you'll get much help on dba.SE's postgresql tag. I haven't used flask, anyway. I'd be looking at PostgreSQL's logs with log_connections=on to see if your framework was really disconnecting and connecting a lot, or whether it just has confusing logs.
    – Craig Ringer
    Commented Jun 10, 2014 at 1:56

1 Answer 1

Reset to default
10

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.

Improve this answer
3
  • Thanks for the detailed explanations, it all makes sense.
    – cjauvin
    Commented Jun 10, 2014 at 16:55
  • @DanielVérité: I have similar pgbouncer logs, but I also see closing because: unclean server (age=0). Do you happen to know what that means, and how to fix it?
    – Hassan Baig
    Commented Dec 12, 2016 at 9:59
  • @HassanBaig: No, but please create a new question for this.
    – Daniel Vérité
    Commented Dec 12, 2016 at 11:07

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.