Postgres Pro
Downloads
Home   >   mailing lists

Thread: PgBouncer doubts

PgBouncer doubts

From
Christian Jauvin
Date:
Hi,

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?

My Flask/psycopg2 connection handling code is super simple:

@app.before_request
def before_request():
    rdc = psycopg2.extras.RealDictConnection
    g.db = psycopg2.connect("dbname=%s user=%s port=%s" %
                            (app.config['DATABASE_NAME'],
                             app.config['DATABASE_USER'],
                             app.config['PGBOUNCER_PORT']),
                            connection_factory=rdc)

@app.teardown_request
def teardown_request(exception):
    if hasattr(g, 'db'):
        g.db.close()

I'd greatly appreciate any explanation or guidance about this

Christian

Re: PgBouncer doubts

From
Adrian Klaver
Date:
On 06/10/2014 07:37 AM, Christian Jauvin wrote:
> Hi,
>
> 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?
>
> My Flask/psycopg2 connection handling code is super simple:
>
> @app.before_request
> def before_request():
>      rdc = psycopg2.extras.RealDictConnection
>      g.db = psycopg2.connect("dbname=%s user=%s port=%s" %
>                              (app.config['DATABASE_NAME'],
>                               app.config['DATABASE_USER'],
>                               app.config['PGBOUNCER_PORT']),
>                              connection_factory=rdc)
>
> @app.teardown_request
> def teardown_request(exception):
>      if hasattr(g, 'db'):
>          g.db.close()
>
> I'd greatly appreciate any explanation or guidance about this

The log is showing that the client is requesting that the connection be
closed. So my guess is that teardown_request is being run for a reason
you have not accounted for.

To make things clearer, what log are we looking at, the PgBouncer or
Postgres?

>
> Christian
>
>


--
Adrian Klaver
adrian.klaver@aklaver.com

Re: PgBouncer doubts

From
Christian Jauvin
Date:
> To make things clearer, what log are we looking at, the PgBouncer or
> Postgres?

This is the PgBouncer log.

> The log is showing that the client is requesting that the connection be
> closed. So my guess is that teardown_request is being run for a reason you
> have not accounted for.

Actually, teardown_request should be executed for every single
interaction with the app (after every Ajax call for instance), so one
thing I tried (under the assumption that maybe the psycopg2 connection
should not be explicitly closed in such a PgBouncer-enabled setup) is
to simply comment it all out, but it didn't change the PgBouncer
behavior at all.

Also, according to this answer to the same question on dba.SE, it
seems that this log is
the expected behavior:

http://dba.stackexchange.com/a/67982/40738

Re: PgBouncer doubts

From
Adrian Klaver
Date:
On 06/11/2014 07:26 AM, Christian Jauvin wrote:
>> To make things clearer, what log are we looking at, the PgBouncer or
>> Postgres?
>
> This is the PgBouncer log.
>
>> The log is showing that the client is requesting that the connection be
>> closed. So my guess is that teardown_request is being run for a reason you
>> have not accounted for.
>
> Actually, teardown_request should be executed for every single
> interaction with the app (after every Ajax call for instance), so one
> thing I tried (under the assumption that maybe the psycopg2 connection
> should not be explicitly closed in such a PgBouncer-enabled setup) is
> to simply comment it all out, but it didn't change the PgBouncer
> behavior at all.

Web apps tend to spawn a lot of connections so this is not surprising.

>
> Also, according to this answer to the same question on dba.SE, it
> seems that this log is
> the expected behavior:
>
> http://dba.stackexchange.com/a/67982/40738
>

Yea, it looks like it is cycling through connections.

--
Adrian Klaver
adrian.klaver@aklaver.com