search

encode / starlette

The little ASGI framework that shines. 🌟
https://www.starlette.io/
BSD 3-Clause "New" or "Revised" License
10.31k stars 949 forks source link

Returns the file, the event loop may be blocked #2664

Closed majiang213 closed 3 months ago

majiang213 commented 3 months ago

Hi, everyone. I have a problem. When returning a file in high concurrency, the event loop may be blocked. For details, please refer to this discussion

https://github.com/encode/uvicorn/discussions/2419

majiang213 commented 3 months ago

Any updates on this issue?

Kludex commented 3 months ago

Well, no. You provide an MRE with FastAPI, this is Starlette, and you don't even add the MRE here.

Kludex commented 3 months ago

I've checked. I don't see any issue. Please provide a script that demonstrates the issue.

majiang213 commented 3 months ago

I've checked. I don't see any issue. Please provide a script that demonstrates the issue.

Sorry. I am now offering a MRE.

from starlette.applications import Starlette
from starlette.responses import JSONResponse, FileResponse
from starlette.routing import Route

async def json(request):
    print("start json")
    return JSONResponse({'hello': 'world'})

async def file(request):
    print("start file")
    return FileResponse("text_file.txt")

routes = [
    Route("/json", endpoint=json),
    Route("/file", endpoint=file)
]

app = Starlette(debug=True, routes=routes)

This is the file returned by the file interface text_file.txt

This is the log of 50 threads accessing the file interface at the same time

start file
start file
start file
INFO:     127.0.0.1:54279 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54281 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54280 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54287 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
start file
start file
INFO:     127.0.0.1:54294 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54296 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54295 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54297 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54298 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54299 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
start file
start file
INFO:     127.0.0.1:54301 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54302 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
start file
INFO:     127.0.0.1:54303 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54300 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54297 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54304 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54305 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54306 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54307 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54300 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54308 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
start file
INFO:     127.0.0.1:54309 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54311 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54310 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54312 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54308 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54312 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54311 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54313 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54314 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
INFO:     127.0.0.1:54315 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54316 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54314 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54313 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54316 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54315 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54318 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
start file
start file
INFO:     127.0.0.1:54319 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54320 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54321 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54322 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54318 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54323 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54324 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54325 - "GET /file HTTP/1.1" 200 OK
start file
start file
start file
INFO:     127.0.0.1:54328 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54329 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54325 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54331 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54329 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54328 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54325 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54331 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54331 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54329 - "GET /file HTTP/1.1" 200 OK
start file
INFO:     127.0.0.1:54328 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54328 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54329 - "GET /file HTTP/1.1" 200 OK
start file
start file
INFO:     127.0.0.1:54328 - "GET /file HTTP/1.1" 200 OK
INFO:     127.0.0.1:54329 - "GET /file HTTP/1.1" 200 OK

This is the log of 50 threads accessing the json interface at the same time

start json
INFO:     127.0.0.1:58458 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58459 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58463 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58481 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58482 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58483 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58484 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58485 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58481 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58485 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58484 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58486 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58487 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58488 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58489 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58490 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58486 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58491 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58490 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58493 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58494 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58495 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58496 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58497 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58493 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58494 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58498 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58500 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58501 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58502 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58503 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58504 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58505 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58503 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58505 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58508 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58509 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58510 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58508 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58511 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58510 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58509 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58508 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58516 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58517 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58518 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58523 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58517 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58516 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58523 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58518 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58517 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58523 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58523 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58518 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58517 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58516 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58523 - "GET /json HTTP/1.1" 200 OK
start json
INFO:     127.0.0.1:58527 - "GET /json HTTP/1.1" 200 OK

You can see that the interface that return FileResponse("text_file.txt") is sometimes blocked.When the server is under high load, it may take 3-4 seconds to process each request. The first request to be processed will be blocked for a longer time, which may reach 10-30 seconds.Then several requests will respond to the client with HTTP 200 at the same time. When returning a json, this phenomenon does not occur at all.

You can run uvicorn example:app to start the MRE and reproduce the problem

I'm a little confused as to why this is happening.

This is my environment information

(Starlette) majiang@majiangdeMacBook-Pro Starlette % python --version
Python 3.11.9
(Starlette) majiang@majiangdeMacBook-Pro Starlette % pip list
Package    Version
---------- -------
anyio      4.4.0
click      8.1.7
h11        0.14.0
idna       3.7
pip        24.2
setuptools 72.1.0
sniffio    1.3.1
starlette  0.38.2
uvicorn    0.30.6
wheel      0.43.0
majiang213 commented 3 months ago

This is the simulated request configuration I used when testing. You can use it directly starlette_#2664_postman_collection.json

adriangb commented 3 months ago

I'm guessing this is because FileResponse uses anyio.open_file (here) which internally uses anyio.to_thread which in turn has a CapacityLimiter(40).

@majiang213 can you try https://github.com/encode/starlette/issues/1724#issuecomment-1179063924 and set the tokens to some large number?

@Kludex IMO we should just allow a thread per-file. Otherwise I think we may even hit deadlocks (not sure if that's what is happening in this PR or not...)

Kludex commented 3 months ago

There's no blocking code here. The output from the file endpoint doesn't prove that.