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 被打满。下面是交易靶场订单服务里埋的三个雷,每个都在本机跑出了现象。
谁拉着
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 线程,就回到内存路线。
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 是一次分配失败:抛给碰巧在分配的那个线程,进程不退出
所以 OOM 的异常栈只说明“谁最后没要到内存”,不说明“内存被谁占了”。要回答后一个问题,得看堆里还活着什么,这是 ④-2 和 ④-3 的事。JVM 也提供了“一 OOM 就退出”的开关,让编排系统拉起新实例,见 ⑥ 坑 1。
④-2 Full GC 之后剩下的,就是还活着的:降不降,分出两条路
Full GC 会把所有还走得到的对象都留下,别的都收掉,所以 GC 之后的那个数近似等于“此刻活着的总量”。泄漏时活着的总量只涨不跌,这个数一路逼近上限;分配太猛时活着的总量其实不大,只是短时间内要的太多,这个数会掉回去。第 8 站的 GC 日志页用的是同一条规则:GC 后还是满的就是代码问题,不是参数问题。
④-3 直方图只能说“什么最多”,堆转储才能说“被谁拉着”
支配树(dominator tree)是 retained size 的来源:从 GC Roots 到 B 的每一条路都必须经过 A,就说 A 支配 B,A 一旦不可达,B 必然跟着死。MAT 把整张对象图算成一棵支配树,树上每个节点的 retained size 就是它子树的总和,所以“哪个节点下面挂的最多”一眼就看得出来。直方图不做这件事,它便宜,但只能看叶子。
④-4 CPU 对到一行:内核线程号 = 线程转储里的 nid
两样工具的区别: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 的文件。
最少的命令
# 启动时就埋好
-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
// “防重复提交,记一下最近的订单”
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 停不下来,改成流式
// 改之前:整份 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 找到那一行
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 元商品、一件商品”这些边界,以及循环的最大轮数(⑥ 规范)。
⑥根治和预防:坑、启动参数、编码规范、更深一层
注意事项
- 现象
- 端口在监听,进程在,监控说实例存活;请求全部超时。⑤ 雷 1 里
curl等 3 秒没回音。 - 根源
- OOM 抛给了碰巧在分配的线程。收连接的
HTTP-Dispatcher线程拿到它就死了,别的线程还活着,JVM 没有理由退出。 - 做法
- 加
-XX:+ExitOnOutOfMemoryError,第一次 OOM 就退出(退出码 3),让 K8s 拉新实例。它和HeapDumpOnOutOfMemoryError可以一起开,按源码的顺序先写转储再退出。存活探针要走一条真实的业务路径,不要只看端口。
- 现象
- 日志里有
Dumping heap to …,后面跟着失败;或者干脆找不到文件。 - 根源
- 转储文件和已用的堆差不多大(⑤ 128 MB 堆写出 140 MB),盘不够就写不完。路径是目录时文件名是
java_pid<pid>.hprof,容器里 pid 常常都是 1,上次的文件还在就写不出来(JDK 17 源码里这里不覆盖)。Pod 被重建,本地盘上的文件也跟着没了。 - 做法
HeapDumpPath指到挂载的持久卷,按 Pod 名分目录,留出一个堆大小以上的空间;拷走以后删掉。
- 现象
- 执行
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压缩,代价是写得更慢。
- 现象
- ⑤ 雷 1 的直方图第一行是
[B,116.7 MB。全系统都在用 byte[],不知道是谁的。 - 根源
- 直方图只按类加总每个对象“自己”的大小,不知道谁拉着谁。
- 做法
- 往下看第一个业务类(这里是 11 万个
Order),个数往往和容器的Node个数对得上;要结论就拍堆转储看支配树。隔几分钟拍两次直方图做差,涨得最多的那一类最可疑。
- 现象
- top 显示
http-ex+;几个吃 CPU 的线程名字一样长,分不清。jstack 说第 19 行,JFR 多数样本在第 14 行。 - 根源
- top 的列宽会截断名字,内核本身也只留线程名的前 15 个字符;C2 编译后的代码只在部分位置记了行号。
- 做法
- 用线程号换成
nid去对,不要靠名字;线程池起名时把区分度放在前面(export-3比http-nio-8080-exec-3好认)。行号当成“这一段”,回到源码里看整个循环。
- 现象
- 容器状态
OOMKilled,退出码 137;这一页的所有工具都没留下东西。 - 根源
- 内核按整个进程的内存(堆 + 线程栈 + 直接内存 + 元空间 + 代码缓存 + GC 自己的结构)杀进程,JVM 来不及做任何事。
- 做法
- 堆只给容器上限的 60%~75%;开
-XX:NativeMemoryTracking=summary,用jcmd VM.native_memory看堆外各占多少。详见 JVM 内存结构,全景第 10 站。
使用规范
-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 8 | JDK 17 | JDK 21 |
|---|---|---|---|
| GC 日志 | -XX:+PrintGCDetails -Xloggc: | 统一日志 -Xlog:gc*(JDK 9 起) | |
| JFR | 8u262 起 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 看堆外。