Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

uvloop is grouping responses to multiple requests/messages #631

Open
SerodioJ opened this issue Sep 22, 2024 · 6 comments
Open

uvloop is grouping responses to multiple requests/messages #631

SerodioJ opened this issue Sep 22, 2024 · 6 comments

Comments

@SerodioJ
Copy link

  • uvloop version: 0.20.0
  • Python version: 3.12.5
  • Platform: Ubuntu 22.04
  • Can you reproduce the bug with PYTHONASYNCIODEBUG in env?:
  • Does uvloop behave differently from vanilla asyncio? How?: Yes. It groups responses, and this behavior is not observed when using asyncio.

I am opening this issue from an issue that I had previously opened in the uvicorn repository

When running a FastAPI app with uvicorn default settings, which uses uvloop, I started to notice that sometimes when handling multiple requests for the same path the response took longer than expected to arrive at the client. This issue became more noticeable when I tried using WebSockets to improve performance by returning the result in parts over the same connection instead of making multiple HTTP requests.

I made a mini FastAPI app that represents the situation of my app, a WebSocket client, and a HTTP Client.

I will try to work on a Minimal Reproducible Example.

Example Code

FastAPI App Code (server.py)

import time

from fastapi import FastAPI, WebSocket

app = FastAPI()

@app.websocket("/ws")
async def websocket_hadler(websocket: WebSocket):
    await websocket.accept()
    title = await websocket.receive_text()
    start = time.time()
    await websocket.send_json(
        {"id": title, "status": "start", "time": time.time() - start}
    )
    for i in range(3):
        time.sleep(2)
        await websocket.send_json(
            {
                "id": title,
                "part": i,
                "time": time.time() - start,
            }
        )
    await websocket.send_json({"id": title, "status": "end", "time": time.time() - start})
    await websocket.close()

@app.get("/slow")
async def slow_endpoint():
    start = time.time()
    time.sleep(3)
    return {"time": time.time() - start}

HTTP Client Code (http.py)

import requests
import time
from threading import Thread
from multiprocessing import Process

def req(exec_id):
   start = time.time()
   response = requests.get(f"http://localhost:8000/slow")
   end = time.time()
   print({
       "id": exec_id,
       "client": end-start,
       "server": response.json()
   })

print("Threads")
for i in range(4):
   t = Thread(target=req, args=(i,))
   t.start()

# print("Process")
# for i in range(4):
#     p = Process(target=req, args=(i,))
#     p.start()

WebSocket Client Code (ws.py)

import time
import json
from websockets.sync.client import connect

with connect("ws://localhost:8000/ws") as websocket:
   websocket.send("uvloop") # or "asyncio"
   start = time.time()
   t = {}
   while t.get("status") != "end":
       t = json.loads(websocket.recv())
       print(t)
       print("----------------------------")
       print(f"Client Time: {time.time() - start}")
       print("#############################")

Experiment Instructions

Start server with uvloop (default)

uvicorn server:app --port 8000

Run clients

python http.py
python ws.py

Start server with asyncio

uvicorn server:app --port 8000 --loop asyncio

Run clients

python http.py
python ws.py

Results

uvloop

HTTP (some times the times are OK -> 3, 6, 9 and 12)

Threads
{'id': 2, 'client': 3.0042872428894043, 'server': {'time': 3.0001935958862305}}
{'id': 0, 'client': 9.011125087738037, 'server': {'time': 3.0001726150512695}}
{'id': 1, 'client': 9.00871992111206, 'server': {'time': 3.000185012817383}}
{'id': 3, 'client': 12.006998300552368, 'server': {'time': 3.0001895427703857}}

WebSockets

{'id': 'uvloop', 'status': 'start', 'time': 9.5367431640625e-07}
----------------------------
Client Time: 6.002939939498901
#############################
{'id': 'uvloop', 'part': 0, 'time': 2.0002377033233643}
----------------------------
Client Time: 6.003247022628784
#############################
{'id': 'uvloop', 'part': 1, 'time': 4.000699281692505}
----------------------------
Client Time: 6.003509283065796
#############################
{'id': 'uvloop', 'part': 2, 'time': 6.001102924346924}
----------------------------
Client Time: 6.00377082824707
#############################
{'id': 'uvloop', 'status': 'end', 'time': 6.001464366912842}
----------------------------
Client Time: 6.004014253616333
#############################

asyncio

HTTP (the grouping behavior was not observed in any attempt)

Threads
{'id': 2, 'client': 3.0055391788482666, 'server': {'time': 3.0002896785736084}}
{'id': 0, 'client': 6.010128021240234, 'server': {'time': 3.000213384628296}}
{'id': 1, 'client': 9.011209487915039, 'server': {'time': 3.000107526779175}}
{'id': 3, 'client': 12.008730173110962, 'server': {'time': 3.0002121925354004}}

WebSockets

