再看线上排查：症状不是根因

一、引子：三个指标同时报警#

「CPU 打满了怎么排查」是一道标准面试题，标准答案是一串命令：

top                          # 找到占 CPU 的进程
top -Hp <pid>                # 找到占 CPU 的线程
printf '%x\n' <tid>          # 线程 ID 转十六进制
jstack <pid> | grep -A 30 <hex-tid>   # 找到线程栈

我背过，也用过，确实能定位到某个具体的方法。

直到有一次线上出问题，监控面板上三个指标同时变红：

• CPU 使用率 95%；
• Full GC 每分钟 12 次；
• 数据库慢查询数量涨了 40 倍。

我按流程走了一遍，jstack 抓到大量线程卡在数据库驱动的 socket read 上。看起来是数据库慢导致的。但 DBA 那边说数据库负载正常，慢查询是从应用侧变慢开始才出现的。

于是问题变成：

CPU 高、GC 频繁、DB 慢，这三个是同时发生的。

哪个是原因，哪个是结果？

我答不上来。而那串命令完全帮不上忙——它能告诉我「线程正在做什么」，但回答不了「为什么会变成这样」。

后来定位到根因是一个接口返回的数据量突然暴涨（上游改了查询条件，单次返回从几百行变成几十万行）。因果链是这样的：

返回数据量暴涨
    → 大对象频繁分配 → 老年代快速填满 → Full GC 频繁     （GC 指标红）
    → Full GC 占用 CPU + 序列化大对象占用 CPU              （CPU 指标红）
    → 应用线程被 GC 反复暂停 → 数据库连接持有时间变长
    → 连接池耗尽 → 后续查询排队                            （DB 指标红）

三个红灯，一个根因，而且根因不在任何一个红灯上。

这件事让我意识到那套「症状 → 命令」的映射有个根本问题：它假设症状和根因是一一对应的。 而真实故障里，症状是一片相互关联的现象，根因往往藏在没有报警的地方。

这篇文章拆三个说法：

二、三支柱的顺序：从范围到细节#

2.1 三支柱是按数据形态分的，不是按用途#

可观测性的标准框架是「三支柱」：Metrics（指标）、Traces（链路）、Logs（日志）。

这个划分是按数据形态做的：

问题在于，这个划分本身不告诉你该按什么顺序用它们。而顺序恰恰是排查效率的关键。

大多数人的习惯是先看日志——因为日志最熟悉，也最容易拿到。但日志是粒度最细的数据。在一个每秒几万条日志的系统里，从日志开始查问题，等于在没有坐标的情况下大海捞针。

正确的顺序应该由范围收缩驱动：

Metrics ──► 确定「哪个服务、什么时间、什么指标」异常     范围：全系统 → 单服务
   ↓
Traces  ──► 找到一条慢的/失败的完整调用链，看卡在哪一环   范围：单服务 → 单环节
   ↓
Logs    ──► 用 trace ID 精确捞出那一环的详细日志          范围：单环节 → 具体细节

每一步都把搜索范围缩小一到两个数量级。跳过前两步直接看日志，就是放弃了这个收缩过程。

2.2 Metrics 该看什么：USE 和 RED#

指标面板通常有几十上百个图。哪些先看？

有两套成熟的方法论，各自适用于不同对象。

两套方法论合起来用：RED 告诉你「服务有问题」，USE 告诉你「哪个资源是瓶颈」。

回到引子那个案例，如果我当时按 USE 检查，会发现「连接池等待线程数」这个饱和度指标早就不为零了——它比 CPU 使用率更早开始异常，因为它是更靠近根因的一环。

2.3 为什么 Traces 是最被低估的一支#

三支柱里，链路追踪是投入产出比最高、但也最容易被跳过的。

原因是它需要提前埋点，而埋点在没出事的时候看不出价值。等到出事了才发现没有 trace，只能靠日志硬拼。

一条完整的 trace 能直接回答「时间花在哪」：

