Frequent freezes occuring with no apparent changes

[seblefou]

Hello,
I am starting this discussion as a we are recently experiencing frequent freezes with SQLAlchemy's async engine.
The engine was created with the following parameters

engine = create_async_engine(
            database_url,
            connect_args={'timeout': 3},
            pool_size=16,
            max_overflow=10,
            pool_timeout=10,
            pool_pre_ping=True, 
            echo=True
        )

The dialect is postgresql and the driver is asynccpg. However, we were able of reproducing the same problem with mysql and aiomysql. The code below shows how the insert operations are performed. We also tried a version with rollback() but it did not make a difference.

async with self.engine.connect() as conn:
         async with conn.begin():
                   record_id = await conn.execute(query)

We also note that the timeout set in line connect_args={'timeout': 3}, does not have any effect once the freeze happens.
Initially we believed that we are dealing with a deadlock on the database site, but nothing could be found in the logs. There are also no issues with memory or CPU load.

Finally, the log looks as follows:

INFO:sqlalchemy.engine.Engine:INSERT INTO "SENSOR_702" (id, value,...
2021-04-16 20:18:55,478 INFO sqlalchemy.engine.Engine [cached since 222.9s ago] (UUID('a681e247-6439-4adb-994f-33e980bbc252'), 2992.19, ...
2021-04-16 20:18:55,478 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-04-16 20:18:55,479 INFO sqlalchemy.engine.Engine INSERT INTO "SENSOR_39" (id, value,...
2021-04-16 20:18:55,479 INFO sqlalchemy.engine.Engine [cached since 213.5s ago] (UUID('daa2fd4b-86ea-4b6a-8cd6-29ed9a685da0'), 0.10228, ...
2021-04-16 20:18:55,479 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-04-16 20:18:55,480 INFO sqlalchemy.engine.Engine INSERT INTO "SENSOR_157" (id, value,...
2021-04-16 20:18:55,480 INFO sqlalchemy.engine.Engine [generated in 0.00025s] (UUID('e171514e-139e-4575-bb74-25d94bd39fd4'), 16.44, ...
2021-04-16 20:18:55,480 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-04-16 20:18:55,481 INFO sqlalchemy.engine.Engine INSERT INTO "SENSOR_575" (id, value...
2021-04-16 20:18:55,481 INFO sqlalchemy.engine.Engine [cached since 13.79s ago] (UUID('607a8302-a217-431f-991b-b206296e1b69'), 43.56,...
2021-04-16 20:18:55,481 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-04-16 20:18:55,481 INFO sqlalchemy.engine.Engine INSERT INTO "SENSOR_4" (id, value...
2021-04-16 20:18:55,481 INFO sqlalchemy.engine.Engine [cached since 42.49s ago] (UUID('3aa80da6-8e4b-4026-9c4e-9442fadcb491'), 0.200436, ...
2021-04-16 20:18:55,484 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,484 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,485 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,485 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,485 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,485 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,486 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,486 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,486 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,578 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,592 INFO sqlalchemy.engine.Engine COMMIT
2021-04-16 20:18:55,606 INFO sqlalchemy.engine.Engine COMMIT
INFO:asyncio:poll 185439.185 ms took 2974.428 ms: 1 events              <-- Freeze occurs here
INFO:asyncio:poll 182463.147 ms took 182520.203 ms: timeout
INFO:asyncio:poll 39368.672 ms took 39408.347 ms: timeout
INFO:asyncio:poll 31146.929 ms took 31179.200 ms: timeout
INFO:asyncio:poll 9567.855 ms took 9577.604 ms: timeout
INFO:asyncio:poll 9936.663 ms took 9946.989 ms: timeout
INFO:asyncio:poll 9995.894 ms took 10006.049 ms: timeout

Insertions are the only operation type and all queries look as follows:
INSERT INTO "SENSOR_#" (id, value, unit, timestamp, source) VALUES (:id, :value, :unit, :timestamp, :source)'

The number of insertions per second average at around 34, but there are short bursts where we end up with over 100 insertions per second.

We are trying to troubleshoot this issue for 10 days already but to no avail. Any help or hint is welcome

Thank you in advance

[zzzeek]

hi -

information about the environment is the start.

What kind of application is it? command line, web application, daemon process?

what kind of web container / server container / etc are in use?

What kind of async frameworks etc. are in use ?

Does the program have this freeze while it is doing exactly just this one thing at a time or are there other concurrent awaitables in progress?

how many database connections are in play at at a time when this freeze occurs? your pool is configured to allow as many as 26 connections at once. if your program reaches for a 27th connection, that awaitable will pause until a connection is available. are you configured to run more concurrent awaitables than 26 ?

does the program use any other concurrency systems in addtion to awaitables? like threads, thread executors, multiprocessing, fork, etc? Or does the application environent / web container / etc use these things?

during the freeze, what is shown in the database? E.g. select from pg_stat_activity while the freeze occurs. are transactions from the relevant pids in progress? what is their status?

[seblefou]

Hi

The environment is:
OS: Ubuntu 20.04.2 LTS
Python: 3.7.6
SQLAlchemy: 1.4.5
asyncpg: 0.22.0

The application is run directly from the command line without a container. There is no parallelism. Everything runs in a single thread. However, there are about 50 concurrent tasks. We added asyncio.Semaphore with a maximum of 5 concurrent tasks in the following manner, but to no avail:

async with semaphore:
        async with self.engine.connect() as conn:
                 async with conn.begin():
                           record_id = await conn.execute(query)

The results from pg_stat_activity look as follows:

   state            | ... |                                            query                                                           
idle in transaction | ... | BEGIN ISOLATION LEVEL READ COMMITTED;
idle in transaction | ... | INSERT INTO "Test13" (id, value, unit, timestamp, source) VALUES ($1::uuid, $2::numeric, $3::varchar, $4::timestamp, $5)
idle                | ... | COMMIT;  
idle in transaction | ... | INSERT INTO "Test199" (id, value, unit, timestamp, source) VALUES ($1::uuid, $2::numeric, $3::varchar, $4::timestamp, $5) 
idle                | ... | COMMIT;
idle                | ... | COMMIT;
idle in transaction | ... | BEGIN ISOLATION LEVEL READ COMMITTED;

The freeze looks like the result of resource starvation. From our investigation, we suspect that the freeze originates from the sqlalchemy.pool.QueuePool more specifically from sqlalchemy.pool.QueuePool.connect() which seems to contain some blocking code. We suspect that this blocks the main thread which prevents any of the connections to be returned to the pool.

However, we are not sure how to trigger this behavior. Even without semaphore we do not exhaust the pool connections and when triggered on purpose we get the following error:

An exception occurred: QueuePool limit of size 10 overflow 16 reached, connection timed out, timeout 30.00 (Background on this error at: http://sqlalche.me/e/14/3o7r)

I would also like to add that we have not observed this issue yet when using NullPool instead of QueuePool.

[zzzeek]

the QueuePool error you see above only occurs when it reaches a pool_timeout. Can you try setting that timeout to zero ? When you use NullPool can you then look at pg_stat_activity and observe the max number of connection that are used concurrently? note also that when using asyncio, the AsyncQueuePool class is what should be in use which modifies to use an asyncio.Lock.

if you can provide a self-contained MCVE with no dependencies that reproduces the issue in isolation I'd be able to determine what's going wrong.

[seblefou]

We finally found the culprit. It had nothing to do with SQLAlchemy. It was just a faulty switch that affected the connection. The reason why we did not catch it was that the connection stayed alive and the buffering delayed the effect by many minutes. We are not sure yet how that ended up locking the main thread, but it is unlikely to be an issue with the library.

I am sorry to have wasted your time. Thank you anyway for your efforts.