MagicStack / MagicStack/asyncpg
Many concurrent requests block the event loop
Chưa có ai nhận issue này.
- Ngôn ngữ chính
- Python
- Star
- 8.1k
- Fork
- 468
- Chỉ số merge pull request
- Không có pull request nào được merge trong 30 ngày
Mô tả
* **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!
Hướng dẫn đóng góp
Chưa lập chỉ mục được hướng dẫn đóng góp cho kho mã nguồn này
Bắt đầu từ đâu
- Đọc hết issue, rồi đọc hướng dẫn đóng góp của dự án.
- Bình luận trên issue rằng bạn sẽ nhận — tránh hai người làm cùng một việc.
- Fork repository và làm thay đổi trên một nhánh.
- Mở pull request có tham chiếu số hiệu của issue.
Hướng nghiên cứu
Bắt đầu bằng cách chạy bản tái hiện gồm 25.000 tác vụ được cung cấp với asyncio và uvloop, sau đó kiểm tra asyncpg/protocol.pyx quanh _on_result__simple_query và waiter.set_result(...), nơi báo cáo đã quan sát thấy độ trễ. Công việc được xem là hoàn tất khi đã xác định và khắc phục việc vòng lặp sự kiện bị chặn dưới các yêu cầu đồng thời, rồi chạy lại bản tái hiện để xác nhận rằng các hiện tượng đình trệ được báo cáo đã được giải quyết.
Do mô hình lập chỉ mục viết ra từ nội dung của issue.
Đánh giá
- Công nghệ
- postgresql, python
- Lĩnh vực
- databases
- Loại issue
- Lỗi
- Độ khó
- 5/5
- Thời gian dự kiến
- Hơn một tuần
- Mức độ hoạt động
- Đình trệ
- Độ rõ ràng
- Cần làm rõ
- Mức phù hợp với người mới
- 25/100