GET /api/order/detail                                    总耗时 2340ms
├── AuthService.verify                                          12ms
├── OrderService.getDetail                                    2280ms
│   ├── SELECT * FROM orders WHERE id = ?                        8ms
│   ├── ItemService.batchGet          ← 这里                  2250ms
│   │   ├── SELECT ... WHERE id = ?                              6ms
│   │   ├── SELECT ... WHERE id = ?                              7ms
│   │   └── ...（重复 300 次）
│   └── SELECT * FROM logistics WHERE order_id = ?              14ms
└── 序列化响应                                                   48ms

这张图一眼就能看出问题：ItemService.batchGet 名字叫 batch，实际上在循环里单条查询了 300 次。经典的 N+1 问题。

如果只有日志，要发现这一点需要在几万条日志里注意到「同一个 trace 下有 300 条相似的 SQL 日志」——理论上可行，实际上没人会注意到。

2.4 日志：结构化和 trace ID#

到日志这一层时，需要的是精确定位，不是搜索。前提是两件事：

第一，结构化。 文本日志没法做条件查询：

// 不好：纯文本
2026-08-16 10:23:45 用户 12345 下单失败，商品 67890 库存不足

// 好：结构化
{"ts":"2026-08-16T10:23:45Z","level":"WARN","event":"order_failed",
 "user_id":12345,"item_id":67890,"reason":"insufficient_stock",
 "trace_id":"a1b2c3d4"}

结构化之后能做的事完全不同：按 reason 分组统计失败原因分布、按 item_id 找出哪个商品出问题最多、按 trace_id 关联到完整调用链。

第二，trace ID 贯穿全链路。 这是把三支柱粘起来的东西。有了它，从一条慢 trace 跳到对应的详细日志是一次精确查询，而不是「在这个时间段附近找找看」。

在 Java 里通常用 MDC（Mapped Diagnostic Context）实现，注意异步场景下 MDC 不会自动传递——线程池里的任务拿不到提交方的 MDC，需要手动包装：

// 提交任务时捕获当前 MDC
Map<String, String> context = MDC.getCopyOfContextMap();
executor.submit(() -> {
    MDC.setContextMap(context);      // 在新线程里恢复
    try {
        doWork();
    } finally {
        MDC.clear();                 // 必须清理，线程会被复用
    }
});

finally 里的清理不能省。线程池的线程是复用的，不清理会导致下一个任务带上前一个任务的 trace ID——这种日志比没有日志更有害，因为它会把排查引向完全错误的方向。

三、症状到工具的映射，以及工具的盲区#

3.1 「CPU 高」不是一个原因#

引子里那串命令的问题在于，它把「CPU 高」当成了一个可以直接查的原因。但 CPU 高至少有五种完全不同的成因，证据和处理方式都不一样：

区分这几种的第一步不是 jstack，而是先分清 CPU 花在哪一类：

vmstat 1 5
# us  sy  id  wa
# 90   3   7   0    → user 主导：业务计算或 GC
# 30  60  10   0    → sys 主导：系统调用、上下文切换、I/O

jstat -gcutil <pid> 1000 10
# 看 YGCT / FGCT / GCT 的增长速度
# 如果 10 秒内 GCT 涨了 8 秒，说明 80% 的时间在 GC

先分类，再取证。 跳过分类直接 jstack，很容易看到一堆卡在 I/O 上的线程，然后误判成下游慢——就像引子里我犯的错。

3.2 jstack 的盲区：safepoint bias#

jstack 是最常用的工具，但它有一个很少被提及的系统性偏差。

要抓取所有线程的栈，JVM 需要让线程停在安全点（safepoint）——一个 JVM 能准确知道所有对象引用位置的执行点。jstack 触发的实际上是一次全局停顿：所有线程跑到最近的安全点，停下，采样，恢复。

问题是：安全点不是均匀分布的。

JVM 会在方法返回、循环回边等位置插入安全点检查。但 JIT 编译器有一个优化：对于计数明确的 int 型循环（counted loop），会省略掉循环内的安全点检查，因为编译器认为它会很快结束。

// 这种循环内部可能没有安全点
for (int i = 0; i < array.length; i++) {
    sum += compute(array[i]);       // 如果 compute 被内联，整个循环可能无安全点
}

