前言
最近服务上的问题有点多,所以最近盯监控的频率比平时高不少。某天翻内存监控的时候,发现有一段曲线很反常:Min、Average、连平时稳定在 70% 以上的 Max 全都一起砸了下去,三条线一路贴到了刚冷启动那个基准值附近,然后花了大半个小时才一起慢慢爬回正常水位。翻了一下容器编排平台的事件记录,那段时间这台服务几乎所有正在跑的容器都被标记成”不健康”、批量摘掉重建了——不是一两个容器抖了一下,是一次实打实的批量摘流,所以连 Max 都被拖下去了,不是只有 Min 掉了。

查了一下发布记录,那段时间没有任何人做部署,没有任何一次发布,容器不是被”正常发新版本”顺带重启的。如果这一点不排除干净,后面查出来的东西都立不住——批量重启完全可能只是一次很普通的发布导致的,压根不需要往别的地方找原因。确认了这不是发布触发的,才有必要往下继续查。
最让人摸不着头脑的是:数据库那边看起来什么都挺正常的,应用自己也没有 OOM、没有 worker 心跳超时的记录。服务好像哪儿都没坏,但就是被判定成不健康,一批一批地摘掉。
排查到最后,元凶是一处很容易被忽略的代码:一个第三方 SDK,接口写成了 async def,内部实际调用却是纯同步阻塞的。就这一处调用,把整条服务的事件循环冻住了几秒钟,然后像推倒了第一块多米诺骨牌一样,一路带崩了数据库连接池、健康检查,最后演变成大规模摘流重建。记录一下整个排查过程和背后的原理。
一、先排除两个最常见的嫌疑
服务用的是 gunicorn + uvicorn worker,遇到这种异常,惯例先查两条:
- 系统 OOM Killer 强杀进程:内核如果把某个 worker 杀了,gunicorn 主进程发现 worker 消失后会打一条精确措辞的日志(类似
Worker was sent SIGKILL! Perhaps out of memory?)。 - worker 自己心跳超时被判死:uvicorn worker 会周期性给 gunicorn 主进程”打卡”,主进程连续一段时间收不到心跳就认为这个 worker 卡死了,直接强杀重启,日志里会有
WORKER TIMEOUT的记录。
查了一下这两个关键词在事故窗口前后的出现次数——一次都没有。这两个最常见的”容器为什么会被换”的理由,全都对不上。
二、换个角度:容器是被谁摘掉的
应用日志这条路走不通,那就换个角度——去查容器编排平台自己维护的服务事件(这条信息不在应用日志里,是编排平台自己记录的一条独立的操作事件流)。
拉出来一看,事情有眉目了:那几分钟里,编排平台把这台服务几乎全部正在运行的容器都标记成了”不健康”,理由清一色是:
(task xxx) is unhealthy in (target-group ...)
due to (reason Request timed out).
也就是说,这是负载均衡器主动发起的健康检查探测超时——不是进程真的挂了,是进程对健康检查探针的响应太慢,慢到超过了负载均衡器的判定阈值,被摘掉重建。而且是一波接一波的:摘掉几个之后,剩下的容器要扛更多流量,响应更慢,又有更多容器被摘,滚雪球一样摘了一大圈。

这一步基本能定性了:进程本身大概率没死,是响应健康检查慢到被外部误判成死了——跟”没有 OOM、没有 worker timeout”完全对得上,因为这本来就是两套独立的判定机制。
三、往回查:那几秒钟到底在忙什么
翻这批容器被摘掉前几十秒的业务日志,找到一大批数据库报错,大意是”连接池里的连接都被占满了,排队等了 30 秒还是没等到,只能放弃”(QueuePool limit ... connection timed out,SQLAlchemy 连接池的标准报错)。
单看这条报错不算稀奇,高并发下连接池被打满不是新鲜事。但奇怪的是这些报错的时间戳几乎全部挤在同一个不到一秒的窗口里,有大几十条。正常情况下连接池被打满、大家各自排队各自超时,报错应该是散开分布的——每个请求发起排队的时间点不一样,各自的 30 秒倒计时该在不同时刻到期。这种”扎堆”的形状不太对劲,也跟前面”数据库看起来挺稳定”这件事对上了:如果真是数据库容量不够,报错该是均匀散开的,不该扎堆。

