Connection pool slow performance

[Zsolt Ero]

I thought I finally got to understand what does it mean to use a connection pool /  QueuePool, but this performance problem puzzles me.

If I run:

for i in range(100):
    with pg_engine.connect() as conn:
        conn.execute('select 1').fetchall()

it takes 47 seconds.

If I run 

with pg_engine.connect() as conn:
    for i in range(100):
        conn.execute('select 1').fetchall()

it takes 17 seconds.

Isn't the whole point of Connection Pool that connections are kept/cached/reused? If so, then why does the first version take 3 times longer?

pg_engine is set up the following way:

pg_url = f'postgresql+psycopg2://app:{pg_config["password"]}@{pg_config["host"]}/app'
pg_certs = {
    'sslcert': f'{config_dir}/client-cert.pem',
    'sslkey': f'{config_dir}/client-key.pem',
    'sslrootcert': f'{config_dir}/server-ca.pem',
}
pg_engine = create_engine(pg_url, connect_args=pg_certs)

The server is a remote server quite far away, hence the connection issues are greatly amplified, compared to localhost. Python is 3.7.

[Mike Bayer]

On Fri, Jan 18, 2019 at 3:58 PM Zsolt Ero <zsol...@gmail.com> wrote:
>
> I thought I finally got to understand what does it mean to use a connection pool / QueuePool, but this performance problem puzzles me.
>
> If I run:
> for i in range(100):
> with pg_engine.connect() as conn:
> conn.execute('select 1').fetchall()
> it takes 47 seconds.
>
> If I run
> with pg_engine.connect() as conn:
> for i in range(100):
> conn.execute('select 1').fetchall()
> it takes 17 seconds.

you have some kind of major issue with your network and/or database.
you'll want to do some ping tests and things like that, or perhaps
the SSL certificate setup you are using is adding some kind of extreme
latency, you'll want to test without it, perhaps there's a slow DNS
lookup or something occurring. the code you have above normally
takes about 100 ms. OK, took me 300ms over a local network:

$ python
Python 3.7.0 (default, Jun 28 2018, 10:59:55)
[GCC 8.1.1 20180502 (Red Hat 8.1.1-1)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> from sqlalchemy import create_engine
>>> e = create_engine("postgresql://scott:tiger@pg10/test")
>>> import time
>>> def go():
... now = time.time()
... with e.connect() as conn:
... for i in range(100):
... conn.execute("select 1").fetchall()
... total = time.time() - now
... print("completed in %f sec" % (total, ))
...
>>> go()
completed in 0.335034 sec

>
> Isn't the whole point of Connection Pool that connections are kept/cached/reused? If so, then why does the first version take 3 times longer?
>
> pg_engine is set up the following way:
>
> pg_url = f'postgresql+psycopg2://app:{pg_config["password"]}@{pg_config["host"]}/app'
> pg_certs = {
> 'sslcert': f'{config_dir}/client-cert.pem',
> 'sslkey': f'{config_dir}/client-key.pem',
> 'sslrootcert': f'{config_dir}/server-ca.pem',
> }
> pg_engine = create_engine(pg_url, connect_args=pg_certs)
>
> The server is a remote server quite far away, hence the connection issues are greatly amplified, compared to localhost. Python is 3.7.
>

> --
> SQLAlchemy -
> The Python SQL Toolkit and Object Relational Mapper
>
> http://www.sqlalchemy.org/
>
> To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.
> ---
> You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.
> To post to this group, send email to sqlal...@googlegroups.com.
> Visit this group at https://groups.google.com/group/sqlalchemy.
> For more options, visit https://groups.google.com/d/optout.

[Zsolt Ero]

I know I'm far away from a remote server, as the server is a Google
Cloud SQL instance, and I'm in a residential cable connection. But
ping times are only 145 ms, nothing extreme I'd say. If you'd like I
can quickly setup a sandbox instance on GCP for trying this out.

Still, I don't even understand the theory, shouldn't connection pools
be the same speed as keeping one connection?

[Mike Bayer]

the problem you are illustrating has nothing to do with the connection pool.

[Mike Bayer]

On Fri, Jan 18, 2019 at 4:54 PM Mike Bayer <mik...@zzzcomputing.com> wrote:
>
> On Fri, Jan 18, 2019 at 4:49 PM Zsolt Ero <zsol...@gmail.com> wrote:
> >
> > I know I'm far away from a remote server, as the server is a Google
> > Cloud SQL instance, and I'm in a residential cable connection. But
> > ping times are only 145 ms, nothing extreme I'd say. If you'd like I
> > can quickly setup a sandbox instance on GCP for trying this out.
> >
> > Still, I don't even understand the theory, shouldn't connection pools
> > be the same speed as keeping one connection?
>
> the problem you are illustrating has nothing to do with the connection pool.

oh, you're asking why if you connect each time, its slower. the
code you are illustrating is still using only one connection at a
time, however when you return a connection to the pool, it has to emit
a ROLLBACK on the connection by default which might be adding extra
latency.

I can replicate that the ROLLBACK causes it to take .77 seconds:

>>> from sqlalchemy import create_engine
>>> e = create_engine("postgresql://scott:tiger@pg10/test")
>>> import time
>>> def go():
... now = time.time()

... for i in range(100):
... with e.connect() as conn:
... conn.execute("select 1").fetchall()
... total = time.time() - now
... print("completed in %f sec" % (total, ))
...
>>> go()

completed in 0.779910 sec

turning that off (this is also instructional in how to do that), takes
.30 seconds again:

>>> from sqlalchemy import create_engine
>>> e = create_engine("postgresql://scott:tiger@pg10/test", pool_reset_on_return=None)

>>> import time
>>> def go():
... now = time.time()

... for i in range(100):
... with e.connect() as conn:
... conn.execute("select 1").fetchall()
... total = time.time() - now
... print("completed in %f sec" % (total, ))
...
>>> go()

completed in 0.301798 sec

[Zsolt Ero]

But why is it doing any kind of network activity on a .connect(), if
the previous connection was closed in the pool?

OK, I created a sandbox server, it'll probably be quicker for you as
the server is in US, but this also did 18 sec for me.

import time
from sqlalchemy import create_engine

e = create_engine("postgresql://postgres:san...@104.154.217.229/postgres")

def go():
now = time.time()
with e.connect() as conn:

for i in range(100):
conn.execute("select 1").fetchall()

total = time.time() - now

print("completed in %f sec" % (total, ))

go()

> You received this message because you are subscribed to a topic in the Google Groups "sqlalchemy" group.
> To unsubscribe from this topic, visit https://groups.google.com/d/topic/sqlalchemy/GEhwdHSBVbs/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to sqlalchemy+...@googlegroups.com.

[Zsolt Ero]

Thank you for the explanation, with ROLLBACK / pool_reset_on_return I
understand it now.

With this snippet:

import time
from sqlalchemy import create_engine

e = create_engine("postgresql://postgres:san...@104.154.217.229/postgres")


def go():
now = time.time()
with e.connect() as conn:
for i in range(100):
conn.execute("select 1").fetchall()
total = time.time() - now
print("completed in %f sec" % (total, ))

def go2():
now = time.time()
for i in range(100):
with e.connect() as conn:

conn.execute("select 1").fetchall()
total = time.time() - now
print("completed in %f sec" % (total, ))

go()

go2()
e = create_engine("postgresql://postgres:san...@104.154.217.229/postgres",
pool_reset_on_return=None)
go2()

I get values 17, 44, 17 in remote connection, or 0.10, 0.17, 0.10
within the same datacenter.

Zsolt