慢接口排查时,日志、Trace、指标三者先看谁?
慢接口现场最怕不是工具不够,而是三种证据一起翻却没有顺序。很多时候先决定证据顺序,比分别把日志、Trace 和指标都看一遍更重要。真正稳的做法,往往是先用指标切范围,再用 Trace 拆耗时,最后再让日志补上触发条件和上下文。
有一次慢接口排查,最先把大家带偏的不是技术问题,而是一条日志。
值班同学在 order/confirm 的应用日志里很快搜到几条看起来很刺眼的 warning:
- 下游优惠服务调用耗时 2.8 秒
- 某个租户参数缺失,触发默认兜底路径
- 少量请求命中本地重试
这些信息都是真的,所以大家很自然地开始往日志里钻。十几分钟后,群里已经贴满了 warning、error、traceId 和异常片段,但还是没人说得清三件事:
- 这次到底是单接口慢,还是一组接口都慢。
- 是所有实例一起慢,还是部分实例先坏。
- 优惠服务的 2.8 秒到底是主因,还是只是已经被拖慢后的结果。
后来把时间线拉回去看,真正让方向收敛的第一张图其实不是日志,而是一张分实例 RT 曲线:12 台实例里只有 3 台在 19:42 之后 P99 突然抬头,其余 9 台基本平稳。
也就是说,日志最先给了细节,但没有先给范围。
这也是我现在更愿意坚持一个默认顺序的原因:
慢接口排查里,先回答“问题长什么样”,再回答“某个请求里发生了什么”。
很多时候,这意味着先看指标,再看 Trace,最后再让日志把上下文补齐。
那次事故里,为什么日志先出现,方向却还是错的
日志之所以容易让人第一时间上手,是因为它最像“现场证词”。
你一搜就能看到:
- 哪个接口报了 warning
- 哪个 traceId 耗时很长
- 哪个参数看起来不太对
- 哪个异常堆栈最显眼
问题在于,日志太擅长讲单个请求发生了什么,却不擅长告诉你这个请求在整体里算不算主流样本。
那次 order/confirm 变慢,最早被翻出来的几条日志全都指向优惠服务,于是大家默认把根因压在下游优惠链上。可后来指标一摊开才发现:
- 只有 3 台实例变慢。
- 变慢实例的工作线程活跃数和队列长度先抬头。
- 同一时间优惠服务整体 RT 并没有全局抬高。
这说明“日志里看见下游慢”这件事本身没错,但它更像结果,不像第一现场。
所以后来我们先看的是指标,不是因为它最详细,而是它先回答了方向
当时最有价值的第一轮指标,不复杂,甚至可以说很普通:
- 单接口还是多接口
- 单实例还是全实例
- P50、P95、P99 谁先坏
- 线程池、连接池、下游 RT 哪一条曲线先抬头
这几张图一摆出来,现场立刻多了三个结论。
第一个结论:这是局部实例问题,不是全站退化
因为 12 台里只有 3 台抬头,优先级就该落到实例差异、局部流量、局部状态漂移,而不是一上来怀疑数据库或某个共享下游全局异常。
第二个结论:先坏的是等待,不是执行
那 3 台实例 CPU 没有明显打满,GC 也没有异常跳升,反而是工作线程 queue 和获取连接耗时先变长。
这一步很关键。它把“是不是 JVM 自己算慢了”先排在了后面,也把“是不是某个等待点把请求挂住了”放到了更前面。
第三个结论:问题开始得很突然,而且和某个局部条件相关
曲线不是慢慢爬升,而是在几分钟内出现分叉。这种形状通常不太像系统整体流量自然上来,更像某个实例上的状态、开关、缓存、连接或分组流量发生了变化。
光这三条结论,就已经比翻十几分钟日志更接近真正的排查顺序了。
指标把范围切出来以后,Trace 才开始有价值
等我们知道“是 3 台实例先坏,而且更像等待链问题”之后,再看 Trace,问题就不一样了。
这时候 Trace 不再是随便点一条最慢请求看看,而是只盯两个问题:
- 时间到底耗在应用内部,还是耗在某个下游阶段。
- 慢请求是不是都长成同一种形状。
后来挑出来的慢 Trace 很有意思。
它们并不是统一卡在 promotion-service 的真正处理时间上,而是先在应用内部排队,然后才把等待传到下游调用阶段。也就是说,Trace 里最慢的一段虽然显示在下游 span 上,但真正先分叉的是应用实例内部的可用工作线程和连接获取速度。
如果没有前面的指标兜底,很容易把这类 Trace 读反:
- 看到下游 span 长,就以为下游先坏。
- 看到某段调用长,就以为那段就是第一现场。
实际上,Trace 更适合回答的是:
这批慢请求的时间到底是怎么被切掉的?
它很会拆账,但不负责先告诉你该先审哪本账。
最后才轮到日志,因为那时我们已经知道该去补什么
等指标和 Trace 都把方向收得差不多了,日志就不再是“海里捞针”,而是去补两类非常具体的东西。
一类是触发条件
例如后来在日志里补到:
- 那 3 台实例刚好在 19:38 接到一批新的租户分组流量。
- 其中一个新租户会命中较重的优惠组合校验。
- 这批请求的参数结构和正常流量并不一样。
这些东西如果没有前面的范围判断,你可能也能搜到,但很难知道它到底是不是关键。
另一类是状态差异
最后定位出来的问题,和一组实例上的本地缓存预热不完整有关。日志里能看见预热任务耗时、缓存 miss 后的回查路径,以及少量 fallback 分支被频繁触发。
这些信息很重要,但只有在前面已经确认“局部实例先坏、等待链先抬头”之后,它们才真正变成证据,而不是新的噪音。
这就是为什么我现在更不建议“日志、Trace、指标一起看”
一起看听起来全面,实际上最容易失去顺序。
因为这三类证据回答的根本不是一个问题。
指标先回答:问题像什么
它帮你看:
- 影响面有多大
- 从什么时候开始
- 哪一层先抬头
- 更像执行慢还是等待慢
Trace 再回答:时间花在哪
它帮你拆:
- 是应用内部耗时,还是下游阶段耗时
- 是单段长,还是多段叠加长
- 慢请求之间有没有共同形状
日志最后回答:当时具体发生了什么
它适合补:
- 参数
- 开关
- 分支
- 异常
- 某个实例上的特殊状态
顺序一旦反过来,就很容易发生这样的事:
- 日志给了细节,但你不知道它是否代表主流样本。
- Trace 给了局部耗时,但你不知道它是不是整体趋势。
- 指标明明能先帮你收范围,却被放到了最后才看。
当然,也不是每次都必须死守这个顺序
如果你们已经有非常成熟的结构化慢日志,里面天然带着接口、实例、租户、阶段耗时、错误码,那日志有时可以更早介入。
如果 Trace 采样很差,关键慢请求根本采不上来,那它的优先级也会下降。
如果指标维度太粗,连单实例差异都看不出来,那你也只能先借助别的证据顶上。
但即便有这些例外,一个判断仍然经常成立:
第一轮最该先拿到的,不是最详细的证据,而是最能帮你决定下一步往哪边收的证据。
慢接口现场里,这个角色大多数时候还是指标。
这篇的边界也很明确
如果你现在已经不是“证据顺序怎么排”的问题,而是 timeout 现场里要先区分应用、网络还是下游依赖,那更该直接看接口超时增多时,先区分应用、网络还是下游依赖?。
如果你卡的是“多个告警同时响,第一轮怎么切范围”,那更应该先看值班时看到多个告警同时响,第一轮该怎样做范围切分?。
这篇只处理一个坎:明明工具都在,但现场不知道先信谁、先看谁。
我后来更在意的一句话,不是“哪个工具最强”,而是“谁先帮我把问题看成一种形状”
那次事故最后真正让人记住的,不是日志、Trace 或指标哪个更高级,而是顺序一换,现场节奏就完全不一样。
先翻日志时,大家拿到的是很多故事。
先看指标时,大家先看见了问题的轮廓。
轮廓出来以后,Trace 才知道往哪一段拆,日志也才知道去补哪一个条件。
慢接口排查真正怕的不是工具少,而是每种证据都看见一点,却始终没把它们接成同一条线。