MagicStack / MagicStack/asyncpg

Many concurrent requests block the event loop

Ouverte
#1,092 10 commentaires 1 réaction 0 personnes assignées Voir sur GitHub

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

  1. Lisez l'issue en entier, puis le guide de contribution du projet.
  2. Signalez en commentaire que vous la prenez — cela évite que deux personnes fassent le même travail.
  3. Forkez le dépôt et travaillez sur une branche.
  4. 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

Recevez les nouvelles issues par e-mail

Un résumé court des issues GitHub adaptées aux débutants.