于是这段代码即使占用了 90% 的 CPU，jstack 也采不到它——因为线程在到达安全点之前不会停下来，等它停下来时已经跑出这段代码了。采样结果会偏向那些「安全点密集」的代码，而不是真正耗时的代码。

这就是 safepoint bias。它的后果是：jstack 采样出来的热点，可能和真实热点不一致。

3.3 jmap 的陷阱：它可能让故障更严重#

内存问题的标准做法是 jmap 导出堆快照。但有几个变体的行为差别很大，而这个差别在生产环境是致命的：

带 :live 的版本会先做一次 Full GC，因为它要「只统计存活对象」——而判断存活就需要一次完整的可达性分析。

在一个已经因为频繁 Full GC 而濒临崩溃的系统上，手动再触发一次 Full GC，可能就是压垮它的最后一根稻草。

即使不带 :live，导出一个 8 GB 的堆也需要几十秒的 STW，期间服务完全无响应——健康检查会失败，负载均衡会把这台机器摘掉，如果是集群里的最后一台，就是全站故障。

3.4 更轻量的选择#

生产环境的排查工具，选择标准是开销和是否需要重启。按这两个维度排一下：

# 运行时开启，记录 60 秒
jcmd <pid> JFR.start duration=60s filename=rec.jfr settings=profile

# 或者启动参数里常态开启，滚动保留
-XX:StartFlightRecording=disk=true,maxsize=1g,maxage=24h

# 最忙的 3 个线程及其栈
thread -n 3

# 找出 BLOCKED 线程和持锁者
thread -b

# 追踪方法内部各步骤耗时（找出慢在哪一行调用）
trace com.example.OrderService getDetail '#cost > 200'

# 观察方法的入参、返回值、异常
watch com.example.ItemService batchGet '{params, returnObj}' -x 2

# 反编译运行中的类（确认线上代码是不是你以为的版本）
jad com.example.OrderService

# 网络连接状态统计：CLOSE_WAIT 堆积说明没关连接
ss -s
ss -ant | awk '{print $1}' | sort | uniq -c

# 磁盘 I/O：util 接近 100% 说明磁盘饱和
iostat -x 1

# 上下文切换：cs 列异常高说明线程太多或锁竞争激烈
vmstat 1

# 系统调用追踪（开销大，谨慎使用）
strace -c -p <pid>

3.5 相关不等于因果#

回到引子的核心问题：三个指标同时变红，怎么判断因果？

有几个可操作的判据：

判据一：看时间的先后顺序。

把几个指标画在同一张时间轴上，放大到秒级。最先开始异常的那个，更可能靠近根因。

引子那个案例里，如果我把「响应数据大小」这个指标也画上去（它当时没有报警，因为没设阈值），会看到它比 CPU 早了大约 40 秒开始上涨。

这也说明：报警阈值只覆盖你想到的指标，而根因常常在没设阈值的指标上。 所以排查时要看的面板，应该比报警的面板宽得多。

判据二：看依赖方向。

A 依赖 B，那么 B 出问题会导致 A 出问题，反过来通常不成立。所以在依赖链上，越靠下游的异常越可能是根因。

但要小心一个例外：上游的行为变化会伪装成下游故障。引子里就是这样——应用请求数据量暴涨，表现出来是数据库慢。数据库是下游，但根因在上游。

判断方法是看下游自身的资源指标：数据库的 CPU、I/O、慢查询日志。如果下游资源完全正常但响应慢，那多半是上游的请求变了（量变大、条件变复杂、并发变高）。

判据三：做一次干预。

如果观察不出因果，就制造一个变化：把某个服务的流量摘掉一半、把某个功能降级、回滚最近的一次发布。看哪个动作让指标恢复。

这是最可靠但成本最高的方法，通常留到最后用。

四、不可复现才是常态#

4.1 「复现问题」这个前提在生产环境不成立#

开发环境的调试流程是：复现 → 打断点 → 单步 → 找到 bug。这套流程有一个隐含前提：问题可以被稳定触发。

生产故障大多不满足这个前提：

