OutOfMemoryError · 频繁 Full GC · CPU 飙高 · 留现场 · HeapDumpOnOutOfMemoryError · GC.class_histogram · 堆转储 · MAT · GC Roots · 支配树 · retained size · Humongous · top -H · jstack · nid · JFR · ExecutionSample · ObjectAllocationSample · NMT · OOMKilled

JVM 故障排查:三种现象,其实只有两个问题要回答:内存是“谁拉着、谁在猛分配”,CPU 是“哪个线程在跑哪一行”。证据要在出事之前就埋好

OOM、频繁 Full GC、CPU 飙高看起来是三种病,查起来只有两条路。内存路线先看 Full GC 之后堆降不降:不降是有东西一直被拉着(泄漏),拿堆转储顺着引用链找到 GC Root;降了是分配太猛(大对象、一阵阵的峰),拿 GC 日志和 JFR 分配采样找到是谁在分配。CPU 路线先用 top -H 看吃 CPU 的是哪个线程:是 GC 线程就转回内存路线,是业务线程就用 jstack 或 JFR 对到那一行。交易靶场订单服务里埋了三个雷,本机实测:泄漏 16 秒后 OOM,进程还活着却一个请求都不回;大导出让 30 秒里发生 401 次 Full GC;一张一分钱的优惠券让一个核一直 100%。三个雷都在 5 分钟内定位到了具体的对象和代码行。

全景:一个对象从 new 到被回收 · 第 9 站地图:J03 · JVM 故障排查:OOM、频繁 Full GC、CPU 飙高

①现象:服务出了事,要在 5 分钟内说出“是谁”

在全景第 9 站,订单 9527 被一个只放不删的缓存拉着,第 8 站的 GC 日志里 Full GC 一次比一次密,最后 Full GC 之后还是放不下新对象,JVM 抛出 OutOfMemoryError。这一步要解决的是:5 分钟内定位到是哪个对象占了内存、被谁拉着(地图上 J03 的过关题之二)。线上还有两种长得像、病根不同的情况:老年代反复被撑满但不 OOM,以及 CPU 被打满。下面是交易靶场订单服务里埋的三个雷,每个都在本机跑出了现象。

交易靶场订单服务 TradeServer JDK 17 · G1 8 个 http-exec 线程 订单 9527 起步 用户 1024 · 88 号键盘 × 2 /order 每秒约 7000 单 /export 4 个并发导出 /coupon?cents=1 只来了 1 个请求 RECENT.put(9527, 订单) “防重复提交记一下”,从来不删 每单带 1 KB 下单快照 20 万行拼成一个字符串 约 9.6 MB,再 toString、getBytes 每份都是“大对象” 1 分钱按比例分给 2 件商品 1 × 29900 / 59800 = 0,分不出去 while (remaining > 0) 永远成立 第 16 秒 OutOfMemoryError 进程活着、端口在听,请求全部没回音 应用日志里连异常栈都没打出来 30 秒 401 次 Full GC 停顿累计 20.8 秒,最慢的请求 30.6 秒 9 个请求 OOM,进程没死 一个核一直 100% 那个请求永远不返回 别的请求照常 2 ms 返回

谁拉着

OOM 和“Full GC 之后堆不降”:要找到那个一直不放手的引用 实测 128.7 MB 被 1 个 static 字段拉着

谁在猛分配

Full GC 很密,但每次都能降下来:要找到一阵阵分配大块内存的代码 实测 97% 的分配在导出接口

哪个线程哪一行

CPU 打满:要找到在跑的线程和它卡住的那一行 实测 Coupon.java:19

5 分钟

前提是证据已经在:GC 日志开着、OOM 时自动转储、出事时先拍线程转储再重启

②常见误判:每一条都“看起来对”,因为它让症状暂时消失了

排查最怕的不是不会用工具,而是一上来就下结论。下面六条在交易靶场里都能找到反例,最后一列是 ⑤ 里实测到的。

误判为什么看起来对错在哪
先重启,恢复了再说重启后服务马上正常堆里是谁、线程在跑什么,全跟着进程没了。泄漏过几小时又会回来,到时还是两手空空。
OOM 了就把堆调大OOM 确实来得晚了泄漏是只进不出,多大的堆都会填满。GC 日志页实测:同样的泄漏,256 MB 第 21.4 秒 OOM,512 MB 第 54.0 秒 OOM。
照着 OOM 的异常栈去改那一行异常栈指着一行具体代码OOM 抛给“最后一个想要内存”的线程,它多半是受害者。⑤ 里泄漏的是 /order,最先拿到 OOM 的却是 HTTP-Dispatcher、idle-timeout-task 这些线程。
CPU 高,就是业务代码慢业务一忙 CPU 就高⑤ 大导出时,两个 GC Thread 各吃掉 72% 和 71% 的核,业务线程每个才 4%。这时该查的是内存。
拍一张线程转储就下结论转储里确实有一堆 RUNNABLE一张转储只是某一瞬间。隔几秒拍两三张,同一个线程一直停在同一行,才算抓到,⑤ 里看的就是 cpu= 涨了多少。
Pod 重启了,当成堆 OOM 去查“内存不够”听起来是一回事被内核杀掉的进程没有 OutOfMemoryError,也不会留堆转储。退出码 137 先查堆外和容器限额,见 JVM 内存结构。

