上一篇《一次锁竞争的完整定位》查的是 CPU 和锁，这篇查内存。同一个思路：先写一个能复现症状的程序，再用 JVM 自带工具一层层把证据收齐。
顺序是从粗到细：GC 日志看趋势，jcmd 和 JFR 看运行时，堆 dump 看末端对象。全文用 JDK 25 跑，每个数字都对应下面贴出来的原始输出。
最后收两个真会把人带偏的场景：堆几乎是空的时候 OOM，以及没人碰老年代却一直 Full GC。

实验环境与口径

机器和 JDK：

1
2
3
4
5
6
7
8
9
10
$ sysctl -n machdep.cpu.brand_string hw.ncpu hw.memsize kern.osversion
Apple M1 Pro
10
17179869184
25G83

$ java -version
java version "25" 2025-09-16 LTS
Java(TM) SE Runtime Environment (build 25+37-LTS-3491)
Java HotSpot(TM) 64-Bit Server VM (build 25+37-LTS-3491, mixed mode, sharing)

工具全部来自 JDK 自带：java / javac / jcmd / jfr / jhsdb，没有装 MAT、VisualVM 或任何第三方分析器。

这台机器在跑实验的时候并不空。uptime 的 load average 在整轮实验里落在 5.2 到 9.6 之间，一部分是实验自己造成的（G1 的并发标记线程和 ZGC 的并发线程都吃 CPU），一部分是机器上本来就有别的进程。所以所有对比都取 3 次重复的中位数，只做横向比较，不把绝对值当成硬件上限。

被测程序

LeakDemo 是一个定速分配负载，用 --mode= 切换三种保留策略：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
interface Sink { void put(String k, byte[] v); }

/** 无界，只进不出 */
static final class LeakSink implements Sink {
    final Map<String, byte[]> m = new HashMap<>();
    public void put(String k, byte[] v) { m.put(k, v); }
}

/** 有界 LRU：LinkedHashMap(accessOrder=true) + 超限从最旧开始淘汰 */
static final class BoundedSink implements Sink {
    final long maxBytes;
    long bytes;
    final LinkedHashMap<String, byte[]> m = new LinkedHashMap<>(1024, 0.75f, true);
    public void put(String k, byte[] v) {
        byte[] old = m.put(k, v);
        bytes += v.length - (old == null ? 0 : old.length);
        if (bytes > maxBytes) {
            Iterator<Map.Entry<String, byte[]>> it = m.entrySet().iterator();
            while (bytes > maxBytes && it.hasNext()) {
                bytes -= it.next().getValue().length;
                it.remove();
            }
        }
    }
}

主循环按 400 次/秒的节奏走，每次分配一个 256 KiB 的 byte[]，每 8 次里的 1 次把它留在堆上。算下来是每秒分配 100 MiB、净增长 12.5 MiB。留的对象塞进 Sink，leak 模式进无界 HashMap，bounded 模式进有界 LRU，none 模式直接丢掉。

payload 选 256 KiB 是有原因的：-Xmx512m 时 G1 的 region 是 1 MiB，超过 512 KiB（region 的一半）的分配会走 humongous 路径，行为跟普通对象不一样。256 KiB 落在普通路径里，日志才干净。

三个模式跑同一份代码、同一份参数，只换 Sink 实现。

第一步：把症状跑出来

leak 模式配 -Xms512m -Xmx512m 跑 3 次，每次都是跑到 OutOfMemoryError 才停：

1
2
3
4
5
6
7
8
$ java -Xms512m -Xmx512m -Xlog:gc*:file=LOG:time,uptime,level,tags \
    -cp classes LeakDemo --mode=leak --rate=400 --payloadKB=256 --retainEvery=8 --seconds=180
CONFIG mode=leak rate=400/s payloadKB=256 retainEvery=8 seconds=180 cacheMB=64
@t=28s ops=11201 heapUsed=368MB heapCommitted=512MB rss=445MB
@t=29s ops=11601 heapUsed=369MB heapCommitted=512MB rss=446MB
@t=30s ops=12001 heapUsed=377MB heapCommitted=512MB rss=446MB
!! OutOfMemoryError
RESULT pid=67991 mode=leak outcome=OOM elapsedMs=29590 ops=11825 opsPerSec=399.6 windowSec=29 windowOps=11825 windowOpsPerSec=407.8 retiredMB=369 leakMBps=12.75 heapUsedMB=372 heapCommittedMB=512 allocP50us=9 allocP99us=781 allocMaxus=51192 allocOver10ms=4

三次的结果：

1
2
3
rep1  elapsedMs=29588  ops=11826  retiredMB=369  leakMBps=12.75  allocP99us=785  allocOver10ms=4
rep2  elapsedMs=29590  ops=11825  retiredMB=369  leakMBps=12.75  allocP99us=781  allocOver10ms=4
rep3  elapsedMs=29539  ops=11809  retiredMB=369  leakMBps=12.73  allocP99us=765  allocOver10ms=3

三次都在 29.5 秒上下撞上 OOM，误差 50 毫秒。这一轮跑的是 --rate=400 --payloadKB=256 --retainEvery=8：每秒发出 400 个 256 KiB 的 payload，每 8 个保留一个，折合 400 × 256 KiB ÷ 8 = 12.5 MiB/s。实测 retiredMB=369 除以 29 秒的统计窗口得到 12.73 到 12.75 MiB/s，与参数算出来的一致，差在窗口取整。后面每轮读各自的 leakMBps，参数一换数字就变。

allocP99us 那一列：正常分配（none 模式，同一台机器同一时段）的 p99 是 56 到 89 微秒；泄漏版最后阶段 p99 涨到 765 到 785 微秒，还有一个 51 毫秒的尖峰。原因是堆快满的时候分配线程会撞上 GC 的同步点。在这次实验里，分配延迟的 p99 比迭代数和 CPU 更早暴露堆压力（同一台机器、3 次重复）。

第二步：GC 日志看趋势

参数

1
-Xlog:gc*:file=gc.log:time,uptime,level,tags

JDK 9 之前 GC 日志是一堆独立开关：-XX:+PrintGCDetails、-XX:+PrintGCDateStamps、-Xloggc:gc.log、-XX:+PrintGCApplicationStoppedTime，各自控制一小块输出，格式还互不相同。JEP 158 在 JDK 9 引入了统一的 JVM 日志框架（-Xlog），JEP 271 在同一个版本把 GC 日志迁到这套框架上。旧的开关后来的命运并不一致，本机 JDK 11 和 JDK 25 上实测：

