这篇我按时间线写。事故发生在两年前一个周四晚上,我做的是主要排查人。时间是我从聊天记录和监控截图里对出来的,误差不超过两分钟。
21:47
报警群里第一条消息:接口平均响应时间从 80ms 涨到 1.2s。我当时在洗碗,手机响的时候手是湿的。
21:53
打开监控。错误率还不高,只有 0.3%,但 P99 已经到 8 秒。第一反应是数据库慢查询,去看 DB 的 CPU——18%,很正常。QPS 也没有异常,还是白天那个量级。
这是第一个让我困惑的点:负载没变,响应变慢了。
22:10
看了应用的线程池指标。活跃线程数打满 200,队列积压 3000+。所以是应用侧在等什么东西。
我做了一件后来觉得非常正确的事:直接在一台机器上 dump 了线程栈。180 多个线程卡在同一个位置——获取数据库连接。
22:25
连接池配置是 max 50。DB 那边看到的活跃连接确实是 50,全部处于 sleep 状态但没被释放。
也就是说,连接被借出去了,但没还回来。典型的连接泄漏。
22:40 — 第一次误判
我去翻当天的发布记录,找到一个下午 6 点上的改动,里面有一段手写的 JDBC 调用。我盯着看了十分钟,觉得 finally 里少了 close,兴冲冲地喊回滚。
回滚了。没有任何变化。
后来复盘我才承认,那段代码其实是有 try-with-resources 的,我看漏了。凌晨的眼睛不可信,这是我那晚学到的第一课。
23:15
降级止血。我们把非核心的三个接口直接返回缓存兜底数据,把连接需求压下去。P99 从 8 秒降到 2.4 秒,勉强能用。用户投诉停了。
这一步花了我 6 分钟,效果比前面 90 分钟都好。教训是:止血优先于定位。我前面浪费了太多时间在「想搞清楚原因」上。
次日 01:30
接着挖。我们把连接池换成了带泄漏检测的配置,leakDetectionThreshold 设成 30 秒,重启一台机器观察。
十分钟后日志里出现了栈:泄漏点在一个报表导出的定时任务里。这个任务用了一个游标式的查询,逐行读,读完再关连接。平时数据量小,两秒读完。
次日 02:10 — 找到真凶
那天下午运营导入了一批数据,让某张表从 40 万行涨到了 1100 万行。定时任务的查询没有分页,一次性游标扫全表,单次持有连接的时间从 2 秒变成了 40 分钟。
而这个任务每 5 分钟触发一次。于是连接一个一个被吃掉,累积到 50 个,池子空了。
整条因果链是:数据量增长 → 慢任务 → 连接长期占用 → 池耗尽 → 所有接口排队。中间没有任何一环是「代码 bug」,每一环单独看都是合理的。
次日 02:40
给那个任务加了分页和单独的连接池(max 5),重启。指标 10 分钟内全部恢复正常。我在群里发了个「已恢复」,然后睡了三个小时。
次日 10:00 — 复盘会
复盘会上我们列了四条改进项,我印象最深的是第三条:任何定时任务必须用独立的资源池。理由是后台任务和在线请求的失败代价完全不同,不应该共享同一个会耗尽的资源。
另外两条也值得写下来:所有连接池默认开启泄漏检测;核心表加行数增长报警,单日增幅超过 50% 就告警。
次日 21:00 — 我自己的复盘
官方复盘之外,我自己记了三条:
- 我在 22:40 那次误判上浪费了 35 分钟,根本原因是我在用「猜」代替「看」。线程栈那个证据 22:10 就拿到了,我却去翻发布记录找嫌疑人。
- 止血手段应该提前准备好开关,而不是事故当场写代码。我们那三个降级开关是现改的配置,如果早有开关,21:55 就能止血。
- 「负载没变但变慢了」这个信号,几乎必然指向资源持有时间变长,而不是资源需求变多。这句话我贴在了工位上。
事故本身不可怕,可怕的是同样的事故发生第二次。到现在两年了,没再出现过。