这六条错在同一个地方:没拿到证据就动手。所以排查路线的第 0 步一律是留现场;后面每一步都是“先看这一条证据,再决定往哪走”,不靠猜。

③排查路线:先留现场,再按证据分两条路走

从现象出发,每个岔口只看一条证据。三种现象最后只落到四个终点:谁拉着、谁在猛分配、哪个线程哪一行、堆外。CPU 高的那一路有一个回头箭头:吃 CPU 的要是 GC 线程,就回到内存路线。

第 0 步:先留现场,别急着重启 jstack 隔几秒拍 3 次 · 保住 GC 日志 · 堆转储(OOM 时自动的,或先摘流量再手动拍) · 容器事件和退出码 进程没了、Pod 被重启 应用日志里没有任何异常 退出码 137?容器事件 OOMKilled? 内核按整个进程的内存杀的,不是 JVM 不是堆:查堆外 线程栈 · 直接内存 · 元空间 · 代码缓存 GC 自己的数据结构 jcmd <pid> VM.native_memory 要先开 -XX:NativeMemoryTracking=summary → JVM 内存结构页 · 容器里的 JVM OutOfMemoryError: Java heap space 或者 Full GC 一次接一次 GC 日志:Full GC 之后,堆降不降? Full GC 之后剩下的 ≈ 还活着的对象 不降 · 泄漏 125M->125M 有东西一直拉着 降 · 分配太猛 228M->193M 大对象 · 一阵阵的峰 谁拉着 堆转储 + MAT 支配树、到 GC Root 的路 谁在猛分配 GC 日志里的 Humongous JFR 分配采样 CPU 飙高、RT 变长 top 里 java 进程 100% 以上 top -H -p:哪个线程在吃 CPU? 看线程名,Java 线程和内核线程一一对应 GC Thread G1 Conc ← 回内存路线 C2 Compiler 刚启动时多见 → JIT 预热 业务线程 http-exec-5 往下走 哪个线程哪一行 jstack 隔 2 秒拍几次 或 JFR 方法采样

OOM 冒号后面要是别的字,路线换一条:Metaspace 是类加载器被拉着,查法和“谁拉着”一样,只是看的是类加载器(见类加载页);Direct buffer memory 和 unable to create native thread 走左列的堆外;GC overhead limit exceeded 只有 Parallel 收集器会报,按“谁拉着”查。完整的对照表在 JVM 内存结构。

手上的工具:越往下信息越多,代价也越大

工具回答什么代价什么时候用
jstat -gcutil <pid> 1s各区占用百分比、GC 次数和累计时间几乎为零第一眼:Full GC 次数在不在涨
GC 日志 -Xlog:gc*每次 GC 的原因、前后占用、停顿很小,一直开着判断“降不降”,看有没有 Humongous(GC 日志页)
jcmd <pid> GC.class_histogram每个类有多少个、占多少字节先做一次 Full GC,停顿 ⑤ 实测 30.5 ms(128 MB 堆)先看“是什么”最多
堆转储 + MAT谁拉着谁、每个对象“连带”占多少停住整个进程写文件,文件和已用堆一样大回答“被谁拉着”
top -H -p <pid>每个线程的 CPU零CPU 高时的第一眼
jstack / jcmd Thread.print那一瞬间每个线程停在哪一行短暂停顿;一张只是一瞬间隔几秒拍几张,对比
JFR一段时间里的方法采样、分配采样、锁、GC 事件官方文档说默认配置的开销通常不到 1%,可以一直开“这一分钟里时间和内存花在哪”
NMT堆外每一块各占多少要启动时开,有少量开销被 OOMKilled、进程内存比堆大很多

选择规则:便宜的一直开(GC 日志、JFR 连续录制、OOM 时自动转储),出事时先拍一定拿得到的(线程转储、jstat),最贵的最后拍(堆转储,先摘流量)。本页的两条路线就用这几样:内存用 GC 日志 + 直方图 + 堆转储 + JFR 分配采样,CPU 用 top -H + jstack + JFR 方法采样。async-profiler、Arthas 这类第三方工具能做得更顺手,列进“下一圈”。

④背后的机制:OOM 抛给了谁,Full GC 之后的数字为什么能分出泄漏,堆转储和线程转储怎么对到“谁”

先知道这些
  • 可达性:从 GC Roots(线程栈上的局部变量、类的 static 字段、JNI 引用等)顺着引用走得到的对象就是活的,GC 不收。见 垃圾回收:分代、可达性、G1、ZGC。
  • 大对象(Humongous):G1 里超过半个 region 的对象直接在老年代占连续的几个 region。堆 128~256 MB 时 region 是 1 MB,门槛 512 KB。见 new 一个对象的全过程。
  • HotSpot 在 Linux 上一个 Java 线程对应一个内核线程,内核线程号在线程转储里叫 nid。见 线程、线程状态与上下文切换。

