CPU 才 12% 服务却全超时？Safepoint 把整个 JVM 冻住了

场景：订单服务午高峰接口全线超时 100%，可 CPU 只有 12.3%、堆用了 40%、一个 FullGC 都没有。服务"死了"但所有指标都不支持这个结论。 路径：top → jstat → jstack 全 RUNNABLE 困惑 → 排除锁自旋 → Safepoint 日志 → 一个线程卡在 native → 修复

上篇我们排查了线程堆栈吃光 16GB 容器的怪事（一个 NMT 查不到的坑），这篇来看一个更反直觉的问题——所有常规指标都健康，服务却在午高峰装死了快一个小时。

14:22，飞书告警：订单服务接口超时率 100%，持续 10 分钟。

第一反应——看 CPU、看堆、看 GC。这是所有 Java 服务"假死"的第一排查入口，GC 停顿是最常见的根因。

但这次三板斧全给了正常答案：CPU 12.3%，堆 40%，FullGC 0 次。所有常规指标都健康，服务却一个请求都不回。

排查到这里，常规路线走不通了。

插一句判断：年排查量上百的团队会知道，这种"全指标正常但服务装死"的 case，最后十有八九不是 CPU、不是内存、不是 GC 自身，而是藏在某一列看起来完全正常的状态里。这一列外人看不出毛病，懂机制的人才看得见它的异常。这次的主角，就是这个。

告警

截图类型: metric — 超时率 100% + CPU 12.3% 双曲线对比

一个反直觉的告警组合

告警弹窗：超时率与 CPU 双曲线

14:22 告警弹窗：

【P0 告警】 订单服务 order-service-0 接口超时率 100%，持续 10 分钟。 当前超时率：100% | P99 RT：13.8s | 错误率：0%（无 5xx，全是超时） 建议操作：检查 CPU / 内存 / GC 停顿。

注意一个反常组合：超时率 100%，但 CPU 只有 12.3%。

如果是 GC 停顿、CPU 飙高、甚至 JIT 编译风暴，CPU 曲线早就该拉满了。可这张图里 CPU 几乎是一根平线，堆内存也平静得不像有 FullGC。

回看监控曲线，其实 13:50 起就有零星长尾超时——那时超时率只有 3-5%，告警阈值压住没报。到 14:12 爬到 22%，14:20 冲到 91%，14:22 才到 100% 触发 P0。也就是说服务实际已经装死了半个多小时，告警是最后才追上的。这也是这个 case 的第二个隐患：单指标告警会迟到。

为什么"进程活着但一个请求都不回"意味着某个全局性阻塞？因为只有全局性阻塞才可能概率性地卡住所有并发请求——而全局性的东西，在 JVM 里只有那么几个候选。

第一步排除了"CPU 扛不住"和"堆不够用"——这两个最常见的服务假死原因今天都排除了。

群里的第一反应

告警群讨论

告警截图甩到群里，评论清一色是：

是不是 FullGC 卡了？查 jstat。 CPU 这么低不可能是 GC，是不是数据库连接池满了？ 看看锁，八成是死锁。

这些猜测不能说错——它们覆盖了 90% 的"服务无响应"案例。但这次全都对不上：FullGC 0 次、连接池正常、没有死锁。

根本问题是：所有常规指标健康时，我们缺一张"JVM 到底在干什么"的快照。 这就是接下来的方向。

起手

截图类型: server — top + vmstat 进程状态 / jstat GC 状态

top：CPU 低、load 低，进程还在

top 输出：进程 CPU 12.3%

$ top -Hp 27421 -b -n 1
top - 14:25:01 up 197 days,  load average: 1.42, 1.38, 1.35
%Cpu(s):  2.3 us,  0.8 sy,  0.0 ni, 96.8 id,  0.0 wa
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  27421 root      20   0 13.6g   3.1g  1.1g S  12.3   2.3  45:35.21 java

进程活着、CPU 12.3%、load 1.42，系统层面没有异常。排除了操作系统层面卡死（比如磁盘 IO 打满、内存 swap 严重）。