1
2
3
4
5
6
7
8
9
$ java -XX:+PrintGCDetails -version
[0.001s][warning][gc] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead.

$ java -Xloggc:/tmp/lg.log -version
[0.001s][warning][gc] -Xloggc is deprecated. Will use -Xlog:gc:/tmp/lg.log instead.

$ java -XX:+PrintGCDateStamps -version
Unrecognized VM option 'PrintGCDateStamps'
Error: Could not create the Java Virtual Machine. Error: A fatal exception has occurred. Program will exit.

PrintGCDetails / PrintGC / -Xloggc 还在，会被自动翻译成等价的 -Xlog 写法并打一条警告；PrintGCDateStamps 和 PrintGCApplicationStoppedTime 已经完全移除，传了直接起不来。也就是说升级 JDK 的时候，老启动参数里冒出来的”Unrecognized VM option”很可能就是这些遗留的 GC 日志开关。

-Xlog 的语法是 what:output:decorators。上面的写法里：

  • gc* 是 tag 选择器：gc 加上所有以 gc 开头的子 tag（gc,heap、gc,phases、gc,metaspace、gc,cpu 等）。不写星号只匹配 gc 这一个 tag，那样拿到的信息会少一大截。
  • file=gc.log 是输出目标，不写就是 stdout。
  • time,uptime,level,tags 是装饰器。uptime 是相对 JVM 启动的秒数，排查时比墙钟时间好用；time 是 ISO-8601 绝对时间，用来跟应用日志对齐；level 和 tags 告诉你这条消息的等级和来源。

不带星号的 -Xlog:gc 大约等价于老的 -XX:+PrintGC，一条 GC 一行；加上 * 之后接近 -XX:+PrintGCDetails 并且更全。

读一段真实日志

下面这段取自诊断run（-Xms768m -Xmx768m）的第 60 到 61 秒：

1
2
3
4
5
6
7
8
9
10
11
12
[2026-09-15T17:05:14.329+0800][60.225s][info][gc,start       ] GC(29) Pause Full (Heap Inspection Initiated GC)
[2026-09-15T17:05:14.432+0800][60.328s][info][gc,heap        ] GC(29) Eden regions: 110->0(203)
[2026-09-15T17:05:14.432+0800][60.328s][info][gc,heap        ] GC(29) Survivor regions: 13->0(15)
[2026-09-15T17:05:14.432+0800][60.328s][info][gc,heap        ] GC(29) Old regions: 577->507
[2026-09-15T17:05:14.432+0800][60.328s][info][gc,heap        ] GC(29) Humongous regions: 19->19
[2026-09-15T17:05:14.432+0800][60.328s][info][gc             ] GC(29) Pause Full (Heap Inspection Initiated GC) 687M->397M(768M) 103.395ms
[2026-09-15T17:05:15.851+0800][61.747s][info][gc,start       ] GC(30) Pause Young (Concurrent Start) (G1 Evacuation Pause)
[2026-09-15T17:05:15.852+0800][61.748s][info][gc,heap        ] GC(30) Eden regions: 203->0(190)
[2026-09-15T17:05:15.852+0800][61.748s][info][gc,heap        ] GC(30) Survivor regions: 0->13(26)
[2026-09-15T17:05:15.852+0800][61.748s][info][gc,heap        ] GC(30) Old regions: 507->507
[2026-09-15T17:05:15.852+0800][61.748s][info][gc,heap        ] GC(30) Humongous regions: 19->19
[2026-09-15T17:05:15.852+0800][61.748s][info][gc             ] GC(30) Pause Young (Concurrent Start) (G1 Evacuation Pause) 600M->410M(768M) 1.048ms

GC(29) 是 GC 序号，同一轮 GC 的所有日志行共用它，gc,start 和结尾的汇总行能对上。序号从 0 开始单调递增，看两个时间点的差值就知道这段窗口里 GC 有多密。

Pause Full (Heap Inspection Initiated GC) 是这一轮的类型和触发原因。Pause 表示这是一次 stop-the-world；Young / Full 是回收范围；括号里是原因。这里的 Heap Inspection Initiated GC 是 jcmd <pid> GC.class_histogram 引起的。也就是说，这一行 Full GC 不是应用自己需要的，是排查动作造成的。同类原因还有 System.gc()、G1 Compaction Pause（G1 自己决定做 Full GC 压实）、Metadata GC Threshold（元空间触发）。

Eden regions: 110->0(203) 是 G1 特有的容量表达：region 数，1 个 region 在 768 MiB 堆上等于 1 MiB。回收前 110 个 region，回收后 0 个。括号里的 203 是这一轮结束后 Eden 的目标容量，不是开始时的数量，同一份日志就能验证：GC(1) 的 before 值正好等于 GC(0) 括号里的 213。

Old regions: 577->507 单独看没意义，看趋势才有意义。

687M->397M(768M) 103.395ms 是这一轮的核心三元组：回收前堆占用、回收后堆占用、堆容量，最后是暂停时长。回收前后差了 290 MiB，说明这一轮回收了东西；如果两个数字几乎相等（下面会看到 582M->582M），这一轮就等于什么都没回收。

第 30 轮的 Old regions: 507->507：老年代一个 region 都没回收掉，因为里面全是活对象。

趋势比单点重要

把 90 秒里每次 GC 打印的 Old regions 抽出来：

1
2
3
4
5
6
7
8
t=  0.5s  Old    2 ->    2 regions (2 MiB)
t=  9.2s  Old    2 ->   27 regions (27 MiB)
t= 12.3s  Old   27 ->   54 regions (54 MiB)
t= 48.7s  Old  350 ->  373 regions (373 MiB)
t= 56.7s  Old  535 ->  559 regions (559 MiB)
t= 64.5s  Old  507 ->  578 regions (578 MiB)
t= 72.9s  Old  591 ->  644 regions (644 MiB)
t= 88.1s  Old  738 ->  741 regions (741 MiB)

老年代从 2 MiB 一路涨到 741 MiB，中间没有任何一次跌回低位。这是泄漏和”堆用得多”的分界：堆压力大但正常的话，Full GC 之后老年代会掉下来；泄漏的话，每次 GC 之后剩下的活对象只多不少。12.3 秒到 48.7 秒这段（36.4 秒）涨了 319 MiB，折合 8.8 MiB/s；整段看下来大约是 8 MiB/s 量级，跟第一步算出来的 12.5 MiB/s 净保留量同一数量级（差异来自 G1 的并发周期什么时候启动、以及年轻代里还没晋升的部分）。