• 依赖特定数据：某个用户的某条脏数据，触发了一个从没走过的分支；
• 依赖并发时序：两个线程以特定顺序交错才出现，概率千分之一；
• 依赖累积状态：连续运行 72 小时后内存碎片化到某个程度才发作；
• 依赖真实流量：QPS 到 5000 才出现，压测环境到不了这个量；
• 依赖环境差异：生产的内核版本、JDK 小版本、网络拓扑和测试环境不同。

对这些问题，「先复现」不是一个可行的起点。排查的重心必须从「复现」转移到「取证」。

两者的区别是：复现是让问题再次发生以便观察；取证是在问题发生的那一刻，尽可能多地保留现场，事后分析。

4.2 三类取证手段#

# OOM 时自动 dump
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dumps/

# GC 日志常态开启（JDK 9+），带滚动
-Xlog:gc*:file=/data/logs/gc.log:time,uptime:filecount=10,filesize=100M

-XX:StartFlightRecording=disk=true,maxsize=1g,maxage=24h,\
settings=profile,filename=/data/jfr/app.jfr

4.3 保留现场 vs 快速恢复#

这是故障处理中最真实的冲突。

服务挂了，重启能立刻恢复。但重启会清空所有现场——堆里的对象、线程状态、连接池状态，全没了。下次再出，还是不知道原因。

我见过团队反复重启同一个服务半年，每次都能「解决」，但从来没找到根因。

平衡点通常是这样的：

「重启前抓一份最小现场」是关键技巧。完整堆转储太慢，但下面这些只要几秒：

# 一次性抓取，总共几秒钟
jstack <pid> > /tmp/jstack.$(date +%s).log
jstat -gcutil <pid> > /tmp/jstat.log
jcmd <pid> GC.heap_info > /tmp/heap_info.log
jmap -histo <pid> | head -50 > /tmp/histo.log      # 注意不加 :live
ss -ant | awk '{print $1}' | sort | uniq -c > /tmp/conn.log
top -Hp <pid> -b -n 1 > /tmp/threads.log

这些加起来不到 10 秒，但能覆盖大部分场景的初步定位。写成一个脚本放在机器上，故障时直接跑，比临时回忆命令快得多。

4.4 那些从一开始就该配好的东西#

排查能力的上限，在故障发生之前就被决定了。故障当下能做的，只是使用已经存在的数据。

一份最小清单：

最后一项值得强调。报警是给「已知的坏情况」设的，而根因常常在没有报警的指标上。 所以看板上要有大量不报警但会被查看的指标——比如引子里那个「响应数据大小」。

五、方法论：怎么排查一个没见过的问题#

5.1 二分，而不是猜#

面对一条长链路，最有效的策略是二分：在中间某个点插入观测，判断问题在前半段还是后半段。

用户 → CDN → 网关 → 应用A → 应用B → 数据库
                      ↑
              先在这里测：到 A 之前正常吗？

具体做法：

• 在中间节点看它记录的耗时。如果 A 记录的「自身处理耗时」正常但「总耗时」高，说明慢在 A 之后；
• 直接绕过前半段：从应用 A 所在的机器上直接 curl 应用 B，看是否慢。如果不慢，问题在 A 到 B 之间的网络或调用层，而不是 B 本身。

每次二分把范围减半。10 个环节的链路，3～4 次就能定位。

比二分更糟的是「从头顺着查」，那是线性的；比线性更糟的是「凭印象猜」——猜中了是运气，猜不中就浪费了一轮时间，而且会形成心理锚定，后面看到的证据都会被往那个方向解读。

5.2 先看变更，再看代码#

上一节说过，但值得作为独立的一条。超过一半的故障能由最近的变更解释。

排查开始的前五分钟应该用来问：

1. 最近一次发布是什么时候，改了什么？
2. 配置中心最近有推送吗？（这个最容易被忘记，因为它不走发版流程）
3. 依赖的服务最近发布了吗？
4. 有没有定时任务、大促、批量作业正好在这个时间点？
5. 基础设施有变更吗？扩缩容、网络策略、证书？

第 2 条我踩过坑。一个动态配置把线程池核心数从 200 改成 20，推送后十分钟服务开始超时。因为不走发版流程，所有人都在查代码，而代码半个月没动过。