但有个细节：进程只是"S"（sleeping）挂在那里，连一个高 CPU 的线程都没有。一个正在处理 100% 超时的服务，线程池里的线程应该在拼命干活才对——没有一个线程在干活，这才是最可疑的信号。

先看 top 是因为它 3 秒就能定位"问题在系统还是应用"。这一步排除了系统层。

jstat：GC 完全正常，最大嫌疑洗清

jstat GC 状态

$ jstat -gcutil 27421 1000 5
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
  0.00   0.00  31.25  40.18  88.45  82.11    214    3.128    0    0.000    0    0.000    3.128

老年代 40.18%，FullGC 0 次，Young GC 214 次总共才花了 3.1 秒。GC 是完全健康的。

"服务无响应"最常见原因是 GC 停顿，这个最大嫌疑洗清之后，剩下的可能收窄到：锁竞争、JIT 编译问题、Safepoint。而锁和 JIT 是另一个量级的问题，先看最有把握的——线程在干什么。

工具链全景：假死问题的三板斧顺序

到这里停一下，把本类问题（进程活着但无响应）的排查顺序理一遍，后面所有案例都用这套路径：

层级 工具 回答了什么问题 回答不了的边界
L1 top CPU/load/IO 是不是系统层 看不到 JVM 内部发生了什么
L2 jstat GC 停没停、堆够不够 看不到线程状态、看不到 GC 之外的停顿
L3 jstack 线程在哪里、什么状态 下的结论可能误导人（见下文收敛）
L4 Safepoint 日志 JVM 全局停了多少次、谁迟到 只告诉"谁迟到"，不给业务上下文

top+jstat 之后，绝大多数人会直接上 jstack——但它恰恰是本类问题里最会骗人的工具。

收敛

截图类型: code — jstack 线程状态快照 / diff — 两次快照对比 / diagram — Safepoint 机制原理图

jstack：线程全是 RUNNABLE，但一个都不在干活

$ jstack 27421 | grep -E "^\"|java.lang.Thread.State" | head -40
"http-nio-8080-exec-101" #452 java.lang.Thread.State: RUNNABLE
"http-nio-8080-exec-102" #453 java.lang.Thread.State: RUNNABLE
"http-nio-8080-exec-103" #454 java.lang.Thread.State: RUNNABLE
"pool-8-thread-1" #267 java.lang.Thread.State: RUNNABLE
...

jstack 线程状态快照

200 多个 Worker 线程全部 RUNNABLE。 直觉上"RUNNABLE = 线程在干活"，但这恰恰是本案例的第一个反转点——这些线程在做的事，是停在同一个等待点上。

这里有个必须澄清的机理，否则推导会跑偏：Safepoint 挂起线程时，不会把线程状态改写成 BLOCKED/WAITING，jstack 快照里被挂起的线程依然显示 RUNNABLE（它在安全点上被 suspend，状态来不及更新）。所以"全 RUNNABLE"有两种解读：

  • 解读 A：所有线程都在并行推进业务 → CPU 应该起飞，但 CPU 才 12%，矛盾
  • 解读 B：所有线程都停在同一处，状态没来得及变 → 与 CPU 12% 吻合

CPU 12% 已经否决了解读 A。我们站在解读 B 的门口。

最容易犯的错：看到全 RUNNABLE 就以为"线程都在抢锁 / 自旋忙等"，直接跑去查锁。

排除锁自旋：一个必须做的旁证

jstack 两次快照逐行对比

如果 200 个线程真的在自旋抢锁，那连续打两次 jstack，它们应该极大概率出现在不同位置（自旋是动态的）。但这次两张快照几乎一模一样——每个线程停在同一栈帧。

$ jstack 27421 > /tmp/jstack1.log && sleep 3 && jstack 27421 > /tmp/jstack2.log
$ diff <(sed -E 's/(tid|nid)=0x[0-9a-f]+/\1=X/g; s/elapsed=[0-9.]+ms/elapsed=X/g; s/\[0x[0-9a-f]+\]/[X]/g' /tmp/jstack1.log) \
        <(sed -E 's/(tid|nid)=0x[0-9a-f]+/\1=X/g; s/elapsed=[0-9.]+ms/elapsed=X/g; s/\[0x[0-9a-f]+\]/[X]/g' /tmp/jstack2.log) | wc -l
