Java

线上故障排查时,为什么很多人第一步就查错了方向?

10:22,网关 504 一片红,群里第一反应是“先查网关”。可把线程队列、active count、重试开关和下游持有时间放回同一条时间线后,先分叉的其实是 `order-service` 内部等待链,而不是最外面的红灯。

  • 故障排查
  • 方法论
  • 稳定性
  • 线上问题
  • Java
17 分钟阅读

10:22,那次事故群里刷得最快的是网关 504 图。

于是第一波动作也很一致:

  • 去翻 ingress access log
  • 看网关 upstream timeout
  • 怀疑是不是连接被上游打满了

这些动作不算错,但它们都默认了一件事:最显眼的红灯,就是最早出问题的地方。

后来把现场几组数摆到一条线上,结论正好相反。网关 504 只是最后冒出来的外层结果,真正先分叉的,是 order-service 自己的工作线程和下游持有时间。

把最亮的红灯和最早的分叉放到一条时间线上

那次事故真正有用的,不是某一张特别红的监控图,而是下面这条时间线:

时间证据变化
10:17:46配置中心推送 payment.retry.enabled=truepayment.retry.max-attempts=2支付失败请求开始允许应用内重试
10:18:11orderSubmitExecutor.active从 21 拉到 64,贴住线程池上限
10:18:34orderSubmitExecutor.queue.size从 0 涨到 148,之后一路抬到 900+
10:19:02paymentClient.holdTime.p95从 110ms 升到 780ms
10:20:16paymentClient.holdTime.p95继续升到 1.8s
10:22:03网关 504 rate开始从 0 抬到 18%
10:24:00业务反馈用户开始集中报“下单卡住”

这条线一摆出来,网关就不再像第一现场了。

因为在 504 出来之前,应用内部已经先有三件事同时变坏:

  • 工作线程 active count 顶满
  • 工作线程队列开始排长队
  • 支付下游调用的持有时间明显拉长

如果最早的分叉已经发生在应用内部等待链里,那第一步还一直盯着网关,方向大概率会越查越偏。

真正把方向掰回来的,是线程池、重试开关和下游持有时间

我们当时不是靠“经验判断”把方向掰回来的,而是靠几条能互相咬合的现场证据。

先看线程池指标。order-service 负责下单提交的线程池配置是固定的:core=32max=64queueCapacity=1000。事故窗口里它的形状很怪:

时间active countqueue sizecompleted task/s
10:1719~240210
10:1864148208
10:1964436171
10:2064712129
10:216490397

如果是网关自己先出问题,你更常看到的是入口错误率先抬,应用内部工作线程还没这么快被顶死。

但这里的形状是:线程先被占满,队列先开始堆,完成速率反而往下掉。这已经更像应用内部有一批请求迟迟放不下来。

再看重试开关。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

这几条日志和线程池指标放一起,现场就很具体了:

  • 支付调用一旦慢下来,请求不会马上退出
  • 重试开关打开后,同一笔失败请求会在应用内部再占一轮线程和下游连接
  • 线程迟迟不释放,orderSubmitExecutor active 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 sizepayment holdTime p95gateway 504 rate
10:269182.1s18.4%
10:28402690ms6.7%
10:29173340ms1.9%
10:3041180ms0.3%

这里最关键的不是“指标变好了”,而是它们按一条很顺的链在回落:

  • 先是支付调用持有时间缩短
  • 然后工作线程队列开始消化
  • 最后网关 504 跟着一起下去

如果网关真是第一现场,这组回落顺序通常不会长成这样。

所以很多人第一步会查偏,不是因为不会查,而是太容易被外层暴露带走

回看那次事故,误判并不神秘。

10:22 出现在大屏上的,确实是网关 504;最先在群里被贴出来的,也确实是网关日志。人在高压下先扑最红的图,很正常。

问题在于,最外层的报错往往负责“把后果放大给人看”,不负责告诉你“哪一层先离开正常状态”。那次现场真正更早开口说话的,是下面这些东西:

  • 线程池 active count 先顶住上限
  • 队列长度先开始持续堆高
  • 重试开关正好在前一分钟被打开
  • 下游持有时间先从 100ms 级别拖到秒级

把这些证据连起来以后,那篇题目里的“为什么很多人第一步就查错了方向”,答案其实已经自己长出来了:

因为事故现场最容易先看到的,是最外层最亮的红灯;可真正最早分叉的,常常藏在里面那条已经开始排队、重试、持有不放的等待链上。

那次如果一直围着网关查,也不是永远查不出来,但会多绕一大圈。真正把方向缩短的,不是一句“别被现象迷惑”,而是这一串很硬的先后顺序:

重试开关先开,支付持有时间先长,工作线程先顶满,队列先堆起来,504 最后才一起爆出来。