把「变更时间线」和「指标时间线」叠在一起看，是效率最高的一个动作。很多故障在这一步就结束了。

5.3 记录你的推理，而不只是结论#

排查过程中会形成很多假设。人的记忆很不可靠，尤其在压力下——半小时后你会忘记自己排除过哪些可能，然后重复验证。

我的做法是边查边记，格式很简单：

10:23  现象：订单接口 P99 从 80ms 涨到 3s，错误率 0
10:25  假设1：数据库慢 → 查 DBA 面板，DB 侧 CPU/IO 正常 → 排除
10:28  假设2：GC 问题 → jstat 显示 FGC 12次/分钟 → 可能，继续
10:31  假设3：为什么 FGC 变多？→ 看堆内对象分布 → byte[] 占 70%
10:35  发现：上游接口返回体大小从 20KB 涨到 8MB（此指标无报警）
10:37  验证：回滚上游发布 → 指标恢复 → 确认

这份记录有三个作用：

1. 避免重复验证已排除的假设；
2. 交接时能让别人快速接上，不用从头讲一遍；
3. 复盘时是最好的材料——能看出哪一步走了弯路，下次改进。

第 3 点最有价值。回头看这份记录，我会发现「假设 1 花了 3 分钟才排除，因为要找 DBA 要面板权限」——那么下次的改进项就是提前把 DB 面板加到自己的看板里。

5.4 区分「止血」和「根治」#

故障处理有两个目标，它们经常冲突：

• 止血：让服务尽快恢复。手段是重启、回滚、扩容、降级、切流量；
• 根治：找到并修复根因。需要时间，需要现场。

这两件事应该由不同的人同时做。 一个人负责恢复服务，另一个人负责保留现场和分析。如果只有一个人，那顺序是：先抓最小现场（10 秒），再止血，然后慢慢分析。

最糟的模式是一边重启一边分析——重启把现场清了，分析永远得不出结论，然后下周同样的故障再来一次。

5.5 最后#

回到引子那个案例。我当时的错误不在于不会用 jstack，而在于我以为排查是一个查找过程——找到那个出问题的地方。

实际上排查是一个推理过程：从一组相互关联的现象出发，构造一条能解释所有现象的因果链，然后验证它。

「CPU 高 → jstack → 找到线程」这种映射之所以不够用，是因为它跳过了推理，直接从症状跳到了工具。而症状和根因之间隔着一整条因果链。

三句话总结这次拆解：

• 三支柱要按范围收缩的顺序用：Metrics 定范围，Traces 定环节，Logs 定细节。直接从日志开始是在放弃已有的收缩手段；
• 工具都有盲区：jstack 有 safepoint bias，jmap -histo:live 会触发 Full GC。知道盲区在哪，比多记几个命令重要；
• 排查能力在故障之前就决定了：GC 日志、JFR、trace ID、结构化日志，这些没提前配好，故障当下再想要就来不及了。

最后一句可能是最重要的：排查不是一项临场技能，而是一项准备工作。

参考#

• Gregg, Brendan. Systems Performance: Enterprise and the Cloud, 2nd ed. Addison-Wesley, 2020.（USE 方法与系统性能分析的经典）
• Gregg, Brendan. The Flame Graph. Communications of the ACM, 2016.
• Wilkie, Tom. The RED Method: How to Instrument Your Services. Grafana Labs, 2018.
• Majors, Charity; Fong-Jones, Liz; Miranda, George. Observability Engineering. O’Reilly, 2022.
• Nitsan Wakart, Why (Most) Sampling Java Profilers Are Fucking Terrible. 2013.（safepoint bias 的经典论述）
• async-profiler 项目文档, AsyncGetCallTrace 与各 event 模式.
• Arthas 官方文档, trace / watch / jad 命令.
• OpenJDK, JDK Flight Recorder 与 Unified Logging (JEP 158).

本站相关：

• 再看 MySQL：被术语盖住的三个地方
• 再看秒杀：一条 SQL 到全链路之间隔着什么
• 再看 Spring Boot：自动配置不是魔法，是时序
• Java并发