④-1 OOM 是一次分配失败:抛给碰巧在分配的那个线程,进程不退出

new byte[1024] 某个线程 TLAB / Eden 平常到这就结束 Young GC 腾出 Eden 再试 Full GC 整个堆标记、整理 还是放不下 → new OutOfMemoryError 抛给正在执行这次 new 的线程,和平常的异常一样往上走 不够 还不够 仍不够 拿到 OOM 的是谁,是碰巧的 雷 1 泄漏:不可恢复 泄漏的是 /order 的 RECENT.put,最先拿到 OOM 的却是: HTTP-Dispatcher · idle-timeout-task · http-exec-1…8 HTTP-Dispatcher 是收连接的线程,它一死,进程还在、端口还在听, 请求却再也没人接:curl 等 3 秒没回音 实测 连 printStackTrace 都要内存,所以应用日志里只有一行 雷 2 大导出:可以恢复 OOM 抛在 JDK 自带 HTTP 服务器的写缓冲区里: ByteBuffer.allocate ← Request$WriteStream.write ← export:87 那个请求失败、它的大数组变成垃圾,下一次 GC 就收回来了 30 秒里 9 个请求 OOM,其余 327 个正常 实测 JVM 分不清这两种情况,所以默认只抛异常,不替你退出

所以 OOM 的异常栈只说明“谁最后没要到内存”,不说明“内存被谁占了”。要回答后一个问题,得看堆里还活着什么,这是 ④-2 和 ④-3 的事。JVM 也提供了“一 OOM 就退出”的开关,让编排系统拉起新实例,见 ⑥ 坑 1。

④-2 Full GC 之后剩下的,就是还活着的:降不降,分出两条路

雷 1 泄漏:一次比一次降得少 堆上限 128M 124M→117M …125M→125M OOM 6 秒里 131 次 Full GC(示意,首末两次的数字取自日志) 实测 雷 2 大导出:每次都能降下来 堆上限 256M 改成流式后:GC 后稳定在 108M →144M GC 后中位数 193M,最低 144M 比 108M 多出来的,是那一刻正在导出的几个请求手里的大数组 30 秒 401 次 Full GC,前中位数 228M → 后 193M 实测

Full GC 会把所有还走得到的对象都留下,别的都收掉,所以 GC 之后的那个数近似等于“此刻活着的总量”。泄漏时活着的总量只涨不跌,这个数一路逼近上限;分配太猛时活着的总量其实不大,只是短时间内要的太多,这个数会掉回去。第 8 站的 GC 日志页用的是同一条规则:GC 后还是满的就是代码问题,不是参数问题。

④-3 直方图只能说“什么最多”,堆转储才能说“被谁拉着”

