线上故障排查时,为什么很多人第一步就查错了方向?
10:22,网关 504 一片红,群里第一反应是“先查网关”。可把线程队列、active count、重试开关和下游持有时间放回同一条时间线后,先分叉的其实是 `order-service` 内部等待链,而不是最外面的红灯。
10:22,那次事故群里刷得最快的是网关 504 图。
于是第一波动作也很一致:
- 去翻 ingress access log
- 看网关 upstream timeout
- 怀疑是不是连接被上游打满了
这些动作不算错,但它们都默认了一件事:最显眼的红灯,就是最早出问题的地方。
后来把现场几组数摆到一条线上,结论正好相反。网关 504 只是最后冒出来的外层结果,真正先分叉的,是 order-service 自己的工作线程和下游持有时间。
把最亮的红灯和最早的分叉放到一条时间线上
那次事故真正有用的,不是某一张特别红的监控图,而是下面这条时间线:
| 时间 | 证据 | 变化 |
|---|---|---|
| 10:17:46 | 配置中心推送 payment.retry.enabled=true、payment.retry.max-attempts=2 | 支付失败请求开始允许应用内重试 |
| 10:18:11 | orderSubmitExecutor.active | 从 21 拉到 64,贴住线程池上限 |
| 10:18:34 | orderSubmitExecutor.queue.size | 从 0 涨到 148,之后一路抬到 900+ |
| 10:19:02 | paymentClient.holdTime.p95 | 从 110ms 升到 780ms |
| 10:20:16 | paymentClient.holdTime.p95 | 继续升到 1.8s |
| 10:22:03 | 网关 504 rate | 开始从 0 抬到 18% |
| 10:24:00 | 业务反馈 | 用户开始集中报“下单卡住” |
这条线一摆出来,网关就不再像第一现场了。
因为在 504 出来之前,应用内部已经先有三件事同时变坏:
- 工作线程 active count 顶满
- 工作线程队列开始排长队
- 支付下游调用的持有时间明显拉长
如果最早的分叉已经发生在应用内部等待链里,那第一步还一直盯着网关,方向大概率会越查越偏。
真正把方向掰回来的,是线程池、重试开关和下游持有时间
我们当时不是靠“经验判断”把方向掰回来的,而是靠几条能互相咬合的现场证据。
先看线程池指标。order-service 负责下单提交的线程池配置是固定的:core=32、max=64、queueCapacity=1000。事故窗口里它的形状很怪:
| 时间 | active count | queue size | completed task/s |
|---|---|---|---|
| 10:17 | 19~24 | 0 | 210 |
| 10:18 | 64 | 148 | 208 |
| 10:19 | 64 | 436 | 171 |
| 10:20 | 64 | 712 | 129 |
| 10:21 | 64 | 903 | 97 |
如果是网关自己先出问题,你更常看到的是入口错误率先抬,应用内部工作线程还没这么快被顶死。
但这里的形状是:线程先被占满,队列先开始堆,完成速率反而往下掉。这已经更像应用内部有一批请求迟迟放不下来。
再看重试开关。10:17:46 配置中心正好有一条变更日志:
10:17:46 INFO DynamicConfigRefresher - update key=payment.retry.enabled old=false new=true
10:17:46 INFO DynamicConfigRefresher - update key=payment.retry.max-attempts old=0 new=2
这个时间点和线程池开始分叉几乎贴在一起。
然后是支付下游的持有时间。我们没有先看到支付彻底报错,先看到的是调用被长时间占着不放:
10:19:08 WARN PaymentClient - hold connection too long traceId=9f7a... cost=812ms retry=1
10:19:31 WARN PaymentClient - hold connection too long traceId=12bc... cost=1436ms retry=2
10:20:17 WARN PaymentClient - hold connection too long traceId=44de... cost=1827ms retry=2
这几条日志和线程池指标放一起,现场就很具体了:
- 支付调用一旦慢下来,请求不会马上退出
- 重试开关打开后,同一笔失败请求会在应用内部再占一轮线程和下游连接
- 线程迟迟不释放,
orderSubmitExecutoractive count 很快顶满 - 新请求继续进来,只能在队列里排队
- 排队时间再叠加进去,网关外面才开始看到 504
也就是说,504 不是根因层发出的第一声,而是等待链已经拖长以后,最外层替你把后果喊出来了。
那次现场真正说服人的,是“关掉重试”之后整条链一起回落
如果只有前面的时间线,还可以说这是“推测”。真正把主线坐实的,是后面的回退验证。
10:27,我们先没有动网关,而是把刚打开的支付重试开关关回去:
10:27:14 INFO DynamicConfigRefresher - update key=payment.retry.enabled old=true new=false
10:27:14 INFO DynamicConfigRefresher - update key=payment.retry.max-attempts old=2 new=0
后面 3 分钟,几组数一起掉头:
| 时间 | queue size | payment holdTime p95 | gateway 504 rate |
|---|---|---|---|
| 10:26 | 918 | 2.1s | 18.4% |
| 10:28 | 402 | 690ms | 6.7% |
| 10:29 | 173 | 340ms | 1.9% |
| 10:30 | 41 | 180ms | 0.3% |
这里最关键的不是“指标变好了”,而是它们按一条很顺的链在回落:
- 先是支付调用持有时间缩短
- 然后工作线程队列开始消化
- 最后网关 504 跟着一起下去
如果网关真是第一现场,这组回落顺序通常不会长成这样。
所以很多人第一步会查偏,不是因为不会查,而是太容易被外层暴露带走
回看那次事故,误判并不神秘。
10:22 出现在大屏上的,确实是网关 504;最先在群里被贴出来的,也确实是网关日志。人在高压下先扑最红的图,很正常。
问题在于,最外层的报错往往负责“把后果放大给人看”,不负责告诉你“哪一层先离开正常状态”。那次现场真正更早开口说话的,是下面这些东西:
- 线程池 active count 先顶住上限
- 队列长度先开始持续堆高
- 重试开关正好在前一分钟被打开
- 下游持有时间先从 100ms 级别拖到秒级
把这些证据连起来以后,那篇题目里的“为什么很多人第一步就查错了方向”,答案其实已经自己长出来了:
因为事故现场最容易先看到的,是最外层最亮的红灯;可真正最早分叉的,常常藏在里面那条已经开始排队、重试、持有不放的等待链上。
那次如果一直围着网关查,也不是永远查不出来,但会多绕一大圈。真正把方向缩短的,不是一句“别被现象迷惑”,而是这一串很硬的先后顺序:
重试开关先开,支付持有时间先长,工作线程先顶满,队列先堆起来,504 最后才一起爆出来。