Java CMS执行未回收对象及jmap命令异常问题咨询

问题背景 #

使用JDK 1.8.0_301创建了一个500M的char数组，JVM配置了-XX:CMSInitiatingOccupancyFraction=30以触发CMS GC，预期方法结束后CMS会回收该char数组，但实际未回收。

测试代码 #

public void add500m() throws Exception {
    StringBuilder sb = new StringBuilder(262144000);
    for (int i = 0; i < 262144000; i++) {
        sb.append("a");
    }
    System.out.println("finish");
}

JVM配置参数 #

-XX:+UseConcMarkSweepGC
-XX:CMSFullGCsBeforeCompaction=5
-XX:+UseCMSCompactAtFullCollection
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:CMSInitiatingOccupancyFraction=30
-XX:+UseCMSInitiatingOccupancyOnly
-Xloggc:jvm_local.log
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=heapdump.hprof
-Xms512m
-Xmn100m
-Xmx2048m

GC日志片段 #

2022-09-01T10:38:08.297+0800: 1691.109: [GC (CMS Initial Mark) [1 CMS-initial-mark: 512000K(933892K)] 559461K(1026052K), 0.0051052 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2022-09-01T10:38:08.302+0800: 1691.114: [CMS-concurrent-mark-start]
2022-09-01T10:38:08.303+0800: 1691.115: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:08.303+0800: 1691.115: [CMS-concurrent-preclean-start]
2022-09-01T10:38:08.304+0800: 1691.116: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:08.304+0800: 1691.116: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2022-09-01T10:38:13.364+0800: 1696.177: [CMS-concurrent-abortable-preclean: 0.574/5.061 secs] [Times: user=0.45 sys=0.00, real=5.06 secs] 
2022-09-01T10:38:13.365+0800: 1696.177: [GC (CMS Final Remark) [YG occupancy: 47461 K (92160 K)]2022-09-01T10:38:13.365+0800: 1696.177: [Rescan (parallel) , 0.0059510 secs]2022-09-01T10:38:13.371+0800: 1696.183: [weak refs processing, 0.0000202 secs]2022-09-01T10:38:13.371+0800: 1696.183: [class unloading, 0.0014238 secs]2022-09-01T10:38:13.372+0800: 1696.184: [scrub symbol table, 0.0008487 secs]2022-09-01T10:38:13.373+0800: 1696.185: [scrub string table, 0.0001447 secs][1 CMS-remark: 512000K(933892K)] 559461K(1026052K), 0.0088900 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-09-01T10:38:13.374+0800: 1696.186: [CMS-concurrent-sweep-start]
2022-09-01T10:38:13.374+0800: 1696.186: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:13.374+0800: 1696.186: [CMS-concurrent-reset-start]
2022-09-01T10:38:13.379+0800: 1696.191: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:15.393+0800: 1698.206: [GC (CMS Initial Mark) [1 CMS-initial-mark: 512000K(933892K)] 559461K(1026052K), 0.0049420 secs] [Times: user=0.20 sys=0.00, real=0.01 secs] 
2022-09-01T10:38:15.398+0800: 1698.211: [CMS-concurrent-mark-start]
2022-09-01T10:38:15.399+0800: 1698.211: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:15.399+0800: 1698.211: [CMS-concurrent-preclean-start]
2022-09-01T10:38:15.400+0800: 1698.212: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:15.400+0800: 1698.212: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2022-09-01T10:38:20.472+0800: 1703.284: [CMS-concurrent-abortable-preclean: 0.576/5.072 secs] [Times: user=0.59 sys=0.00, real=5.07 secs] 
2022-09-01T10:38:20.472+0800: 1703.284: [GC (CMS Final Remark) [YG occupancy: 47461 K (92160 K)]2022-09-01T10:38:20.472+0800: 1703.284: [Rescan (parallel) , 0.0069744 secs]2022-09-01T10:38:20.479+0800: 1703.291: [weak refs processing, 0.0000385 secs]2022-09-01T10:38:20.479+0800: 1703.291: [class unloading, 0.0022398 secs]2022-09-01T10:38:20.481+0800: 1703.294: [scrub symbol table, 0.0013527 secs]2022-09-01T10:38:20.483+0800: 1703.295: [scrub string table, 0.0002406 secs][1 CMS-remark: 512000K(933892K)] 559461K(1026052K), 0.0113743 secs] [Times: user=0.20 sys=0.00, real=0.01 secs] 
2022-09-01T10:38:20.483+0800: 1703.296: [CMS-concurrent-sweep-start]
2022-09-01T10:38:20.483+0800: 1703.296: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-09-01T10:38:20.483+0800: 1703.296: [CMS-concurrent-reset-start]
2022-09-01T10:38:20.489+0800: 1703.301: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

现象观察 #

• 通过JConsole或GC日志可见，该char数组位于老年代，CMS GC次数持续增加说明GC在执行，但每次都未回收任何内容（JConsole显示老年代大小未下降，CMS GC次数持续上升）。
• 在JConsole或VisualVM中点击“执行GC”触发Full GC（包含元空间GC）时，该char数组会被回收。
• 使用jmap -dump:format=b,file=heapdump.hprof生成堆转储文件，在VisualVM中发现该char数组无法从GC根节点到达。

疑问 #

1. 为什么CMS GC正常执行但未回收任何对象？
2. 为什么执行jmap -dump:live,format=b,file=heapdump-live.hprof命令有时不会触发Full GC？

内容的提问来源于stack exchange，提问作者Chiang