GC Root TradeServer.RECENT static 字段 HashMap 48 B Node[262144] 1 MB Node × 111621 32 B Long 键 24 B Order 48 B byte[1024] 快照 1040 B 类直方图:按类加总“自己多大”(shallow) 1: 125160 个 116720704 B [B ← byte[] 2: 111621 个 5357808 B Order 3: 116182 个 3717824 B HashMap$Node 排第一的是 byte[],Java 里到处都是 byte[],这一行说明不了是谁的 个数对得上(11 万多个 Order 和 Node)是线索,但不是结论 堆转储:按“拿掉它能一起收走多少”(retained) class TradeServer retained 128,745,544 98.50% └ HashMap (RECENT) retained 128,743,064 └ HashMap$Node[] retained 128,743,016 每条记录连带 1144 B = 32 + 24 + 48 + 1040,和直方图对得上 MAT 的 Leak Suspects 报告把这条路列成第一嫌疑 实测

支配树(dominator tree)是 retained size 的来源:从 GC Roots 到 B 的每一条路都必须经过 A,就说 A 支配 B,A 一旦不可达,B 必然跟着死。MAT 把整张对象图算成一棵支配树,树上每个节点的 retained size 就是它子树的总和,所以“哪个节点下面挂的最多”一眼就看得出来。直方图不做这件事,它便宜,但只能看叶子。

④-4 CPU 对到一行:内核线程号 = 线程转储里的 nid

top -H -p <pid> PID %CPU COMMAND 1989158 93.8 http-ex+ 1989088 0.0 GC Thre+ printf %x 0x1e5a26 jstack <pid>,找 nid=0x1e5a26 "http-exec-5" … cpu=5587.93ms elapsed=5.64s … nid=0x1e5a26 runnable java.lang.Thread.State: RUNNABLE at …Coupon.split(Coupon.java:19) JFR:每 10 ms 采一次在跑的线程的栈 10 秒,jdk.ExecutionSample 983 个 983 sampledThread = "http-exec-5" 925 Coupon.split line 14 · 58 line 19 隔 2 秒再拍一次 cpu=5587ms → 7793ms(2.2 秒涨了 2.2 秒) 还停在 Coupon.split:这才算抓到 只拍一次,可能正好拍到一个刚好路过的线程

两样工具的区别:jstack 要让所有 Java 线程停在安全点才能拍,拍到的是“停下来那一刻”的位置,一张只是一瞬间;JFR 在一段时间里按固定间隔采样,样本多了就是统计,能直接回答“这 10 秒 CPU 花在哪”。行号要看成“附近”:C2 编译后的循环只在部分位置记了行号,所以样本分到了第 14 行(for)和第 19 行(while 的回跳),都在同一个循环里(JIT 页)。

④-5 为什么这样设计:证据要在出事之前埋好

出事之后再去抓被放弃的做法

  • OOM 之后堆里全是活对象,jcmd 挂上去时 JVM 自己的挂接线程都要不到内存:⑤ 里先报了 Exception in VM (AttachListener::init) : java.lang.OutOfMemoryError,那次运气好,直方图最后还是拿到了。靠运气拿到的证据不能当流程
  • 值班的人先重启,现场就没了;CPU 高的那个请求,等你登上机器可能已经超时退出
  • 堆转储要停住整个进程写一个和堆一样大的文件,在正卡着的服务上再停一次,雪上加霜

提前埋好本页的做法

  • -XX:+HeapDumpOnOutOfMemoryError:OOM 的那一刻由 JVM 自己写转储,128 MB 堆写了 0.249 秒(⑤ 实测)
  • GC 日志、JFR 连续录制一直开着,开销小,出事后把最近一段倒出来就行
  • 出事时先拍线程转储(便宜、一定拿得到),再决定要不要重启

决定胜负的约束:现场转瞬即逝,而最有用的证据(堆转储)恰恰最贵、在出事时最难拿到。所以 JVM 把最贵的那次拍照做成“出事那一刻自动触发”,把能一直开的(GC 日志、JFR)做得足够便宜。OpenJDK 源码里还有一个细节:多个线程同时 OOM 时只转储第一次(report_java_out_of_memory 里用一个静态标志挡住),免得一次事故写出十几个几百 MB 的文件。

最少的命令

命令JDK 17参数细节放到 ⑥
# 启动时就埋好
-Xlog:gc*:file=gc.log  -XX:+HeapDumpOnOutOfMemoryError  -XX:HeapDumpPath=/data/dump
# 内存路线
jstat -gcutil <pid> 1000                      # Full GC 次数在不在涨
jcmd <pid> GC.class_histogram | head -15     # 什么最多(会先做一次 Full GC)
jcmd <pid> GC.heap_dump /data/dump/x.hprof   # 谁拉着,拿去 MAT
# CPU 路线
top -H -p <pid>                              # 哪个线程,记下线程号
printf '%x\n' <线程号>                        # 换成 nid
jstack <pid> | grep -A 12 'nid=0x<十六进制>' # 隔 2 秒拍几次
jcmd <pid> JFR.start duration=60s filename=/data/x.jfr   # 或者录一分钟

⑤复现一次:在订单服务里排掉三个雷

一个不依赖任何库的程序:TradeServer 用 JDK 自带的 HTTP 服务器起三个接口,Load 是压测客户端。按 JDK 8 的写法写(--release 8 编译),本机用 JDK 17 运行。完整代码 →

$ cd study-labs/java && mvn -q -pl jvm/jvm-troubleshooting compile && cd jvm/jvm-troubleshooting
$ CP=target/classes; M=labs.jvm.jvm_troubleshooting
# 每个雷开一个终端起服务,另一个终端压测;-Dsun.net.httpserver.nodelay=true 关掉 Nagle,不然每个请求白等 40 ms

⑤-1 雷 1:泄漏到 OOM,用直方图和 MAT 找到 RECENT

雷 1TradeServer.order
// “防重复提交,记一下最近的订单”
static final Map<Long, Order> RECENT = new HashMap<>();

Order o = new Order(id, user, sku, qty, 29900L * qty, true); // 带 1 KB 快照
synchronized (RECENT) {
    RECENT.put(o.id, o);           // 只放不删
}
$ java -Xmx128m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=. \
    -Xlog:gc:file=leak.log -Dsun.net.httpserver.nodelay=true -DhistoryK=0 -cp $CP $M.TradeServer
$ java -cp $CP $M.Load "http://127.0.0.1:8090/order?user=1024&sku=88&qty=2" 8 30
t=  5s  ok=18014   t= 10s  ok=35385   t= 15s  ok=55972
t= 20s  ok=2249    t= 25s  ok=0       t= 30s  ok=0
# 服务端 stdout
java.lang.OutOfMemoryError: Java heap space
Dumping heap to ./java_pid1985767.hprof ...
Heap dump file created [140421815 bytes in 0.249 secs]
# 服务端 stderr:连异常栈都没打出来
Exception: java.lang.OutOfMemoryError thrown from the
  UncaughtExceptionHandler in thread "HTTP-Dispatcher"
$ grep 'Pause Full' leak.log | sed -n '1p;$p'
[16.243s] Pause Full (G1 Compaction Pause) 124M->117M(128M) 33.7ms
[22.041s] Pause Full (G1 Compaction Pause) 125M->125M(128M) 30.1ms
$ grep -c 'Pause Full' leak.log
131
$ curl -m 3 http://127.0.0.1:8090/order; ss -ltn | grep 8090
(3 秒没回音)
LISTEN  0  512  [::ffff:127.0.0.1]:8090  *:*
$ jcmd <pid> GC.class_histogram | head -6
   1:   125160   116720704  [B
   2:   111621     5357808  labs…Order
   3:   116182     3717824  java.util.HashMap$Node
   4:   111877     2685048  java.lang.Long
$ ParseHeapDump.sh java_pid1985767.hprof org.eclipse.mat.api:suspects
# MAT 1.16.1 命令行,8 秒出报告;打开 *_Leak_Suspects.zip
Problem Suspect 1
The class labs…TradeServer … occupies
  128,745,544 (98.50%) bytes.
The memory is accumulated in one instance of
  java.util.HashMap$Node[] … 128,743,016 bytes.

Shortest Paths To the Accumulation Point
java.util.HashMap$Node[262144]   1,048,592  128,743,016
\ table java.util.HashMap         48        128,743,064
 \ RECENT class …TradeServer     16        128,745,544

5 分钟里做了三件事:GC 日志看到“125M→125M”,判定是泄漏(④-2);直方图看到 byte[] 和 11 万个 Order,知道“是什么”;堆转储交给 MAT,第一嫌疑直接指到 TradeServer.RECENT(④-3)。修法是给它上限和过期:防重复提交本来只需要记住几分钟,用带过期的缓存,或者干脆放进 Redis 设 TTL(⑥ 规范)。

⑤-2 雷 2:大导出让 Full GC 停不下来,改成流式

雷 2TradeServer.export
// 改之前:整份 CSV 先攒在内存里
StringBuilder sb = new StringBuilder();     // 一路翻倍扩容
for (Order o : today) o.appendCsv(sb);      // 20 万行 ≈ 9.6 MB
byte[] body = sb.toString().getBytes(UTF_8); // 再复制两份
os.write(body);       // JDK 的 HttpServer 里还要一块 2 倍大的缓冲

// 改之后:64 KB 一块,边算边写
byte[] buf = new byte[64 * 1024];
for (Order o : today) {
    line.setLength(0); o.appendCsv(line);
    if (n + line.length() > buf.length) { os.write(buf, 0, n); n = 0; }
    for (int i = 0; i < line.length(); i++) buf[n++] = (byte) line.charAt(i);
}
$ java -Xmx256m -Xlog:gc:file=big.log -Dsun.net.httpserver.nodelay=true \
    -DhistoryK=2000 -cp $CP $M.TradeServer      # 常驻 200 万条历史订单
$ java -cp $CP $M.Load "http://127.0.0.1:8090/export?rows=200000" 4 30
requests=336 ok=327 err=9  p50=265.2ms p99=925.8ms max=30597.8ms
$ jstat -gcutil <pid>   (节选:FGC  FGCT)
                                 401   20.795
$ grep -m3 'Humongous\|Pause Full' big.log
Pause Young (Concurrent Start) (G1 Humongous Allocation) 135M->132M
Pause Young (Normal) (G1 Humongous Allocation) 236M->236M 0.5ms
Pause Full (G1 Compaction Pause) 236M->153M(256M) 87.5ms

# 同一个服务,换成 /export?rows=200000&stream=true
requests=970 ok=970 err=0  p50=119.0ms p99=226.6ms max=1046.2ms
FGC 0 · Young GC 12 次 · Humongous 0 次 · GC 累计 0.129 s
$ top -H -b -n 2 -d 3 -p <pid>   (大导出时,第二屏)
    PID  %CPU  COMMAND
1989791  72.4  GC Thre+
1989773  70.8  GC Thre+
1989775   8.0  G1 Conc+
1989822   4.0  http-ex+
1989825   4.0  http-ex+
$ jcmd <pid> JFR.dump name=1 filename=x.jfr   # 启动时开了连续录制
$ jfr print --events jdk.ObjectAllocationSample x.jfr | 按调用点加总 weight
34.5%  byte[]  Order.appendCsv:25        # StringBuilder 扩容
34.1%  byte[]  TradeServer.export:85     # toString + getBytes
23.7%  byte[]  Order.appendCsv:22
 4.1%  byte[]  Order.appendCsv:23
# 合计 97% 的分配在导出这条路上

这一个雷把 ② 里两条误判都演了一遍:CPU 是满的,但吃 CPU 的是 GC 线程(转回内存路线);Full GC 之后能降到 144~221M(④-2,不是泄漏);OOM 抛在 JDK HTTP 服务器的写缓冲里,不在导出代码本身(④-1)。真正的证据是 GC 日志里成串的 G1 Humongous Allocation 和 JFR 的分配采样。按估算,一个导出请求同时拿着约 50 MB 的大数组(扩容后的 StringBuilder、String、byte[]、HTTP 缓冲),4 个并发就是 200 MB,再加 108 MB 常驻,256 MB 的堆装不下。

⑤-3 雷 3:一分钱的优惠券,用 top -H、jstack、JFR 找到那一行

雷 3Coupon.split左边是文件里的行号
11  long remaining = couponCents;
12  while (remaining > 0) {
13      long round = remaining;
14      for (int i = 0; i < prices.length; i++) {
15          long part = round * prices[i] / total; // 1 × 29900 / 59800 = 0
16          share[i] += part;
17          remaining -= part;               // 减了 0
18      }
19  }

// 改法:前面的按比例取整,尾差全给最后一件,只走一轮
share[n - 1] = couponCents - given;
$ curl "http://127.0.0.1:8090/coupon?cents=1&prices=29900,29900" &   # 不返回
$ top -H -b -n 1 -p <pid> | head -9
    PID  S  %CPU  COMMAND
1989158  R  93.8  http-ex+
1989085  S   0.0  java
$ printf '%x\n' 1989158
1e5a26
$ jstack <pid> | grep -A3 'nid=0x1e5a26 '
"http-exec-5" #19 … cpu=5587.93ms elapsed=5.64s … nid=0x1e5a26 runnable
   java.lang.Thread.State: RUNNABLE
	at …Coupon.split(Coupon.java:19)
	at …TradeServer.coupon(TradeServer.java:113)
# 2 秒后再拍:cpu=7793.52ms,还在 Coupon.java:19
$ curl -w '%{http_code} %{time_total}s' http://127.0.0.1:8090/order
200 0.002256s           # 别的请求照常
$ jcmd <pid> JFR.start duration=10s settings=profile filename=cpu.jfr
$ jfr print --events jdk.ExecutionSample --stack-depth 1 cpu.jfr | …
925  Coupon.split(long, long[]) line: 14
 58  Coupon.split(long, long[]) line: 19
983  sampledThread = "http-exec-5"

两种工具指到同一个循环(④-4)。这个雷不会自己好:Java 线程没法从外面安全地杀掉,这个线程会一直占着一个核和线程池里的一个位置。按推算,再来 7 个一分钱的请求,8 个 http-exec 线程就全卡死,整个服务不再响应。上线前该有的是单元测试覆盖“1 分钱、0 元商品、一件商品”这些边界,以及循环的最大轮数(⑥ 规范)。

到这里已经能交差了。三个雷各有一条证据链:泄漏是“GC 后不降 → 直方图 → MAT 指到 RECENT”,大对象是“GC 线程吃 CPU → GC 后能降 → Humongous → JFR 分配采样指到 export”,死循环是“top -H → nid → 两次 jstack 同一行 → JFR 确认”。写成排障记录,就是地图上 J03 给靶场的任务。

已知还没处理的细节:OOM 之后进程成了僵尸(⑥ 坑 1);转储文件放在哪、会不会把盘写满(⑥ 坑 2);在线上大堆上拍转储会停多久(⑥ 坑 3);容器里被杀掉时这些都用不上(⑥ 坑 6)。

⑥根治和预防:坑、启动参数、编码规范、更深一层

第一圈

注意事项

坑 1OOM 之后进程还在,健康检查也绿着,但一个请求都不处理← ④-1 OOM 只是一个异常⑤ 实测
现象
端口在监听,进程在,监控说实例存活;请求全部超时。⑤ 雷 1 里 curl 等 3 秒没回音。
根源
OOM 抛给了碰巧在分配的线程。收连接的 HTTP-Dispatcher 线程拿到它就死了,别的线程还活着,JVM 没有理由退出。
做法
加 -XX:+ExitOnOutOfMemoryError,第一次 OOM 就退出(退出码 3),让 K8s 拉新实例。它和 HeapDumpOnOutOfMemoryError 可以一起开,按源码的顺序先写转储再退出。存活探针要走一条真实的业务路径,不要只看端口。
坑 2配了 OOM 自动转储,出事时却没有文件← ④-5 只转储第一次源码核对
现象
日志里有 Dumping heap to …,后面跟着失败;或者干脆找不到文件。
根源
转储文件和已用的堆差不多大(⑤ 128 MB 堆写出 140 MB),盘不够就写不完。路径是目录时文件名是 java_pid<pid>.hprof,容器里 pid 常常都是 1,上次的文件还在就写不出来(JDK 17 源码里这里不覆盖)。Pod 被重建,本地盘上的文件也跟着没了。
做法
HeapDumpPath 指到挂载的持久卷,按 Pod 名分目录,留出一个堆大小以上的空间;拷走以后删掉。
坑 3在线上手动拍堆转储,服务卡住好几秒← ④-5 最贵的证据⑤ 实测 + 估算
现象
执行 jcmd GC.heap_dump 之后,这台实例所有请求一起超时,上游开始重试。
根源
转储期间整个进程停着。GC.heap_dump 默认只转储活对象,所以还要先做一次 Full GC。⑤ 里 128 MB 写了 0.249 秒,按同样的速度估算,16 GB 的堆是半分钟量级。直方图也会先做一次 Full GC(⑤ 实测 30.5 ms)。
做法
先把这台实例从负载均衡里摘掉再拍。要的是全部对象(包括已经不可达的)时加 -all,省掉那次 Full GC;盘紧张时加 -gz=1 压缩,代价是写得更慢。
坑 4直方图第一行是 byte[]、String,看了等于没看← ④-3 shallow 和 retained⑤ 实测
现象
⑤ 雷 1 的直方图第一行是 [B,116.7 MB。全系统都在用 byte[],不知道是谁的。
根源
直方图只按类加总每个对象“自己”的大小,不知道谁拉着谁。
做法
往下看第一个业务类(这里是 11 万个 Order),个数往往和容器的 Node 个数对得上;要结论就拍堆转储看支配树。隔几分钟拍两次直方图做差,涨得最多的那一类最可疑。
坑 5top 里线程名只剩一半,jstack 的行号和你想的差一两行← ④-4 nid 和采样⑤ 实测
现象
top 显示 http-ex+;几个吃 CPU 的线程名字一样长,分不清。jstack 说第 19 行,JFR 多数样本在第 14 行。
根源
top 的列宽会截断名字,内核本身也只留线程名的前 15 个字符;C2 编译后的代码只在部分位置记了行号。
做法
用线程号换成 nid 去对,不要靠名字;线程池起名时把区分度放在前面(export-3 比 http-nio-8080-exec-3 好认)。行号当成“这一段”,回到源码里看整个循环。
坑 6Pod 一直重启,没有 OOM、没有转储、日志干干净净← ③ 左列:不是堆按文档
现象
容器状态 OOMKilled,退出码 137;这一页的所有工具都没留下东西。
根源
内核按整个进程的内存(堆 + 线程栈 + 直接内存 + 元空间 + 代码缓存 + GC 自己的结构)杀进程,JVM 来不及做任何事。
做法
堆只给容器上限的 60%~75%;开 -XX:NativeMemoryTracking=summary,用 jcmd VM.native_memory 看堆外各占多少。详见 JVM 内存结构,全景第 10 站。
第二圈

使用规范

启动参数JDK 17 / 21,每个服务都带上JFR 这行本机 JDK 17 跑过
-Xlog:gc*:file=/data/log/gc-%p-%t.log:time,uptime,level,tags:filecount=10,filesize=50m
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dump/${POD_NAME}/
-XX:+ExitOnOutOfMemoryError                              # 坑 1:别当僵尸
-XX:StartFlightRecording=disk=true,maxage=6h,maxsize=200m,dumponexit=true,filename=/data/jfr/app.jfr
# 需要查堆外时再加:-XX:NativeMemoryTracking=summary
规范防的是什么
上面这组参数写进基础镜像,不靠每个服务自己记得出事时才发现没有 GC 日志、没有转储,只能靠猜(④-5)
值班手册第一条:先拍 3 次线程转储、存 GC 日志和 JFR,再摘流量拍堆转储,最后才重启“先重启再说”把现场弄没(② 误判 1)
放进内存的集合一律有上限和过期:static Map 只能放有限的、启动时就确定的东西雷 1:只放不删的缓存。要缓存就用带上限和过期的缓存库,或者放到 Redis 设 TTL
导出、报表、批量接口一律流式或分页,单个请求的内存和数据量无关雷 2:一次请求几十 MB 的大对象,并发一高就 Full GC
“直到分完为止”的循环必须有最大轮数;金额计算用单测覆盖 1 分钱、0 元、只有一件这些边界雷 3:取整之后永远退不出去的循环
告警看“Full GC 之后老年代占用”的趋势,不只等 OOM泄漏是几小时、几天慢慢涨上去的,趋势告警比 OOM 早得多(④-2)
排障记录固定写:现象、时间线、证据(命令和输出原文)、根因、修复、预防下一次同类问题不用从头查;地图上 J03 的靶场任务交的就是这个
练习台

拿到一条证据,下一步往哪走

排查练习台:先猜,再看为什么


    

看到这条证据,下一步该做什么?

先选一个答案。

证据都是 ⑤ 里真跑出来的输出,或者按文档写的典型输出(案例里注明了)。左右方向键也能切换案例。

第三圈

更深一层

线程转储要等安全点,采样器不用:为什么 JFR 的“热点”更可信

jstack 是一次安全点操作:所有 Java 线程跑到下一个安全点停下,VM 线程再逐个记下栈。所以它拍到的永远是“安全点附近”,长时间不进安全点的代码会让所有线程一起等。JFR 的方法采样按固定间隔挑几个正在跑 Java 代码的线程,暂停它、记下栈、放它走,不需要全体停下,⑤ 里 10 秒 983 个样本几乎没有影响其他请求。它仍然只采 Java 帧;要看 native 代码和内核里的时间,用 async-profiler 这类工具,列在下一圈。

堆转储要换个地方分析

MAT 解析时要建索引,内存大约要和转储文件同一量级,所以别在出事的那台机器上开。⑤ 里用的是 MAT 的命令行:ParseHeapDump.sh x.hprof org.eclipse.mat.api:suspects,140 MB 的转储 8 秒出报告(MAT 1.16.1,要 JDK 17 以上运行),解析出的索引文件留在转储旁边,之后用图形界面打开就不用再解析。大转储给 MAT 调大 MemoryAnalyzer.ini 里的 -Xmx。

版本差异

能力JDK 8JDK 17JDK 21
GC 日志-XX:+PrintGCDetails -Xloggc:统一日志 -Xlog:gc*(JDK 9 起)
JFR8u262 起 OpenJDK 才有自带;jfr 命令行工具可以直接打印事件
分配采样 jdk.ObjectAllocationSample没有,只有 TLAB 内外分配事件有(JDK 16 起),带限流,可以一直开
线程转储里的 cpu= elapsed=没有,只能靠 top -H有(JDK 11 起),一次转储就能看出谁在吃 CPU
GC.heap_dump -gz没有有(JDK 15 起)
虚拟线程没有jstack 看不到虚拟线程,用 jcmd <pid> Thread.dump_to_file -format=json

本机只用 JDK 17 跑了这页的实验;JDK 8 和 21 这一列来自各版本的发行说明和 JEP,没有在本机复现。

下一圈

↺回到⑤:把三个雷修掉,再排一次

练习用到做对了会看到
1. 把 RECENT 换成有上限的 LRU(LinkedHashMap 重写 removeEldestEntry,上限 1 万),用同样的压测跑 60 秒第二圈 · 缓存有上限没有 OOM;GC 日志里没有 Full GC,Young GC 之后的占用稳定
2. 给雷 1 加上 -XX:+ExitOnOutOfMemoryError 重跑坑 1进程退出,echo $? 是 3;转储文件照样在
3. 先猜:同时发 8 个一分钱的请求,/order 还能返回吗?再跑一次验证,然后给 split 加最大轮数④-4 · 第二圈 · 循环要有出口8 个线程全部卡住,/order 超时;修好后 cents=1 立即返回 0 1
1. 用一句话说出这一页的精华。

三种现象只有两个问题:内存先看 Full GC 之后降不降,不降找“谁拉着”(堆转储),降了找“谁在猛分配”(GC 日志 + JFR 分配采样);CPU 先看是哪个线程,GC 线程就回内存路线,业务线程就对到那一行。证据要在出事之前埋好。

2. “先重启”和“加大堆”这两个老办法,疼在哪?

重启把现场弄没了,泄漏过一阵又回来,到时还是没有证据;加堆只是把泄漏的 OOM 往后推(GC 日志页实测 256 MB 第 21 秒、512 MB 第 54 秒),而且 Full GC 要处理的活对象更多,每次停得更久。

3. 为什么不能照着 OOM 的异常栈去改那一行?是哪条原理?

④-1:OOM 是一次分配失败,抛给的是碰巧在分配的那个线程。占内存的可能是另一个线程、很久以前放进去的对象。⑤ 雷 1 里拿到 OOM 的是 HTTP-Dispatcher 这类线程,雷 2 里是 JDK HTTP 服务器的写缓冲。

4. 预测:雷 2 把堆从 256 MB 调到 1 GB,Full GC 会怎样?这算修好了吗?

Full GC 会消失:常驻 108 MB,加上 4 个并发导出约 200 MB 的峰值,1 GB 装得下,大对象在 Young GC 里就被收掉了。从 ④-2 推出:GC 后能降,说明活对象不多,是峰值问题,这种问题加堆是对症的。本机跑过:1 GB 时 30 秒 0 次 Full GC,但 G1 Humongous Allocation 触发的 Young GC 有 514 次;吞吐 1603 个请求、p50 73.5 ms,甚至比 ⑤ 的流式写法(970 个、119 ms,逐字符拷贝更费 CPU)还快。它是合法的修法,代价是内存用量仍和导出行数、并发数成正比,导出量翻几倍又会回来;流式写法让每个请求只用 64 KB,和数据量无关。两个可以一起用。

5. 预测:雷 3 换成 ZGC,或者把机器从 2 核加到 8 核,会好吗?

不会。这是业务线程自己在空转,和 GC 无关(④-4:吃 CPU 的是 http-exec-5,不是 GC 线程)。加核只是让它占的那个核在总量里显得少一点,请求还是永远不返回,线程池里的位置也一直被占着。

6. 放回全景:第 9 站前后各发生了什么?要是把第 10 站的 OOMKilled 当成第 9 站的堆 OOM 去查,会怎样?

前面是第 8 站:GC 日志里 Full GC 越来越密、GC 之后的占用一路上涨,这是泄漏最早的信号;后面是第 10 站:容器只看整个进程的内存。把 OOMKilled 当堆 OOM 查,会去找转储(根本没有,内核直接杀的),找不到就把 -Xmx 调大,结果堆外更没有余量,被杀得更勤。正确的分岔在 ③ 左列:先看退出码 137 和容器事件,再用 NMT 看堆外。