I created an char array of 500m with jdk 1.8.0_301. According to the configurations of JVM, -XX:CMSInitiatingOccupancyFraction=30(just to trigger CMS gc), CMS should reclaim the char array when the method finished,but actually not.
the code is below:
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 arguments is below:
-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
two gc log:
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]
From JConsole or gc log, we can see that the char array is in old generation, and the GC times of the CMS are continuously increasing, indicating that the CMS is working, but nothing reclaimed every time.
But when I click Perform GC in JConsole or VisualVM to trigger Full GC(Metaspace gc included), the char array is reclaimed.
I suspect the char array is referenced by somewhere else, for example metaspace, then I get the heapdump.hprof using jmap -dump:format=b,file=heapdump.hprof, and find that the char array can't be reachable from gc root(No gc root showed in VisualVM).
In short, why is CMS working but relaimed nothing?
And, I find another strange question: "jmap -dump:live,format=b,file=heapdump-live.hprof", the command don't trigger Full GC sometimes? Why?