3

把线程头里的 tid/nid/elapsed/地址这类运行期会变的字段全部归一化后，两次快照只剩 3 行差异——所有线程的栈帧都是一样的。不是锁自旋——自旋的帧会不停跳动。这是"所有线程被同一股外力钉住"的铁证。

Safepoint：所有线程必须停在同一行

Safepoint 机制原理图

既然线程都被钉在同一处，下一个问题就是：谁能同时钉住 200 个线程，还不让 CPU 起飞？

答案是 Safepoint（安全点）——JVM 里一种全局同步机制：当 VM 需要做某些操作（GC 前的根扫描、类重定义、偏向锁撤销等）时，它要求所有 Java 业务线程停在一个预先定义好的安全点上，全部到齐之后才执行关键操作，做完再统一放行。这段时间就是常说的 STW（Stop-The-World，世界停顿）。

关键点在这：Safepoint 不是只停"干活慢的那个"——只要有一个线程迟迟不到安全点，其他所有线程就得无限期等它。整个 JVM 的时钟卡在一个迟到线程上。

这是一种 2008 年就有、但极少在教科书里讲透的设计权衡：用"全员等待"换"全局一致"——因为 VM 操作（比如重定义类）不能在只停了一部分线程的状态下进行，要么全停，要么全不停。代价是：一个不可控线程就能抵押整个 JVM 的可用性。

现在问题变成：200 个线程都到了安全点，是谁迟到了？工具链里 L4 的 Safepoint 日志，就是为这个准备的。

定位

截图类型: metric — Safepoint 统计面板 / trace — Safepoint 延迟线程日志

-Xlog:safepoint：时间都去哪了

Safepoint 统计面板

给 JVM 加上 Safepoint 统计开关，看全局停了多少次、每次停多久。老 JDK 8 用 PrintSafepointStatistics，JDK 9+ 统一走 -Xlog:safepoint（本文环境是 JDK 11，用后者）：

# JDK 11：重启时带上 xlog 开关（Safepoint 统计和明细都走这里）
$ export JAVA_OPTS="-Xlog:gc,safepoint=info,debug -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=2000"

SafepointTimeout：Safepoint 等待超时自动打印原因的开关；SafepointTimeoutDelay：超过多少毫秒算"超时"（这里设 2 秒）。它们必须写在启动参数里，重启才生效——这也是这个 case 里我们选择让服务快速滚动重启的一个原因。

重启并复现后，safepoint 日志给了两张表。先看统计——sync（等待全部线程到齐的时间）这一列：

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
2890.213: G1CollectFull                   [     220      0             1         ]    [ 0    0   28891   0     0    ]   4
2891.402: G1CollectFull                   [     220      1             0         ]    [ 0    0  30441   0     0    ]   4

2891 次全局停顿里，大部分 sync 时间在 1ms 以内，但有那么几次，sync 高达 28.9 秒、30.4 秒。这几次异常值交给了我们关键线索——停顿不是均匀的，是个别事件把 sync 拉爆了。

但统计只告诉"sync 很长"，它回答不了"是谁让 sync 这么长"。这个边界必须清楚：统计只给了总账，明细要看同一条日志里 SafepointTimeout 打印的迟到线程。

SafepointTimeout：让 JVM 自己招出那个线程

Safepoint 延迟线程日志（trace 视图）

SafepointTimeout 生效后，每当等待超过 2 秒，日志里就会多一行点名是谁让大家等的明细：

[14:39:21.023][info][safepoint] Safepoint "G1CollectFull", 
   200 threads waited for 18002 ms
   thread "ForkJoinPool-3-worker-7" (tid=8411) reached safepoint 18002 ms late

ForkJoinPool-3-worker-7，迟到 18 秒。 这 18 秒里，其他 200 个线程（包括所有处理订单的 http-nio worker）全部停在安全点上干等。