{'id': 'asyncio', 'status': 'start', 'time': 7.152557373046875e-07}
----------------------------
Client Time: 0.0005409717559814453
#############################
{'id': 'asyncio', 'part': 0, 'time': 2.0002756118774414}
----------------------------
Client Time: 2.0013813972473145
#############################
{'id': 'asyncio', 'part': 1, 'time': 4.0009095668792725}
----------------------------
Client Time: 4.0020751953125
#############################
{'id': 'asyncio', 'part': 2, 'time': 6.001420021057129}
----------------------------
Client Time: 6.0024802684783936
#############################
{'id': 'asyncio', 'status': 'end', 'time': 6.001809120178223}
----------------------------
Client Time: 6.003089427947998
#############################

Environment

I am using Ubuntu 22.04 and a Python 3.12.5 environment created via conda (4.10.3).
pip freeze output:

annotated-types==0.7.0
anyio==4.5.0
certifi==2024.8.30
charset-normalizer==3.3.2
click==8.1.7
dnspython==2.6.1
email_validator==2.2.0
fastapi==0.115.0
fastapi-cli==0.0.5
gevent==24.2.1
greenlet==3.1.0
h11==0.14.0
httpcore==1.0.5
httptools==0.6.1
httpx==0.27.2
idna==3.10
Jinja2==3.1.4
markdown-it-py==3.0.0
MarkupSafe==2.1.5
mdurl==0.1.2
pydantic==2.9.2
pydantic_core==2.23.4
Pygments==2.18.0
python-dotenv==1.0.1
python-multipart==0.0.9
PyYAML==6.0.2
requests==2.32.3
rich==13.8.1
setuptools==75.1.0
shellingham==1.5.4
sniffio==1.3.1
starlette==0.38.5
typer==0.12.5
typing_extensions==4.12.2
urllib3==2.2.3
uvicorn==0.30.6
uvloop==0.20.0
watchfiles==0.24.0
websocket==0.2.1
websockets==13.0.1
wheel==0.44.0
zope.event==5.0
zope.interface==7.0.3
@Kludex
Copy link

Kludex commented Sep 22, 2024

This is a bad MRE for uvloop, but it does look like there's a different behavior from asyncio here.

@graingert
Copy link
Contributor

MRE is:

import socket
import uvloop
import asyncioasync def main():
    s1, s2 = socket.socketpair()
    with s1, s2:
        reader, writer = await asyncio.open_connection(sock=s1)
        writer.write(b"\x00")
        s2.recv(1)
​
asyncio.run(main())
print("asyncio done")
uvloop.run(main())
print("uvloop done")

Looks like the bug is here: https://github.com/MagicStack/uvloop/blob/master/uvloop/handles/stream.pyx#L430

uvloop only writes to the socket if the high water is reached, otherwise it schedules it for the next event loop cycle which never happens

asyncio attempts to send it then adds it to the buffer if anything is not sent https://github.com/python/cpython/blob/main/Lib/asyncio/selector_events.py#L1067

@tarasko
Copy link

tarasko commented Oct 16, 2024

MRE is:

import socket
import uvloop
import asyncioasync def main():
    s1, s2 = socket.socketpair()
    with s1, s2:
        reader, writer = await asyncio.open_connection(sock=s1)
        writer.write(b"\x00")
        s2.recv(1)
​
asyncio.run(main())
print("asyncio done")
uvloop.run(main())
print("uvloop done")

Looks like the bug is here: https://github.com/MagicStack/uvloop/blob/master/uvloop/handles/stream.pyx#L430

uvloop only writes to the socket if the high water is reached, otherwise it schedules it for the next event loop cycle which never happens

asyncio attempts to send it then adds it to the buffer if anything is not sent https://github.com/python/cpython/blob/main/Lib/asyncio/selector_events.py#L1067

I've already optimized this part and made it inline with original asyncio: #619
Perhaps it even fixes the bug, maybe you could try.

The thing is, I've also made a few other nice optimizations a couple month ago (check out the latest PRs) that significantly improve uvloop performance!
However, nobody gave any feedback. uvloop seems a little abandoned now.

@1st1
Copy link
Member

1st1 commented Oct 29, 2024

The thing is, I've also made a few other nice optimizations a couple month ago (check out the latest PRs) that significantly improve uvloop performance! However, nobody gave any feedback. uvloop seems a little abandoned now.

I'll take a look this week!

@tarasko
Copy link

tarasko commented Nov 9, 2024

The thing is, I've also made a few other nice optimizations a couple month ago (check out the latest PRs) that significantly improve uvloop performance! However, nobody gave any feedback. uvloop seems a little abandoned now.

I'll take a look this week!

Thank you, those performance optimizations are really cool!

It would make sense to update benchmark graph on the main page
https://raw.githubusercontent.com/MagicStack/uvloop/master/performance.png
after they are merged.

@hidaris
Copy link

hidaris commented Nov 10, 2024

I hope this issue can be resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants