MagicStack / MagicStack/asyncpg
Many concurrent requests block the event loop
Personne n'a encore pris cette issue.
- Langage dominant
- Python
- Étoiles
- 8.1k
- Forks
- 468
- Métriques de merge des PR
- Aucune PR mergée en 30 j
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!
Guide de contribution
Aucun guide de contribution indexé pour ce dépôt
Par où commencer
- Lisez l'issue en entier, puis le guide de contribution du projet.
- Signalez en commentaire que vous la prenez — cela évite que deux personnes fassent le même travail.
- Forkez le dépôt et travaillez sur une branche.
- Ouvrez une pull request qui référence le numéro de l'issue.
Piste de recherche
Commencez par exécuter la reproduction fournie de 25 000 tâches avec asyncio et uvloop, puis inspectez asyncpg/protocol.pyx autour de _on_result__simple_query et de waiter.set_result(...), là où le rapport a observé le délai. La tâche est terminée lorsque le blocage de la boucle d’événements sous des requêtes concurrentes a été identifié et corrigé, puis que la reproduction a été relancée pour confirmer que les blocages signalés sont résolus.
Rédigé par le modèle d'indexation à partir du texte de l'issue.
Évaluation
- Stack technique
- postgresql, python
- Domaine
- databases
- Type d'issue
- Bug
- Difficulté
- 5/5
- Temps estimé
- Plus d'une semaine
- Activité
- À l'abandon
- Clarté
- À clarifier
- Accessibilité débutants
- 25/100