到这里，两个证据链闭合了： - Safepoint 统计：sync 多处异常（28.9s / 30.4s） - SafepointTimeout：点名了 ForkJoinPool-3-worker-7 迟到 18 秒

（数字如何自洽：18s 是这次点名时的迟到时长；28.9s / 30.4s 是同一根链条上更狠的两次，都是同一原因——都是那个 native 线程在不同时刻制造的停顿。看到"每次都差在同一个线程"就彻底踏实了。）

但还差最后一问：这个 worker 为什么迟到？ Safepoint 等待线程到达是有限度的，线程一般是主动进入安全点，而不会一直被外力按住。能硬生生抗拒 safepoint 的，只有一种情况——它此刻不在 Java 字节码里，而是在 native 代码里（这里指 JNI 或其他不受 JVM 管控的原生代码），native 执行不经过安全点检查，除非它自己返回 Java 层，否则 JVM 拿它毫无办法。

根因：一个卡在 native 的 task

根因代码：native 图像处理调用

顺藤摸瓜找到 ForkJoinPool-3-worker-7 正在执行的代码——订单详情页要生成一张商品拼图，业务团队接了一个 OCR 图像处理 SDK，里面走 JNI 调底层 C++ 库：

// OrderDetailServiceImpl.java:182  订单详情页拼图生成
String ocrResult = ocrSdk.processImage(imageBytes); // JNI → native C++

// requestTiming 的一次调用：2ms ~ 30S 不等，取决于图片复杂度
long elapsed = System.nanoTime() - start;

这就是迟到的根源：一个走 JNI 的 OCR 调用，偶尔会卡在 C++ 层 20-30 秒不返回。

到这里因果链终于闭合，而且比想象中精彩——这不是"一次巧合撞上 GC"，而是一轮恶性循环：

  1. OCR 调用卡在 native 30 秒不回 Java 层 → ForkJoinPool-3-worker-7 拒不进安全点
  2. 卡住的这段时间，新请求照常进来，堆里的对象只增不减
  3. 堆顶压力拉满 → G1 触发 Full GC（G1CollectFull）→ 需要全员进安全点
  4. 但那个 native 线程还躺在那儿 → JVM 只能干等 18-30 秒

也就是说：GC 不是巧合撞上来，恰恰是这次停顿"制造"了触发 GC 的压力。native 线程卡得越久，堆涨得越快，GC 越频繁，每次 GC 又都得等同一个迟到线程——停顿像滚雪球一样被自己放大。这也是为什么 sync 会出现 28.9s / 30.4s 这种极端值：它们不是独立事故，是同一根链条上的不同节点。

为什么 native 会"卡"？因为 native 代码不归 JVM 调度，JVM 无法主动抢占它——不同于 Java 线程可以在安全点被挂起，native 线程只能等它自愿返回到 Java 边界。这一次它宁可吞 30 秒也不让路，整个订单服务陪葬。

业务侧也无辜：这个 OCR SDK 是供应商给的，平时 99.9% 的调用在 5ms 内返回，谁也没想到会有 30 秒的极端值。

复盘

截图类型: diff — 修复前后 P99 RT 对比 / chat — 修复复盘群聊 / timeline — 排查时间线

修复：native 长任务移出核心路径

修复前后 P99 对比

修复分两层：

  1. 治标：给 OCR 调用加超时——native 调用无法强制中断，但可以用子线程隔离 + Future.get(timeout)，超时丢弃结果走降级，绝不让一个 30 秒的 native 调用堵住 ForkJoinPool 和整个 Safepoint。
  2. 治本：把 OCR 拼图从同步请求链路抽到异步任务队列，图片处理挪到独立线程池 + 独立 JVM，从架构上把"不可控 native"和"订单主链路"彻底隔离。

修复后同流量下 P99 从 13.8s 掉到 180ms，超时率归零。更关键的是：以后即使 OCR 再出极端值，它也只影响异步拼图，撼不动订单主链路。

复盘群聊

修复复盘群聊

