FastAPI + Gunicorn Worker请求处理异常问题排查

问题 #

使用FastAPI示例代码，通过gunicorn启动10个UvicornWorker运行服务时，请求处理出现异常：同时发送6个请求时，第一个请求立即处理，剩余5个需等待第一个完成后才批量执行；后续新请求会排队，待当前批量请求处理完成后，重复此“单请求先处理+批量执行剩余”的模式。

启动命令 #

gunicorn -k uvicorn.workers.UvicornWorker main:app --bind unix:/tmp/gunicorn.sock -w 10 -t 120

示例代码 #

app = FastAPI()

@app.get("/ping")
async def ping():
    print("Start")
    time.sleep(20)
    print("Done")
    return JSONResponse(status_code=200, content="OK",media_type="application/json")

相关日志 #

INFO:     Uvicorn running on http://127.0.0.1:7777 (Press CTRL+C to quit)
INFO:     Started reloader process [5756] using WatchFiles
INFO:     Started server process [75304]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
Start
Done
INFO:     127.0.0.1:53432 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Start
Start
Start
Done
INFO:     127.0.0.1:53432 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53433 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53461 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53462 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53464 - "GET /ping HTTP/1.1" 200 OK
Start
Done
INFO:     127.0.0.1:53518 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Start
Start
Start
Start
Done
Done
INFO:     127.0.0.1:53519 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53555 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53558 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53561 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53567 - "GET /ping HTTP/1.1" 200 OK
Start
Done
INFO:     127.0.0.1:53567 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Start
Start
Start
Done
INFO:     127.0.0.1:53567 - "GET /ping HTTP/1.1" 200 OK
Start
Done
INFO:     127.0.0.1:53589 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53611 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53616 - "GET /ping HTTP/1.1" 200 OK
Done
Done
INFO:     127.0.0.1:53567 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Start
Done
INFO:     127.0.0.1:53567 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Start
Done
INFO:     127.0.0.1:53655 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53678 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53567 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53689 - "GET /ping HTTP/1.1" 200 OK
Start
Done
Done
INFO:     127.0.0.1:53689 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Start
Start
Start
Done
INFO:     127.0.0.1:53689 - "GET /ping HTTP/1.1" 200 OK
Start
Done
INFO:     127.0.0.1:53718 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53745 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53749 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53753 - "GET /ping HTTP/1.1" 200 OK
Done
INFO:     127.0.0.1:53689 - "GET /ping HTTP/1.1" 200 OK
Start
Start
Done
INFO:     127.0.0.1:53689 - "GET /ping HTTP/1.1" 200 OK

原因分析 #

核心问题是异步接口中调用了同步阻塞的time.sleep(20)，具体影响如下：

• UvicornWorker基于单线程异步IO模型，依赖非阻塞操作实现并发处理。但time.sleep是同步阻塞调用，会直接卡住当前worker的事件循环，导致该worker在20秒内完全无法处理其他请求。
• 结合客户端的HTTP长连接（Keep-Alive）机制，同一个客户端发送的多个请求会被分配到同一个worker进程。第一个请求触发time.sleep阻塞该worker后，后续的5个请求只能排队等待该worker的事件循环恢复，所以会出现“第一个请求先完成，剩余5个批量执行”的现象。
• 即使启动了10个worker，只要请求来自同一个客户端的复用连接，就会集中到同一个worker上，无法利用多worker的并发能力，最终表现为请求排队处理的异常模式。

内容的提问来源于stack exchange，提问作者Arjun Gamer