到了最后几秒，日志的形状会变：

1
2
3
4
5
6
[2026-09-15T17:05:44.700+0800][90.596s][info][gc,start       ] GC(389) Pause Full (G1 Compaction Pause)
[2026-09-15T17:05:44.706+0800][90.602s][info][gc             ] GC(389) Pause Full (G1 Compaction Pause) 582M->582M(768M) 6.405ms
[2026-09-15T17:05:44.706+0800][90.602s][info][gc,start       ] GC(390) Pause Young (Normal) (G1 Evacuation Pause)
[2026-09-15T17:05:44.707+0800][90.603s][info][gc             ] GC(390) Pause Young (Normal) (G1 Evacuation Pause) 582M->582M(768M) 0.616ms
[2026-09-15T17:05:44.707+0800][90.603s][info][gc,start       ] GC(391) Pause Full (G1 Compaction Pause)
[2026-09-15T17:05:44.732+0800][90.628s][info][gc             ] GC(391) Pause Full (G1 Compaction Pause) 582M->565M(768M) 25.267ms

一轮接一轮，582M->582M 反复出现：90.596s 到 90.628s 这 32 毫秒里连做三次 GC，前两次一点没回收，第三次才掉到 565M。这种形态叫 GC 抖动（thrashing）：可回收的对象已经没有了，但分配还在继续，JVM 只能不停触发回收来腾地方。到这个阶段离 OOM 只剩几百毫秒。

GC 序号从 0 涨到 391。最后 29 秒（GC(30) 在 61.747s，GC(391) 在 90.628s）就做了 362 次，平均每秒十几次。

第三步：运行时观测

GC 日志只能告诉你”堆在涨”，说不清是哪个类在涨。这一步换 jcmd 和 JFR。

GC.heap_info

1
2
3
4
$ jcmd 79042 GC.heap_info
79042:
garbage-first heap   total reserved 786432K, committed 786432K, used 431745K [0x00000007d0000000, 0x0000000800000000)
 region size 1024K, 301 young (308224K), 52 survivors (53248K)

used 431745K 是整堆当前占用。region size 1024K 确认了 region 大小。301 young 是当前 Eden + Survivor 占用的 region 数。命令本身不触发 GC；官方把它的影响标为 Medium，压测期间别高频调用。

同一次运行第 60 秒再打一次：

1
2
3
4
$ jcmd 79042 GC.heap_info
79042:
garbage-first heap   total reserved 786432K, committed 786432K, used 688466K [0x00000007d0000000, 0x0000000800000000)
 region size 1024K, 108 young (110592K), 13 survivors (13312K)

整堆占用从 421 MiB 涨到 672 MiB，年轻代反而从 301 个 region 缩到 108 个。年轻代变小、总量变大，多出来的都在老年代。

GC.class_histogram