更像是”这些请求的倒计时其实早该到期,但触发倒计时回调的那个东西,中间有一段时间没能正常运转,直到它恢复运转的瞬间,攒着没触发的回调才一股脑全部执行”。也就是说:不是数据库不够用,是有什么东西把承载这套超时机制的事件循环,冻住了一段时间。
四、揪出真凶:一处”看起来异步、实际同步”的调用
带着”事件循环被冻住”这个猜测,回头去查这台服务当时在跑什么,重点找那种写在 async def 里、内部实际调用却是同步阻塞的地方(这种代码骗得了眼睛骗不了事件循环,async/await 不会自动把一个普通同步函数调用变成非阻塞的)。
翻到一处:项目里很早以前就接了一个第三方 AB 实验/特性开关平台的官方 SDK,从提交记录看这段封装代码写得挺早,那会儿的流量应该还没现在这么大,这种同步阻塞的调用大概率一直没怎么被感知到。项目里的代码出自不同人手,整体质量参差不齐,类似这种”看起来异步、实际同步”的坑不是谁刻意留下的,更像是历史遗留、没人特别在意——直到最近流量涨上来,才被放大成了一次实打实的雪崩。封装代码大概是这样:
class ExperimentManager:
_client = None
@classmethod
async def fetch_variants(cls, *, device_id, user_id) -> dict:
"""docstring 里写着"用线程避免阻塞事件循环"……"""
if cls._client is None:
return {}
user = User(device_id=device_id, user_properties={...})
# 这一行是纯同步调用,SDK 内部走的是同步 HTTP 客户端
variants = cls._client.fetch_v2(user)
return {k: v.value for k, v in (variants or {}).items()}
docstring 写得挺好——”用线程池避免阻塞事件循环”,但实际代码里根本没有 asyncio.to_thread 或任何形式的线程调度,cls._client.fetch_v2(user) 就是原地一个同步方法调用。这个 SDK 自己配置的参数是”3 秒超时、失败重试一次、重试前退避 0.3~2 秒、重试再给 3 秒”,单次调用理论上限能到小几秒。
去查这个 SDK 自己打的失败日志,正常情况下几乎为零,但在事故那一分钟内,失败次数直接冲到了几百次,而且这个暴增的时间点,正好卡在数据库连接池扎堆爆发之前。

