FastAPI与Uvicorn响应耗时异常：仅3%耗时来自业务代码求分析

我使用Python3.12结合FastAPI与Sqlalchemy开发后端，为排查耗时引入Server Timing工具。结果显示，总响应耗时395.41毫秒中仅13毫秒被追踪代码捕获，经测试追踪逻辑无误。

通过cURL测试得到：

• 建立连接耗时0.293981秒
• TTFB（首字节时间）1.040998秒
• 总耗时1.041211秒
  连接建立后到发送首字节间的间隔耗时过长。

应用启动命令：

python -m uvicorn fast_api.main:app --host 0.0.0.0

我们通过中间件与装饰器追踪DB、Redis及第三方调用耗时，中间件示例代码如下：

class ServerTimingMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next):
        self._init_tracking()
        response = await call_next(request)
        self._finish_tracking()
        response.headers["Server-Timing"] = self._generate_server_timing_header()
        return response

app.middleware("http")(catch_exceptions_middleware)
app.add_middleware(ServerTimingMiddleware) # this is the middleware
# rest of the middleware

排查方向建议 #

• 中间件执行顺序遗漏：当前ServerTimingMiddleware在catch_exceptions_middleware之后添加，检查是否有其他前置中间件（如认证、请求预处理）的耗时未被统计。比如异常捕获中间件若包含阻塞逻辑，或其他中间件的执行时间未被纳入追踪范围。
• UVicorn进程模型与配置：默认启动命令为单进程单线程，高并发场景下请求会排队等待处理。尝试添加参数--workers 4 --loop uvloop启用多进程和高性能异步事件循环，观察TTFB是否下降。同时检查UVicorn日志级别，大量同步日志IO可能拖慢请求处理。
• SQLAlchemy连接池初始化：确认SQLAlchemy连接池的pool_size、max_overflow配置是否合理。首次请求时可能需要建立数据库连接，这部分耗时未被现有装饰器追踪。可在应用启动时预创建连接池，并单独统计连接建立的耗时。
• 异步代码中的阻塞点：FastAPI基于异步框架，但如果业务代码中使用了同步的SQLAlchemy API、同步Redis客户端等阻塞操作，这些耗时不会被当前异步中间件正确统计。检查所有依赖是否采用异步实现，或同步代码是否通过asyncio.to_thread执行但未被追踪。
• 路由匹配与依赖解析耗时：单独统计从中间件启动到call_next(request)执行前的时间，以及call_next返回后的时间，确认FastAPI的路由匹配、依赖注入（Depends）过程是否存在未被追踪的耗时。
• 系统资源瓶颈：用top、iostat等工具监控服务器CPU、内存、磁盘IO状态。若内存不足导致swap频繁，或CPU被其他进程占用，会导致请求处理被阻塞，这部分耗时不会体现在业务代码追踪中。
• 网络层面隐藏延迟：如果应用部署在容器或云环境中，检查是否存在TCP延迟、负载均衡器转发耗时等网络层面的额外延迟，这类耗时不在应用代码的追踪范围内。
• Server Timing统计范围校验：确认_init_tracking是否在中间件最开始执行，_finish_tracking是否在响应生成后立即执行，避免因时机偏差遗漏耗时统计。同时检查_generate_server_timing_header是否正确汇总了所有装饰器追踪的耗时项，确保没有统计丢失。

内容的提问来源于stack exchange，提问作者Antonio Gamiz Delgado