22:00 修复上线、P99 回到 180ms 之后，群里复盘又盘出了两条规矩。第一条是"native 依赖先评审再加入"——王哥提出来的，说这次 OCR SDK 上线时没有经过性能评审，供应商一句"平均 5ms"大家就信了，没人去要最坏延迟的数字。第二条是"JNI 调用必须带超时"，刘老师补的：native 无法强中断，唯一可靠的防线是调用侧用 Future 兜超时。

这两条当天就固化进了团队准入门条：新增 native/JNI 组件需要 SRE 评审，评审问题表第一行就是"最长延迟是多少、有没有阻塞主链路的可能"。

这类问题最怕的不是这一次，而是下次另一个团队又引入一个带 native 的组件，在同一个坑里再摔一次。

三句话预防

  • Safepoint 是所有 Java 线程的"集体红绿灯"——一辆车（一个 native 线程）抢黄灯，整条街（整个 JVM）的绿灯全灭。
  • jstack 不是用来判断线程有没有在干活的，它是用来判断每个线程站在哪一行的——全 RUNNABLE 也可能意味着全员被钉在原地。
  • 接第三方 native/JNI 组件，一定要问一句：它的最坏延迟是多少？——供应商说"平均 5ms"的时候，问"最长呢"，答案往往是事故。

排查时间线

排查时间线

13:50 首次长尾超时（被阈值压住）→ 14:22 P0 告警 → 14:25 top（排除系统层）→ 14:26 jstat（排除 GC）→ 14:31 jstack 全 RUNNABLE（第一次反转）→ 14:33 两次快照对比排除锁自旋 → 14:34 滚动重启开启 SafepointTimeout → 14:39 点名 ForkJoinPool-3-worker-7 → 14:42 定位 OCR native 调用 → 22:00 发版修复。从告警到定位根因 20 分钟，算上 13:50 起被掩盖的半小时，服务一共装死了快一个小时。

读出几个关键点：前端三板斧只花 4 分钟就排除了两大最常见根因（top 排除系统层、jstat 排除 GC），真正耗时的反转发生在 jstack——"全 RUNNABLE"这一个信号逼着我们放弃直觉路线。而滚动重启是这里绕不开的代价：SafepointTimeout 必须启动参数，想拿到"谁迟到"的铁证就得复现一次。整个工具链 top → jstat → jstack → 快照对比 → SafepointTimeout，从"猜全局卡点什么"走到了"让 JVM 亲口说出来"。

附：完整命令清单

确认进程层

top -Hp <pid> -b -n 1          # 进程活着吗？CPU/load 有无异常
vmstat 1 3                     # 系统层有没有 IO/swap 卡点

排除 GC

jstat -gcutil <pid> 1000 5     # 堆占比 + FullGC 次数 + GCT

排除锁自旋

jstack <pid> > /tmp/jstack1.log && sleep 3 && jstack <pid> > /tmp/jstack2.log
diff <(sed -E 's/(tid|nid)=0x[0-9a-f]+/\1=X/g; s/elapsed=[0-9.]+ms/elapsed=X/g; s/\[0x[0-9a-f]+\]/[X]/g' /tmp/jstack1.log) \
      <(sed -E 's/(tid|nid)=0x[0-9a-f]+/\1=X/g; s/elapsed=[0-9.]+ms/elapsed=X/g; s/\[0x[0-9a-f]+\]/[X]/g' /tmp/jstack2.log) | wc -l
# 行数若接近 0 → 帧被钉死，不是自旋

定位 Safepoint

# 重启时开启（SafepointTimeout 非 manageable，必须启动参数）
export JAVA_OPTS="-Xlog:gc,safepoint=info,debug -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=2000"
# 观察日志：sync 尖刺 + 迟到的线程名
grep -E "safepoint|reached" <jvm-logfile>

实锤 native 根因

jstack <pid> | grep -A 20 "ForkJoinPool-3-worker-7"   # 栈顶是 native 方法

下篇我们聊 GC 选型事故：Parallel Scavenge 在高并发下暂停时间失控——同样是全员停顿，这次根因是 GC 算法本身的取舍。