MagicStack / MagicStack/asyncpg

Many concurrent requests block the event loop

Open
#1,092 10 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Python
Stars
8.1k
Forks
468
PR merge metrics
No merged PRs in 30d

Description

* **asyncpg version**: 0.28.0
* **PostgreSQL version**: 14.7
* **Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
the issue with a local PostgreSQL install?**: Issue occurs on RDS and local Docker Postgres.
* **Python version**: 3.9.16. Reproduction also works on 3.10.11.
* **Platform**: Ubuntu 20.04.5 LTS
* **Do you use pgbouncer?**: No.
* **Did you install asyncpg with pip?**: Yes. The issue occurs with both `pip install asyncpg==0.28.0` and install from source.
* **If you built asyncpg locally, which version of Cython did you use?**: 0.29.32
* **Can the issue be reproduced under both asyncio and
[uvloop](https://github.com/magicstack/uvloop)?**: Can be reproduced under both asyncio and uvloop.

### Reproduction (for simplicity, against a local Docker instance of Postgres).
```python
import asyncpg

import asyncio
import time

async def main():
asyncio.get_running_loop().slow_callback_duration = 0.05

pg = await asyncpg.create_pool(
user="postgres",
password="",
database="defaultdb",
host="localhost",
port="5432",
)

await pg.execute(
"""
CREATE TABLE IF NOT EXISTS my_table (
id VARCHAR(20) PRIMARY KEY,
value VARCHAR(255)
);
INSERT INTO my_table (id, value) VALUES ('id-123', '4')
ON CONFLICT (id) DO NOTHING;
"""
)

query = "UPDATE my_table SET value = '4';"

for i in range(25000):

async def go():
for _ in range(10):
async with pg.acquire() as conn:
async with conn.transaction():
await conn.execute(query)

asyncio.create_task(go())

t0 = time.time()
await asyncio.sleep(0.001)
elapsed_ms = (time.time() - t0) * 1000

if elapsed_ms > 50:
print(f">>> {i} took {elapsed_ms}ms")

# import uvloop

# asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())

asyncio.run(main(), debug=True)
```

### Output:
```
Executing wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /usr/lib/python3.9/asyncio/base_events.py:184] created at /usr/lib/python3.9/asyncio/base_events.py:626> took 0.061 seconds
>>> 3851 took 62.56461143493652ms

Executing .go() running at /home/ubuntu/modal/analytics/asyncpg_blocking.py:35> wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> created at /usr/lib/python3.9/asyncio/tasks.py:361> took 0.095 seconds
>>> 4921 took 96.0381031036377ms

Executing took 0.126 seconds
>>> 5990 took 128.0958652496338ms

Executing wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /usr/lib/python3.9/asyncio/base_events.py:184] created at /usr/lib/python3.9/asyncio/base_events.py:626> took 0.138 seconds
>>> 7064 took 139.1909122467041ms

Executing wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /usr/lib/python3.9/asyncio/base_events.py:184] created at /usr/lib/python3.9/asyncio/base_events.py:626> took 0.166 seconds
>>> 8125 took 167.76275634765625ms

Executing took 0.193 seconds
>>> 9282 took 194.34309005737305ms
Executing .go() running at /home/ubuntu/modal/analytics/asyncpg_blocking.py:35> wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> created at /usr/lib/python3.9/asyncio/tasks.py:361> took 0.232 seconds
>>> 10635 took 232.7420711517334ms

Executing took 0.256 seconds
>>> 12092 took 257.3966979980469ms

Executing wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> cb=[shield.._inner_done_callback() at /usr/lib/python3.9/asyncio/tasks.py:890] created at /usr/lib/python3.9/asyncio/tasks.py:883> took 0.292 seconds
>>> 13746 took 293.03622245788574ms

Executing .go() running at /home/ubuntu/modal/analytics/asyncpg_blocking.py:35> wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> created at /usr/lib/python3.9/asyncio/tasks.py:361> took 0.321 seconds
>>> 15671 took 321.78592681884766ms

Executing wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /usr/lib/python3.9/asyncio/base_events.py:184] created at /usr/lib/python3.9/asyncio/base_events.py:626> took 0.375 seconds
>>> 17901 took 376.0251998901367ms

Executing .go() running at /home/ubuntu/modal/analytics/asyncpg_blocking.py:37> wait_for=._outer_done_callback() at /usr/lib/python3.9/asyncio/tasks.py:907, ()] created at /usr/lib/python3.9/asyncio/base_events.py:429> created at /usr/lib/python3.9/asyncio/tasks.py:361> took 0.418 seconds
>>> 20313 took 418.8547134399414ms

Executing wait_for=()] created at /usr/lib/python3.9/asyncio/base_events.py:429> cb=[shield.._inner_done_callback() at /usr/lib/python3.9/asyncio/tasks.py:890] created at /usr/lib/python3.9/asyncio/tasks.py:883> took 0.486 seconds
>>> 23108 took 487.2567653656006m
```

### Further investigation
Adding verbose prints to `protocol.pyx` led to me chasing down one particular 80ms+ blocking execution, which ended at `waiter.set_result(...)` in `_on_result__simple_query`, which took up the majority (150ms out of 151ms, for example) of a slow callback. After this, I wasn't sure how to continue debugging -- open to suggestions or ideas here.

### Removing debug=True

The issue is still present, albeit less frequent, without debug mode on

```
>>> 11807 took 86.72428131103516ms
>>> 16438 took 117.77758598327637ms
>>> 21042 took 172.47319221496582ms
```

Thanks all!

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by running the supplied 25,000-task reproduction with asyncio and uvloop, then inspect asyncpg/protocol.pyx around _on_result__simple_query and waiter.set_result(...), where the report observed the delay. Done means identifying and fixing the event-loop blocking under concurrent requests, then rerunning the reproduction to confirm the reported stalls are resolved.

Written by the indexing model from the issue text.

Assessment

Tech stack
postgresql, python
Domain
databases
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.