两点各打一次直方图（只保留前几行，[B 是 byte[]）：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
$ jcmd 79042 GC.class_histogram      # t=+25s
 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:         21028      150881784  [B (java.base@25)
   2:            13        1930512  [J (java.base@25)
   3:         19301         463224  java.lang.String (java.base@25)
   4:          2514         327600  java.lang.Class (java.base@25)
   5:            67         291056  [Ljava.util.concurrent.ConcurrentHashMap$Node; (java.base@25)
   6:          2866         236768  [Ljava.lang.Object; (java.base@25)
   7:          6038         193216  java.util.HashMap$Node (java.base@25)
...
Total         92005      155892520

$ jcmd 79042 GC.class_histogram      # t=+62s
 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:         23014      410968392  [B (java.base@25)
   2:            13        1930512  [J (java.base@25)
   3:         20295         487080  java.lang.String (java.base@25)
   4:          2481         323600  java.lang.Class (java.base@25)
   5:            67         291056  [Ljava.util.concurrent.ConcurrentHashMap$Node; (java.base@25)
   6:          2866         236768  [Ljava.lang.Object; (java.base@25)
   7:          7030         224960  java.util.HashMap$Node (java.base@25)
...
Total         95937      416035984

两次相隔 37 秒。[B 从 21028 个 / 150881784 字节变成 23014 个 / 410968392 字节，增量是 1986 个实例、260086608 字节，也就是 248 MiB / 37s ≈ 6.7 MB/s。第二步从 GC 日志估出来的 8 MiB/s 和这里 6.7 MB/s 是同一个量级，两个独立手段互相印证。

Total 行：第一次 155892520 字节、第二次 416035984 字节。这个数只有 156 MB 和 416 MB，比 GC.heap_info 的 421 MiB / 672 MiB 小一截。原因是 GC.class_histogram 不带参数时会先做一次 Full GC，统计的是 GC 之后仍然活着的对象。所以直方图的数字是”存活”，heap_info 的数字是”当前占用（含垃圾）”，两者不要混着比。

上面那段 GC 日志里 Pause Full (Heap Inspection Initiated GC) 就是这里产生的。生产环境上频繁打 GC.class_histogram 会自己制造 Full GC，别设成定时任务。

VM.native_memory

这个命令需要 JVM 启动时加 -XX:NativeMemoryTracking=summary（或 detail），否则打不出来。本次诊断的 JVM 是带这个参数起的：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
$ jcmd 79042 VM.native_memory summary
79042:

Native Memory Tracking:

(Omitting categories weighting less than 1KB)

Total: reserved=2316491KB, committed=903419KB
       malloc: 41931KB #38231, peak=53260KB #34712
       mmap:   reserved=2274560KB, committed=861488KB

-                 Java Heap (reserved=786432KB, committed=786432KB)
                            (mmap: reserved=786432KB, committed=786432KB, at peak)

-                     Class (reserved=1048729KB, committed=601KB)
                            (classes #2178)
                            (  instance classes #1928, array classes #250)
                            (malloc=153KB tag=Class #3254) (at peak)
                            (mmap: reserved=1048576KB, committed=448KB, at peak)
                            (  Metadata:   )
                            (    reserved=65536KB, committed=4288KB)
                            (    used=4207KB)
                            (    waste=81KB =1.89%)
                            (  Class space:)
                            (    reserved=1048576KB, committed=448KB)
                            (    used=390KB)
                            (    waste=58KB =12.86%)

-                    Thread (reserved=59686KB, committed=374KB)
                            (threads #30)
                            (stack: reserved=59600KB, committed=288KB, peak=288KB)
                            (malloc=54KB tag=Thread #180) (peak=62KB #184)
                            (arena=33KB #56) (peak=145KB #28)

-                      Code (reserved=251146KB, committed=9210KB)
                            (malloc=1513KB tag=Code #9037) (at peak)
                            (mmap: reserved=249632KB, committed=7696KB, at peak)
                            (arena=1KB #1) (peak=34KB #2)

-                        GC (reserved=67531KB, committed=67531KB)
                            (malloc=19195KB tag=GC #4941) (peak=19255KB #5023)
                            (mmap: reserved=48336KB, committed=48336KB, at peak)
                            (arena=0KB #0) (peak=9KB #9)
-                  Internal (reserved=1425KB, committed=1425KB)
-                    Symbol (reserved=1392KB, committed=1392KB)
-        Shared class space (reserved=16384KB, committed=13936KB, readonly=0KB)

读这张表要看 committed 而不是 reserved。reserved 是虚拟地址空间的保留量，Class 那一行的 reserved=1048729KB 差不多是 1 GB，但 committed 只有 601 KB。这是压缩类空间预留的地址区间，跟实际占用的物理内存没关系，看到 1 GB 就以为元空间吃了 1 GB 是常见误读。

committed=903419KB 里，Java Heap 占 786432 KB，是绝对大头。这也是”排查内存问题先看堆”的理由：如果堆本身没满，剩下的 native 部分通常只有几十到几百 MB，量级完全不同。

JFR

JFR 是 JDK 自带的低开销录制器，jcmd 也能直接开：

1
-XX:StartFlightRecording=name=diag,settings=profile,filename=dumps/diag.jfr

也可以运行中再开：jcmd <pid> JFR.start。录完用 jfr view 出视图。JDK 25 上跟内存相关的视图，用 jfr view 直接列得出来的有 memory-leaks-by-class、memory-leaks-by-site、object-statistics、allocation-by-class、allocation-by-site、gc、gc-pauses、heap-configuration、native-memory-committed 这些。

泄漏视图靠 jdk.OldObjectSample 事件，它采样那些在老年代里活过一段时间的对象，并记录分配时的调用栈。在 JDK 自带的工具里，能给出”这片内存是谁分配的”这种带调用栈答案的只有它，GC.class_histogram 只能到类这一层。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
$ jfr view memory-leaks-by-class dumps/diag.jfr

                        Memory Leak Candidates by Class

Alloc. Time Object Class                                  Object Age Heap Usage
----------- --------------------------------------------- ---------- ----------
17:05:43    byte[]                                            925 ms   582.3 MB

$ jfr view memory-leaks-by-site dumps/diag.jfr

                         Memory Leak Candidates by Site

Alloc. Time Application Method                            Object Age Heap Usage
----------- --------------------------------------------- ---------- ----------
17:05:43    LeakDemo.main(String[])                           925 ms   582.3 MB

两行结论：泄漏的是 byte[]，总量 582.3 MB，分配点在 LeakDemo.main(String[])。这两条信息足够回答「哪个类在涨、在哪分配」；要追引用链和 retained size 还得靠堆 dump。JFR 的开销本文没有单独测，是否常开按自己服务的预算定。

jfr view gc 能看到 GC 事件的逐条明细，最后几行是这样的：

1
2
3
4
5
6
7
8
9
$ jfr view gc dumps/diag.jfr
17:05:43   384 Old Garbage Collection         583.0 MB      582.5 MB       6.19 ms
17:05:43   385 Old Garbage Collection         582.5 MB      582.5 MB       5.09 ms
17:05:44   386 Young Garbage Collection       582.5 MB      582.5 MB      0.909 ms
17:05:44   387 Old Garbage Collection         582.5 MB      565.5 MB           0 s
17:05:44   388 Old Garbage Collection         582.5 MB      582.5 MB       6.98 ms
17:05:44   389 Old Garbage Collection         582.5 MB      582.5 MB       6.39 ms
17:05:44   390 Young Garbage Collection       582.5 MB      582.5 MB       0.588 ms
17:05:44   391 Old Garbage Collection         582.5 MB      565.5 MB       25.3 ms

跟 GC 日志是同一件事的另一种呈现，好处是可以按事件类型和字段排序、过滤，不用写正则去啃文本日志。

第四步：堆 dump

导出

三种方式：

1
2
3
4
5
6
7
8
# 运行中手动导
jcmd <pid> GC.heap_dump /tmp/leak.hprof

# 压缩后导（gzip，本机实测 JDK 17 / 21 / 25 可用，JDK 11 报 Unknown argument）
jcmd <pid> GC.heap_dump -gz=1 /tmp/leak.hprof.gz

# OOM 时自动导
java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/leak-oom.hprof ...

本次用的是第三种，OOM 时的输出：

1
2
3
4
5
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /private/tmp/jvmlab/dumps/diag-oom.hprof ...
Heap dump file created [614301411 bytes in 0.810 secs]
!! OutOfMemoryError
RESULT pid=79042 mode=leak outcome=OOM elapsedMs=90356 ops=35795 opsPerSec=396.2 windowSec=90 windowOps=35795 windowOpsPerSec=397.7 retiredMB=559 leakMBps=6.22 heapUsedMB=565 heapCommittedMB=768 allocP50us=17 allocP99us=164 allocMaxus=25235 allocOver10ms=10

这一轮是排查专用跑，参数与矩阵不同：--retainEvery=16（矩阵是 8）、-Xmx768m、windowSec=600，因此净保留是 400 × 256 KiB ÷ 16 = 6.22 MiB/s，只有矩阵轮的一半。第 2 到第 4 步的 GC 日志、直方图与堆 dump 都来自这一轮。

768 MiB 的堆写出了 586 MiB 的文件，耗时 0.81 秒。dump 期间 JVM 是停住的（GC.heap_dump 会触发一次 Full GC 然后暂停所有线程），这个 0.81 秒会全额落在请求延迟上。生产上导出堆 dump 之前先确认能不能接受这个停顿。

没有 MAT 怎么分析

jhat 在 JDK 9 就被移除了，JDK 25 的 bin 目录里已经没有它（jmap 还在，但通常用 jcmd 的同名功能代替）。JDK 自带的工具链里没有一个能打开 hprof 文件的命令行工具。常见的说法是”装个 MAT 就行”，但很多线上机器不让装东西，dump 文件又不好随便往外传（里面有全部业务数据，别传在线分析网站）。

可行的路子有两条。

第一条是在进程还活着的时候问，用 jcmd GC.class_histogram 做两点对比。这个上面已经做过，拿到的是”哪一类在涨”，对这个例子足够了。

第二条是把 hprof 当成普通二进制文件自己读。hprof 格式很直白，规范就写在 HotSpot 源码 src/hotspot/share/services/heapDumper.cpp 的文件头注释里。文件结构是：

1
2
3
4
5
6
7
8
9
10
header    "JAVA PROFILE 1.0.2"（0 结尾）
u4        id 宽度（跟宿主指针一样宽，64 位机器上就是 8）
u4 u4     时间戳（高 32 位 + 低 32 位，毫秒）
[record]* 一串记录

record:
u1        tag
u4        相对时间戳的微秒数
u4        记录体剩余字节数
[u1]*     记录体

常用 tag 和它们的记录体：

tag 名字 记录体
0x01 HPROF_UTF8 id 字符串标识 + UTF8 字节
0x02 HPROF_LOAD_CLASS u4 类序号 + id 类对象 + u4 栈序号 + id 类名
0x0C / 0x1C HEAP_DUMP / HEAP_DUMP_SEGMENT 一串子记录
0x2C HPROF_HEAP_DUMP_END 空
0x20 CLASS_DUMP 类元数据（含静态/实例字段表）
0x21 INSTANCE_DUMP id 对象 + u4 栈序号 + id 类对象 + u4 字节数 + 字段
0x22 OBJ_ARRAY_DUMP id 对象 + u4 栈序号 + u4 元素数 + id 数组类 + 元素
0x23 PRIM_ARRAY_DUMP id 对象 + u4 栈序号 + u4 元素数 + u1 类型 + 数据

根记录的 tag 是 0x01 到 0x08 和 0xFF，各自定长。下表里的”尾巴”是 id 之后还要读的字段：

tag 名字 尾巴
0x01 ROOT_JNI_GLOBAL id
0x02 ROOT_JNI_LOCAL u4 + u4
0x03 ROOT_JAVA_FRAME u4 + u4
0x04 ROOT_NATIVE_STACK u4
0x05 ROOT_STICKY_CLASS 无
0x06 ROOT_THREAD_BLOCK u4
0x07 ROOT_MONITOR_USED 无
0x08 ROOT_THREAD_OBJ u4 + u4
0xFF ROOT_UNKNOWN 无

坑在这里：这些 tag 的编号跟网上不少资料（包括一些老版本的 hprof 规范文档）对不上。常见的老文档写的是 0x01 = ROOT_UNKNOWN、0x02 = JNI_GLOBAL，跟 HotSpot 实际写出来的差一位。对着老表写解析器，头几十 KB 能解对，之后开始飘，最后在某个陌生的 tag 上崩掉。以 heapDumper.cpp 里的 enum hprofTag 为准。

下面这个 100 多行的 Python 解析器就是按这张表写的，只做浅大小直方图和最大单体对象，不做引用遍历。跑一遍 586 MiB 的 dump：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
$ python3 hprof_histo.py diag-oom.hprof 8
GC 根 2084 个，存活实例 92072 个，浅大小合计 580.8 MB

 instances   shallowBytes  shallowMB  class
     24151      604253477      576.3  [B
        15        1940320        1.9  [J
        64         579584        0.6  [Ljava/util/concurrent/ConcurrentHashMap$Node;
      2922         370408        0.4  [Ljava/lang/Object;
     20818         291452        0.3  java/lang/String
      1426         218864        0.2  [Ljava/util/HashMap$Node;
      6471         181188        0.2  java/util/HashMap$Node
      2579         113476        0.1  java/util/LinkedHashMap$Entry

[B 的实例大小分布（前 5 档）：
      2397 个             5 字节  (合计 0.0 MB)
      2331 个             6 字节  (合计 0.0 MB)
      2238 个        262144 字节  (合计 559.5 MB)
      1088 个             4 字节  (合计 0.0 MB)
       896 个             3 字节  (合计 0.0 MB)

最大的单个对象：
    16777216    16.00 MB  prim array byte len=16777216   [B
     1928192     1.84 MB  prim array long len=241024     [J
      524288     0.50 MB  obj array len=65536            [Ljava/util/concurrent/ConcurrentHashMap$Node;
      262144     0.25 MB  prim array byte len=262144     [B
      ...

整个文件 0.4 秒读完。结论很干净：

  • 存活对象 92072 个，浅大小合计 580.8 MB，跟 OOM 前最后一次打印的 heapUsedMB=565 是同一量级（差 2.8%，两次读数之间还能再漏一会儿）。
  • byte[] 24151 个，合计 576.3 MB，占了整堆的 99%。
  • 按大小分档，其中 2238 个正好是 262144 字节（256 KiB），加起来 559.5 MB。这个 262144 就是 payloadKB=256，2238 × 256 KiB = 559.5 MB，跟程序自己报的 retiredMB=559 完全一致。
  • 顺手还能看出实验程序自身的对象：16 MiB 的 byte[] 是 OOM 前预留的紧急缓冲，1928192 字节的 long[241024] 是分配延迟采样数组。

这个例子里最大的对象是 16 MiB 的紧急缓冲，不是泄漏本体。只看”最大单个对象”会被它带偏，按类的浅大小合计才是对的入口。

能力边界

自己写的解析器能回答：某个类有多少个实例、一共占多少字节、最大的单个对象多大。

它回答不了：这些对象是被谁引用的、如果把这个引用切断能释放多少。后者需要从 GC 根出发做引用遍历，算支配树（dominator tree）和 retained size，是 MAT 的核心功能，写起来是另一个量级的工程。这个例子里不需要，因为两千多个 256 KiB 的 byte[] 已经足够指认目标，但真实业务里对象图往往是多个类互相缠绕，”谁持有谁”才是关键，那时候该上 MAT。

MAT 在本地跑就行，用不着联网。dump 文件里有完整的业务数据（用户 ID、订单号、请求体全在里面），不要传到任何在线分析服务上去。

jhsdb 在 macOS 上的坑

JDK 还带了一个 jhsdb，可以像 gdb 一样挂到 JVM 上：

1
2
3
4
$ jhsdb jmap --histo --pid 96561
Attaching to process ID 96561, please wait...
ERROR: attach: task_for_pid(96561) failed: '(os/kern) failure' (5)
Error attaching to process: Can't attach to the process. Could be caused by an incorrect pid or lack of privileges.

第一反应是权限不够，加 sudo 再试：

1
2
3
4
$ sudo jhsdb jmap --histo --pid 96561
Attaching to process ID 96561, please wait...
ERROR: attach: task_for_pid(96561) failed: '(os/kern) failure' (5)
Error attaching to process: Can't attach to the process. Could be caused by an incorrect pid or lack of privileges.

root 也一样失败。 jhsdb 在 macOS 上走 task_for_pid 拿目标进程的 task port，而 macOS 从 10.7 起对这条路径有硬性要求：目标进程必须带 get-task-allow 这个 entitlement，否则谁都拿不到，root 也不例外。JDK 发行版里的 java 是签过名的，但没有这个 entitlement，所以从它启动的 JVM 一律不可 attach。

结论是：macOS 上不要指望 jhsdb，用 jcmd。jcmd 走的是 JVM 自己实现的 attach 机制（一个文件系统的 socket，加上目标进程内线程执行），全程不碰 task_for_pid，普通用户权限下就能用。本次实验里所有 jcmd 调用都是这么跑的。

Linux 上 jhsdb 没有这层限制，jhsdb jmap --histo --pid <pid> 能拿到跟 jcmd GC.class_histogram 类似的结果。这条路径本次未验证，因为机器是 macOS。

第五步：修与验证

改法

leak 模式和 bounded 模式只差 Sink 的实现。上面已经贴过 BoundedSink，用的是 LinkedHashMap 加访问顺序，超限从最旧开始淘汰，按字节数封顶 64 MiB。

这里没用 WeakReference。WeakReference 适合”键的生命周期由别处决定，这里只做缓存”的场景（WeakHashMap 就是干这个的），但这个例子的语义是”最近用过的数据要留住”，弱引用会让 GC 一来就把缓存清空，命中率掉到接近零。有界 LRU 才是对的形状。

复测

三个模式各跑 3 次，-Xms512m -Xmx512m，同样的 400 次/秒、256 KiB、每 8 次留 1 次：

指标 泄漏版（无界静态 Map） 修复版（有界 LRU 64 MiB） 不保留（基线）
结束状态 3/3 次 OutOfMemoryError 3/3 次正常结束 3/3 次正常结束
存活时长 29.6 / 29.6 / 29.5 s 60 s 60 s
完成迭代 11826 / 11825 / 11809 24000 / 24000 / 24000 24000 / 24000 / 24000
结束堆占用 372 MiB 194 / 252 / 306 MiB 172 / 171 / 172 MiB
GC 事件数 241 / 233 / 243 53 / 53 / 53 27 / 27 / 27
Pause Full 26 / 25 / 25 0 / 0 / 0 0 / 0 / 0
累计暂停 396.1 / 464.2 / 375.8 ms 130.5 / 134.1 / 119.5 ms 32.8 / 28.3 / 29.9 ms
暂停时间占比 1.34% / 1.57% / 1.27% 0.22% / 0.23% / 0.20% 0.06% / 0.05% / 0.05%
分配延迟 p50 9 / 9 / 9 µs 9 / 9 / 9 µs 10 / 9 / 10 µs
分配延迟 p99 785 / 781 / 765 µs 64 / 58 / 59 µs 89 / 62 / 56 µs
分配 >10 ms 次数 4 / 4 / 3 1 / 2 / 1 0 / 0 / 0

几个点：

暂停时间占比那一行是归一化后的指标，泄漏版 396.1 ms / 29.6 s = 1.34%，修复版 130.5 ms / 60 s = 0.22%，差 6 倍。这是把不同时长的运行放在一起比的办法。

Pause Full 从 25 到 26 次变成 0 次，是这张表里最有辨识度的一行。G1 只有在并发周期收拾不干净的时候才会退到 Full GC，一旦出现并且频繁出现，基本可以断定老年代里有东西长期不死。

分配延迟 p99 从 780 微秒掉到 60 微秒，跟基线一个水平，说明修复版没有留下新的分配路径开销。

修复版的堆占用在第 3 次跑到了 306 MiB，比前两次高。这不是泄漏（60 秒固定时长跑完正常结束，且没有 Full GC），是 G1 在 512 MiB 堆上没有及时做并发周期收集，浮动空间留得比较大。真要压这个数字，可以把 -XX:InitiatingHeapOccupancyPercent 调低，代价是并发标记更频繁。

第六步：G1 还是 ZGC

同一个修复版程序，去掉限速（--rate=0）跑满，-Xms1g -Xmx1g，30 秒一档各 3 次，开 JFR 录制，暂停用 jfr view gc-pauses 统计。

指标 G1 ZGC（分代，JDK 25 默认）
完成迭代 5273602 / 5406776 / 5581737 3489912 / 3469866 / 3484521
吞吐 175787 / 180226 / 186058 ops/s 116330 / 115658 / 116151 ops/s
暂停总时长 8.88 / 8.86 / 8.87 s 125 / 124 / 119 ms
暂停次数 4295 / 4424 / 4553 17360 / 17182 / 17374
中位暂停 2.35 / 2.32 / 2.31 ms 0.00667 / 0.00667 / 0.00621 ms
P99 暂停 5.07 / 3.68 / 3.42 ms 0.0260 / 0.0249 / 0.0242 ms
最大暂停 23.8 / 156 / 12.3 ms 0.194 / 0.339 / 0.293 ms

ZGC 的暂停总时长是 G1 的 1/71（125 ms 对 8.88 s）。jfr view gc-pauses 的完整输出：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
$ jfr view gc-pauses dumps/flatout-zgc-rep1.jfr

GC Pauses
---------

Total Pause Time: 125 ms

Number of Pauses: 17,360

Minimum Pause Time: 0.00138 ms

Median Pause Time: 0.00667 ms

Average Pause Time: 0.00717 ms

P90 Pause Time: 0.0114 ms

P95 Pause Time: 0.0132 ms

P99 Pause Time: 0.0260 ms

P99.9% Pause Time: 0.0503 ms

Maximum Pause Time: 0.194 ms

同一份负载在 G1 下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
$ jfr view gc-pauses dumps/flatout-g1-rep1.jfr

GC Pauses
---------

Total Pause Time: 8.88 s

Number of Pauses: 4,295

Minimum Pause Time: 0.0157 ms

Median Pause Time: 2.35 ms

Average Pause Time: 2.07 ms

P90 Pause Time: 2.81 ms

P95 Pause Time: 3.07 ms

P99 Pause Time: 5.07 ms

P99.9% Pause Time: 16.9 ms

Maximum Pause Time: 23.8 ms

G1 在 30 秒里停了 8.88 秒，占 29.6% 的时间；ZGC 停了 125 毫秒，占 0.4%。中位暂停差 350 倍；最坏情况 23.8 毫秒对 0.194 毫秒，差两个数量级。

但吞吐反过来：G1 每秒 18 万次迭代，ZGC 每秒 11.6 万次，ZGC 慢了 36%。这个负载是单线程死命分配的极端形状，256 KiB 的数组瞬间变垃圾，ZGC 的并发标记线程要和业务线程抢 CPU 和内存带宽，抢不过。

两边合起来就是选择依据：

用 ZGC 的场合：有明确的暂停时间上限。比如 p99 必须压在 10 毫秒以内，或者同一台机器上还跑着别的服务，不能被别人的 GC 停顿带着一起抖。代价是多花 CPU 和内存带宽，换的是可预测性。

用 G1 的场合：吞吐优先，或者堆不大（几个 GB 以内）。JDK 9 之后 G1 就是默认 GC，绝大多数业务系统不需要动它。

换 GC 不能解决的情况：症状不是 GC 引起的时候。本文开头那个泄漏程序在 G1 下的暂停占比是 1.3%，把 GC 换成 ZGC 能把停顿抹平，但泄漏一秒没少漏，OOM 照样来，排查时反而少了一个明显的告警信号。先确认是”GC 停顿长”还是”内存本身在涨”，再决定要不要动 GC 参数。

关于版本：JDK 21 上 -XX:+UseZGC 默认还是非分代的，要加 -XX:+ZGenerational 才拿到分代模式。JEP 474 在 JDK 23 把分代改成默认，JEP 490 在 JDK 24 直接移除了非分代实现，ZGenerational 选项在 JDK 24 起是 obsolete，传了会打警告但不再改变行为。所以 JDK 25 上的 -XX:+UseZGC 只有一个含义。

两个常见误判

堆几乎是空的，却 OOM

场景一：元空间。MetaLeak 用编译器 API 不断生成并加载新类，堆上限 256 MiB，元空间上限 32 MiB：

1
2
3
4
$ java -Xmx256m -XX:MaxMetaspaceSize=32m -cp classes MetaLeak --classes=40000 --methods=24 --batch=400
@classes=2000 elapsedMs=1438 metaspaceUsedKB=21845 heapUsedMB=20
!! java.lang.OutOfMemoryError: Metaspace
RESULT outcome=OOM:Metaspace classes=3973 metaspaceUsedKB=32442 heapUsedMB=4

OOM 的时候堆只用了 4 MB，元空间用满 32 MB。这类 OOM 的消息是 Metaspace 或者 Compressed class space，跟 Java heap space 完全不是一回事。元空间默认没有上限（受进程可用内存限制），线上一般会配 -XX:MaxMetaspaceSize 兜底。真出问题的时候多半是热部署反复加载同一个类、或者动态代理 / CGLIB 生成类没有上限，jcmd <pid> VM.metaspace 能按类加载器维度看分布：

1
2
3
4
5
6
7
8
9
$ jcmd 93616 VM.metaspace
93616:
Metaspace        used 15138K, committed 15360K, reserved 98304K
 class space     used 1485K, committed 1600K, reserved 32768K

Total Usage - 39 loaders, 3526 classes (1135 shared):
  Non-Class:  466 chunks,     15.69 MB capacity,   13.44 MB ( 86%) committed,    13.33 MB ( 85%) used,   107.76 KB ( <1%) free,     0 bytes (  0%) waste , deallocated: 38 blocks with 8.77 KB
      Class:  119 chunks,      1.64 MB capacity,    1.52 MB ( 92%) committed,     1.45 MB ( 88%) used,    66.13 KB (  4%) free,     0 bytes (  0%) waste , deallocated: 0 blocks with 0 bytes
       Both:  585 chunks,     17.33 MB capacity,   14.95 MB ( 86%) committed,    14.78 MB ( 85%) used,   173.89 KB ( <1%) free,     0 bytes (  0%) waste , deallocated: 38 blocks with 8.77 KB

39 loaders, 3526 classes 是这里的核心：泄漏的话，类加载器数量和类数量会单调上涨，而且卸载不掉（每个生成的类都被强引用着）。正常应用里这两个数在启动完成后就稳定了。

场景二：直接内存。DirectLeak 反复 ByteBuffer.allocateDirect(8 MiB)，堆上限 256 MiB，直接内存上限 64 MiB：

1
2
3
4
5
$ java -Xmx256m -XX:MaxDirectMemorySize=64m -cp classes DirectLeak
@buffers=4 directReservedMB=32 heapUsedMB=2 elapsedMs=15
@buffers=8 directReservedMB=64 heapUsedMB=3 elapsedMs=32
!! java.lang.OutOfMemoryError: Cannot reserve 8388608 bytes of direct buffer memory (allocated: 67108864, limit: 67108864)
RESULT outcome=done buffers=8 directMB=64 heapUsedMB=1 elapsedMs=575

堆用了 1 MB。ByteBuffer.allocateDirect 分配的内存在 JVM 堆之外，不计入 -Xmx，也不被 GC 日志的堆用量统计，但它受 -XX:MaxDirectMemorySize 限制。NIO / Netty / gRPC 这类框架的缓冲区大多在这块内存里，堆 dump 看不到它们，得靠 jcmd <pid> VM.native_memory summary 里的 Internal 或者 NMT 的 detail 级别来看。

-XX:MaxDirectMemorySize 不设的时候，java 手册里的原话是”If not set, the flag is ignored and the JVM chooses the size for NIO direct-buffer allocations automatically”，默认值取决于运行时判断。-XX:+PrintFlagsFinal 打出来是这样：

1
2
3
$ java -XX:+PrintFlagsFinal -version 2>&1 | grep -i "MaxDirectMemorySize\|MaxHeapSize"
   uint64_t MaxDirectMemorySize                      = 0                                         {product} {default}
     size_t MaxHeapSize                              = 4294967296                                {product} {ergonomic}

MaxDirectMemorySize 显示 0，意思是”没有显式上限，由 JVM 自己定”，并不等于 MaxHeapSize。想控住就得显式配，不要靠推算。

两个场景的共同点：-Xmx 只管 Java 堆。看到 OOM 先去确认异常消息是哪个 pool，再看对应的上限，不然容易在堆上白找半天。

老年代没压力，却一直 Full GC

GcCall 每 5 轮调一次 System.gc()，其余时间只分配很小的对象：

1
2
3
4
5
6
7
$ java -Xms256m -Xmx256m -Xlog:gc:file=gcon.log:time,uptime,level,tags -cp classes GcCall --gc=on --rounds=20
RESULT explicitGc=true rounds=20 retainedMB=40 heapUsedMB=82
--- GC 日志里的 Pause 行:
[2026-09-15T17:17:10.052+0800][0.198s][info][gc] GC(0) Pause Full (System.gc()) 12M->10M(256M) 2.571ms
[2026-09-15T17:17:10.832+0800][0.978s][info][gc] GC(1) Pause Full (System.gc()) 56M->28M(256M) 1.761ms
[2026-09-15T17:17:11.602+0800][1.748s][info][gc] GC(2) Pause Full (System.gc()) 74M->37M(256M) 1.547ms
[2026-09-15T17:17:12.371+0800][2.517s][info][gc] GC(3) Pause Full (System.gc()) 83M->46M(256M) 1.513ms

4 次调用，4 次 Pause Full (System.gc())。堆才用了 83 MiB，离 256 MiB 上限远得很。

如果只看监控大盘上的”Full GC 次数”曲线，这看起来像是老年代有严重压力。但 GC 日志括号里写着 System.gc()，它跟 G1 Compaction Pause（G1 自己的决定）和 Metadata GC Threshold（元空间触发）是三种完全不同的原因。先看括号再下结论。

加上 -XX:+DisableExplicitGC，同一个程序、同样的 4 次调用，20 轮里只有 1 次 Pause，还是 young：

1
2
3
4
$ java -Xms256m -Xmx256m -XX:+DisableExplicitGC -Xlog:gc:file=gcoff.log:time,uptime,level,tags -cp classes GcCall --gc=on --rounds=20
RESULT explicitGc=true rounds=20 retainedMB=40 heapUsedMB=100
--- GC 日志里的 Pause 行:
[2026-09-15T17:17:14.955+0800][1.892s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 111M->28M(256M) 0.910ms

-XX:+DisableExplicitGC 把 System.gc() 变成一个空调用，JVM 该回收的时候照样回收（那次 Young GC 是 8 MiB 的大对象走 humongous 路径触发的）。

加这个参数之前先搞清楚 System.gc() 是谁调的。它的常见来源不只业务代码，第三方库和 JDK 内部组件都可能在特定路径上调到。关掉显式 GC 相当于把决定权全部交给 G1 的自适应策略，在堆比较紧的服务上反而可能让 Full GC 来得更突然。

找调用方靠 JFR 的 jdk.SystemGC 事件，它带调用栈：

1
2
3
4
5
6
7
8
9
$ jfr view jdk.SystemGC dumps/sysgc.jfr

                                    System GC

Start Time Duration Event Thread    Stack Trace               Invoked Concurrent
---------- -------- --------------- ------------------------- ------------------
17:20:36    6.36 ms main            java.lang.Runtime.gc()                 false
17:20:37    4.71 ms main            java.lang.Runtime.gc()                 false
17:20:38    3.87 ms main            java.lang.Runtime.gc()                 false

Duration 就是这一次 System.gc() 造成的停顿，Stack Trace 是调用点。真实业务里的调用点通常不在自己的代码里，顺着这个栈往回找比全仓库搜 System.gc 快得多。

另一种更隐蔽的情况是 -XX:+ExplicitGCInvokesConcurrent。这个参数让 System.gc() 走并发回收而不是 Full GC，java 手册里写明只能跟 -XX:+UseG1GC 一起用。同一个程序加上它之后：

1
2
3
4
5
6
7
8
9
10
11
12
$ java -Xms256m -Xmx256m -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent \
    -Xlog:gc:file=gcconc.log:time,uptime,level,tags -cp classes GcCall --gc=on --rounds=20
RESULT explicitGc=true rounds=20 retainedMB=40 heapUsedMB=82
--- Pause Full 的次数:
0
--- 原来的 Full GC 变成了:
[2026-09-15T17:19:33.714+0800][0.212s][info][gc] GC(1) Concurrent Mark Cycle
[2026-09-15T17:19:33.715+0800][info][gc] GC(1) Pause Remark 10M->10M(256M) 0.289ms
[2026-09-15T17:19:33.716+0800][info][gc] GC(1) Pause Cleanup 10M->10M(256M) 0.005ms
[2026-09-15T17:19:34.490+0800][0.989s][info][gc] GC(3) Concurrent Mark Cycle
[2026-09-15T17:19:34.492+0800][info][gc] GC(3) Pause Remark 28M->28M(256M) 0.241ms
[2026-09-15T17:19:34.492+0800][info][gc] GC(3) Pause Cleanup 28M->28M(256M) 0.013ms

Pause Full 从 4 次变成 0 次，剩下的是并发周期里的两次短停顿。监控大盘上”Full GC 次数”会归零，但停顿时长只是从毫秒级变成几百微秒，总暂停并没有消失，Pause Remark 和 Pause Cleanup 还在那里。这个参数适合的场景是”代码里有无法立刻去掉的 System.gc()，又不想吃 Full GC 的停顿”，不适合拿来把监控曲线刷平。

小结工具链

按从粗到细排：

  1. -Xlog:gc*:file=...:time,uptime,level,tags，看老年代增长趋势和 Full GC 的触发原因，开销很低，生产常开。
  2. jcmd <pid> GC.heap_info，看当前占用和分代切片，不触发 GC。
  3. jcmd <pid> GC.class_histogram，做两点对比看哪一类在涨，它会触发一次 Full GC。
  4. jcmd <pid> VM.native_memory summary，看堆之外的 native 用量，需要启动时加 -XX:NativeMemoryTracking。
  5. JFR 加 jfr view memory-leaks-by-class / memory-leaks-by-site，直接给出泄漏的类和分配点。
  6. jcmd <pid> GC.heap_dump，最后一招，会停顿，且 dump 文件含敏感数据，本地分析。

本次实验里的命令在 JDK 25 上全部跑通（跨版本对比那几处另外用了 JDK 11 / 17 / 21）。唯一没跑通的是 jhsdb：macOS 上普通用户和 root 都报 task_for_pid 失败，它在 Linux 上是否可用本次未验证。

系列索引：Java 系列，语言特性与运行时的长文集