三条证据链的时间顺序对上了:这个同步调用先卡住事件循环 → 期间所有靠事件循环调度的东西(等数据库连接、等健康检查)全部被拖长排队时间 → 事件循环恢复的瞬间集中爆发一批超时 → 健康检查答不上来 → 负载均衡器判超时 → 编排平台开始摘容器。
五、一个疑点:为什么下游的风暴比触发源持续更久
把两条时间线摆在一起看,有个地方不太对称:那个 SDK 的失败日志只在一分钟内集中爆发,过了这一分钟就彻底没有了;但数据库连接池的超时报错却是从这一分钟结束才刚起步,一直持续了将近十分钟才收尾,累计报了七万多条。这里要先说清楚一句:数据库本身在这段时间里没有出问题——连接数、CPU 这些核心指标一直很平稳,这些报错全部是应用这一侧的连接池自己排队排不到、主动放弃抛出来的(QueuePool 是 SQLAlchemy 在应用进程里自己维护的池子,不是数据库物理连接数被打满了),跟数据库容量没关系,是应用层自己的问题。
那问题就来了:触发源只闹了一分钟,下游的应用层报错凭什么要持续十倍的时间?
具体看这段时间连接池报错的分布,不是一次性炸开就完事,是接连出现了 5 个明显的波峰,横跨大约十分钟,每个波峰间隔大致都在 2 分钟左右,整体形状是”先小幅起势,中间两三波顶到全程最高,最后逐渐衰减收尾”——是一种有节奏的震荡,不是杂乱噪声。这背后大概是两层机制叠在一起:
第一层,摘流引发的雪崩反馈:Amplitude 那次冻住事件循环之后,第一批容器因为答不上健康检查被摘掉重建,它们原来扛着的那部分流量转移到了剩下的容器上——剩下的容器一下子要扛更多请求,连接池的竞争自然更激烈,于是又有更多容器因为响应变慢被判定不健康、被摘掉。这个反馈环一旦转起来,不需要 Amplitude 继续添乱,自己就能维持一段时间的震荡,直到摘掉/重建的节点数量达到某个平衡点才会停下来——这也解释了为什么报错是一波一波的:每一波大致对应一轮”摘除 → 冲击 → 再摘除”的循环,跟健康检查加上编排平台重建节点的周期节奏对得上。
第二层,重启本身也在制造新的资源紧张:一个容器被摘掉重建之后,新容器起来的第一件事是从零重新建立整个连接池——池子里那些连接不是配置写了数字就自动有的,是要一个个真去建 TCP 连接、走数据库认证握手的。如果一批容器在短时间内接连重启,这些新容器会几乎同时抢着建立大量新连接,这个”建连接”的动作本身也要花时间、也要排队,相当于在本就紧张的资源上又叠加了一轮”挤兑”,进一步拉长了恢复所需的时间。
也就是说,Amplitude 那一次同步调用只是推倒了第一块骨牌,它本身停下来之后,后面这一连串效应已经有了自己的惯性,要靠上面这两层机制自己耗完才能真正停下来——这也是这类雪崩故障最麻烦的地方:根因可能只作祟了一分钟,但收拾烂摊子要花上十倍的时间。
六、拆一下原理:为什么一次同步调用能把这么多东西一起带下水
这里有几个细节,排查过程里反复确认过,值得单独拎出来讲清楚。
1. “写在 async 函数里”不等于”这行代码就是异步的”
async/await 只在真正的 await 表达式那个点上才会挂起协程、让出控制权。函数体里直接调用一个普通同步阻塞函数(没有 await,因为它根本不是一个 awaitable),Python 不会因为外层是 async def 就自动帮你插入挂起点——就是普通地执行、普通地等、普通地返回。
关键是:asyncio 的事件循环全程只有一个线程在跑,所有协程轮流在这一个线程上执行。真正的异步等待会把控制权交还给这个线程,让它去调度别的协程;而一次裸同步调用,会把这唯一的线程原地占用,直到它自己返回为止——这段时间里,这个线程没法做任何别的事,包括调度其他协程、接收新连接。
2. 那把健康检查接口改成同步的,能不能避免 task 被频繁摘流?
结合上一节的分析,这里其实是两层问题:第一层,事件循环在那几秒钟里确实是被真正卡住的,这是事实,没什么好绕的;第二层,是 task 因为答不上健康检查被判定 unhealthy、被频繁摘流,摘流本身又反过来放大了后续的拥堵——也就是上一节讲的那个持续了将近十分钟的雪崩。
所以问题应该问得更精确一点:如果把健康检查接口写成同步的,是不是至少能让它在事件循环被卡住的那几秒钟里也正常响应,从而避免 task 被判定 unhealthy、避免被摘流,把这条雪崩链路从源头掐掉?
答案还是不行,原因跟前面一样:不管一个接口最终是同步还是异步实现,请求进来的第一步永远要先经过事件循环——是它负责监听端口、接住新连接、解析出 HTTP 请求,然后才谈得上”这个接口该自己跑,还是丢进线程池”。事件循环这一步都过不去,压根轮不到”丢给线程池”这个动作发生。所以哪怕把健康检查接口改成同步的,在事件循环真被冻住的那几秒钟里,它一样答不上来,一样会被判定 unhealthy,一样会被摘流——这条雪崩链路没法从”接口同步还是异步”这个层面被掐断,这条路本身就走不通。
3. 为什么超时会扎堆爆发
数据库连接池的排队超时,底层一般靠事件循环的定时器机制(”若干秒后回调一次,检查是否等到了资源”)实现,同样依赖事件循环持续运转才能按时触发。事件循环被冻住的这段时间里,所有原本该依次到期的定时器全部攒着不动,直到它恢复运转的那一瞬间,才会一次性批量触发——这就是”扎堆”现象的成因,也是判断”是不是事件循环被冻住过”的一个好用信号:同一类超时报错大量挤在同一个极短窗口里,而不是均匀分布,基本可以怀疑是调度层出了问题,不是资源真紧张到那个程度。
4. 进程心跳 ≠ 单个接口的响应时间
gunicorn 判断一个 worker 是否”活着”,靠的是这个 worker 有没有按时打心跳,是进程级别的存活检查,跟某一个具体请求跑了多久是两个维度。只要事件循环本身还在正常调度,心跳就能按时跳;某个请求哪怕跑几分钟,只要是”体面地在 await”而不是”裸同步占着不放”,进程心跳都不受影响,gunicorn 不会去杀这个 worker。
反过来,“进程心跳正常”从来不能证明”每个接口都响应及时”——这是两件独立的事,靠一套机制去兜底另一件事,本身就是容易被忽视的架构缺口。
七、修复思路
真正要修的是那个”伪异步”调用,把它老老实实丢进线程池:
variants = await asyncio.to_thread(cls._client.fetch_v2, user)
这样一改,这个 SDK 调用哪怕真的卡上几秒,也只是占用线程池里的一个线程名额,事件循环本身完全不受影响,其他协程(包括健康检查)照常调度。
顺手也重新审视了几个内部超时数值之间的关系:数据库连接池的排队等待超时、负载均衡器的健康检查判定阈值、gunicorn 自己的 worker 心跳超时,原来是各自拍脑袋定的,凑巧还撞了同一个数量级,一旦真的发生资源紧张,几套机制几乎同时触发,互相印证成”真的死了”,反而放大了雪崩效应。后续把这几个数值按”谁的爆炸半径小就该谁先兜底”的原则重新理了一遍优先级:局部的资源等待超时应该明显小于进程级看门狗的超时,这样资源紧张时永远是”这一个请求体面地失败”先发生,不会惊动”杀掉整个进程、陪葬一堆其他正常请求”这种更粗暴的机制。
总结
这次排查最大的收获,是把”进程存活”和”单个请求健康”这两个原本容易被混着想的概念,彻底拆干净了——它们是两套独立的机制,一套只关心”事件循环还在不在转”,另一套关心”这一个请求到底跑了多久”,谁也不能替代谁兜底。
另外一个更朴素的教训是:async def 只是一个语法外壳,它不会自动检查函数体里的调用是不是真的异步。 接第三方 SDK 的时候,哪怕文档或者 docstring 写得信誓旦旦说”已经在线程里跑了、不会阻塞”,也值得抽时间去翻一下它底层到底有没有真的这么做——尤其是那些历史悠久、可能还没跟上项目里其它部分异步化步伐的封装代码,往往就是这类”伪异步”最容易藏身的地方。而一旦真的踩上,代价往往不是”这一个接口慢一点”这么简单,而是像这次一样,顺着事件循环这根唯一的调度轴,把看起来毫不相关的一堆机制全部拖下水。
本博客所有文章除特别声明外,均采用 @Oreoft 许可协议。转载请注明出处!
┌┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┬┐
├ 记得关注公众号:没有气的汽水 ┤
└┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┴┘