asyncio 接口集体超时:同步调用阻塞事件循环

工单服务月末高峰期一批请求集体冻结,p99 从 300ms 飙至 8s,CPU 却只有 12%。根因是新增功能里同步 SDK 调用阻塞了 asyncio 事件循环,改用 to_thread 隔离并补事件循环延迟监控后恢复。

问题背景

工单聚合服务是客服系统的入口层:聚合工单、客户、物流三块数据后返回给坐席工作台。服务用 Python 3.11 + FastAPI + uvicorn 部署在 K8s 上,4 个 worker,平时 300 QPS 上下,p99 稳定在 300ms 以内。两周前上线了一个小功能——坐席点开工单详情时顺带查询关联包裹的物流轨迹,数据源是物流厂商提供的同步 SDK。

这个功能代码量不到一百行,测试环境点了十几单都正常,顺利上线。它的第一周风平浪静,直到月末结算日:当天上午 10:20 开始,客服大面积反馈"工作台转圈",监控上 p99 一路飙到 8 秒以上,部分请求直接超时断开。

故障现象

  • 延迟集体恶化且不均匀:同一分钟内,大部分请求 200ms 内返回,但有一批请求卡 5~10 秒后失败——不是整体匀速变慢,而是"一批一批地冻住"。
  • 资源全是闲的:故障期间 CPU 12%、内存平稳、GC 正常、数据库连接池正常、下游依赖的延迟也没变化——常规性能瓶颈一个都对不上。
  • 日志出现时间断层:某些日志相邻两行的时间戳差了好几秒,而这两行之间只是普通的参数校验,理论上应该是微秒级。
  • 存活探针开始间歇失败,3 个 Pod 先后重启,处理中的请求被掐断,客户端重试又把流量抬高了一截。
  • 回滚掉两周前的物流查询功能后故障消失——此时已过去 40 分钟,高峰也基本过去了。

排查过程

第一步,先证伪常见的四类瓶颈。 CPU、内存、GC、连接池、下游依赖全部正常,而 p99 暴涨——“资源全闲、延迟爆表"这个组合本身就指向一个方向:请求不是在等资源,而是在排队;让它们排队的不是 I/O,是执行机会。

第二步,抓住日志时间断层。 参数校验这种纯同步代码出现秒级断层,说明进程在那一刻"没人干活”——不是慢,是停了。同步代码不会自己停几秒,唯一解释是它所在的线程根本得不到执行。

第三步,给事件循环装上"测速仪"。 在服务里加了一个后台协程:每 100ms 醒来一次,用 loop.time() 记录自己实际睡了多久。正常情况下漂移在几毫秒内;故障复现时,这个"事件循环延迟"直接冲到 3.8 秒。证据坐实:事件循环被长时间独占,同循环上所有协程集体饿死。

第四步,用 py-spy 定位是谁占着循环。 py-spy dump 可以在生产 Pod 上免重启抓调用栈,主线程的栈停在 ssl 模块的 socket read 里,上层是物流 SDK 的 requests 调用,再上层正是新增的轨迹查询 handler——它写成了 async def,函数体里却直接调了同步 SDK。

第五步,解释"为什么是间歇性"。 4 个 uvicorn worker 各自有一个事件循环,负载轮询分配。只有恰好落到"正在被同步调用阻塞"的那个 worker 上的请求才会冻结;而且第三方 SDK 的响应时间随对方负载波动(月末对账高峰恰好是他们的慢时段),阻塞时长时短,故障看起来就飘忽不定。这也解释了测试环境为何复现不了——压不出并发,也赶不上对方慢。

解决方案

  1. 止血:把同步 SDK 调用包进 asyncio.to_thread(),配一个专用线程池(max_workers 显式设为 20,不用默认的无界池),并加 asyncio.wait_for 5 秒超时;热修复滚动发布后 p99 回落到 400ms 以内。
  2. 加固:事件循环延迟接入告警(漂移超 500ms 预警、超 2s 升级);延长优雅下线时间减少重启时的请求掐断;客户端重试改为指数退避,抑制重试风暴。
  3. 治本:推动物流厂商 SDK 的异步化(httpx 异步客户端版本),过渡期内所有同步依赖统一走线程池通道。
  4. 防回归:CI 引入 flake8-async / ruff 的 ASYNC 规则族,拦截 async def 里直接调用同步 requests、time.sleep、阻塞式文件打开等写法;代码评审清单新增一条"新增依赖必须声明同步还是异步"。

根因分析

直接根因是在 asyncio 事件循环里直接调用同步阻塞的 SDK:同步网络 I/O 不会让出控制权,事件循环被按住在那一刻,同一个 worker 上所有协程一起停摆。深层根因有两个:一是心智模型错位——“函数写成 async def“被当成了"它不阻塞”,而 Python 的异步是协作式的,只要有一处不同步地阻塞,整个循环一起遭殃;二是监控盲区——团队盯了 CPU、内存、GC 所有资源指标,却没有"事件循环延迟"这个直指调度健康的指标,故障发生 20 分钟后才靠人肉发现日志断层。

预防措施

  • 事件循环延迟纳入所有 asyncio 服务的标准监控与告警;
  • async handler 的外部调用四选一:异步客户端 / asyncio.to_thread / 进程池 / 拆到独立服务,禁止裸调同步依赖;
  • 压测场景必须包含"慢依赖"注入(代理延迟或故障注入),不能只测快路径;
  • 探针与重启策略评审:评估重启对请求处理中任务与重试放大效应的影响;
  • py-spy 纳入生产排障工具箱,定期演练免重启抓栈。

总结

这次事故最值得记住的一幕,是"所有资源都闲、所有请求都在转圈”——它几乎是在明说:问题不在资源,在调度。asyncio 用得好,是把并发做得又轻又省;用不好,就是一根同步调用卡死整条流水线。给团队留下的三件东西:一个监控指标(事件循环延迟)、一条禁令(async 里不裸调同步)、一个工具(py-spy),比这次故障本身值钱得多。

延伸阅读

使用 Hugo 构建
主题 Stack 由 Jimmy 设计