Concurrent Mark-Sweep Collector GC Log Message Format

JVM Tutorials - Herong's Tutorial Examples

∟Memory Management and Garbage Collectors

∟Concurrent Mark-Sweep Collector GC Log Message Format

This section provides examples of HotSpot Concurrent Mark-Sweep Collector (CMS) GC log messages.

As a comparison, here is an example of log messages generated by the Concurrent Mark-Sweep Collector:

C:\>\progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m 
   -XX:+UseConcMarkSweepGC
   -XX:+PrintGCDetails GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:

   [GC (Allocation Failure) 
      [ParNew: 649K->64K(960K), 0.0023484 secs] 
      649K->511K(1984K), 
      0.0025041 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

1   2031616   691704   1339912

   [GC (Allocation Failure) 
      [ParNew: 861K->64K(960K), 0.0393917 secs] 
      1308K->1304K(2500K), 
      0.0395898 secs] 
   [Times: user=0.05 sys=0.00, real=0.04 secs] 

   [GC (CMS Initial Mark) 
      [1 CMS-initial-mark: 1240K(1540K)] 
      1560K(2500K), 
      0.0002852 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
   
   [CMS-concurrent-mark-start]
   
   [GC (Allocation Failure) 
      [ParNew: 904K->0K(960K), 0.0009065 secs] 
      2145K->2127K(3280K), 
      0.0010593 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

2   3555328   1156320   2399008

   [CMS-concurrent-mark: 0.002/0.003 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
   
   [CMS-concurrent-preclean-start]
   [CMS-concurrent-preclean: 0.000/0.000 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

   [GC (CMS Final Remark) 
      [YG occupancy: 215 K (1152 K)]
      [Rescan (parallel) , 0.0004463 secs]
      [weak refs processing, 0.0000140 secs]
      [class unloading, 0.0001668 secs]
      [scrub symbol table, 0.0000990 secs]
      [scrub string table, 0.0000251 secs]
      [1 CMS-remark: 2127K(2320K)] 
      2342K(3472K), 
      0.0008695 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

   [CMS-concurrent-sweep-start]
   [CMS-concurrent-sweep: 0.000/0.000 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

   [CMS-concurrent-reset-start]
   [CMS-concurrent-reset: 0.000/0.000 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 
   
   [GC (Allocation Failure) 
      [ParNew: 1068K->63K(1152K), 0.0024959 secs] 
      3175K->3147K(4664K), 
      0.0026369 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

   [GC (CMS Initial Mark) 
      [1 CMS-initial-mark: 3083K(3512K)] 
      3269K(4664K), 
      0.0010725 secs] 
   [Times: user=0.00 sys=0.00, real=0.00 secs] 

   [CMS-concurrent-mark-start]

3   4775936   1339096   3436840

...

Heap
 par new generation   total 1152K, used 317K [0x03e00000, 0x03f30...
  eden space 1088K,  23% used [0x03e00000, 0x03e3f710, 0x03f10000)
  from space 64K,  99% used [0x03f20000, 0x03f2fd90, 0x03f30000)
  to   space 64K,   0% used [0x03f10000, 0x03f10000, 0x03f20000)
 concurrent mark-sweep generation total 43712K, used 36412K [0x05...
 Metaspace used 45K, capacity 2242K, committed 2368K, reserved 4480K

With the help from this blog: Understanding CMS GC Logs, by Poonam Bajaj, here is how I read those extra log messages generated by the Concurrent Mark-Sweep (CMS) Collector:

"[GC (CMS Initial Mark) [1 CMS-initial-mark: 1240K(1540K)] 1560K(2500K), 0.0002852 secs]" - Indicating the completion of the initial marking phase. The initial marking phase is the first phase of the tenured generation collection with the CMS collector. In this phase, all the objects directly reachable from roots are marked. This is done with all the mutator threads stopped. "1240K(1540K)] 1560K(2500K)" tells me that total the Tenured Generation size was 1540K with 1240K used, and total heap size was 2500K with 1560K used.
"[CMS-concurrent-mark-start]" - Indicating the beginning of concurrent marking phase. In this concurrent marking phase, threads stopped in the first phase are started again and all the objects transitively reachable from the objects marked in first phase are marked here.
"[CMS-concurrent-mark: 0.002/0.003 secs]" - Indicating the end of concurrent marking phase. "0.002/0.003 secs" tells me that the concurrent marking phase took 0.002 seconds of CPU time and 0.003 seconds of elapsed time.
"[CMS-concurrent-preclean-start]" - Indicating the start of precleaning. Precleaning is also a concurrent phase. In this phase, The garbage collector looks at the objects in CMS heap which got updated by promotions from young generation or new allocations or got updated by mutators while it was doing the concurrent marking in the previous concurrent marking phase. By rescanning those objects concurrently, the precleaning phase helps reduce the work in the next stop-the-world "remark" phase.
"[CMS-concurrent-preclean: 0.000/0.000 secs]" - Indicating the end of precleaning. "0.000/0.000 secs" tells me that the precleaning phase took 0.000 seconds of CPU time and 0.000 seconds of elapsed time.
"[GC (CMS Final Remark) [YG occupancy: 215 K (1152 K)] [Rescan (parallel), 0.0004463 secs] [weak refs processing, 0.0000140 secs] [class unloading, 0.0001668 secs] [scrub symbol table, 0.0000990 secs] [scrub string table, 0.0000251 secs] [1 CMS-remark: 2127K(2320K)] 2342K(3472K), 0.0008695 secs]" - Indicating the completion of the remark phase, which is a stop-the-world phase. This phase rescans any residual updated objects in CMS heap, retraces from the roots and also processes Reference objects. The Young Generation has 1152K space with 215K used. The Rescan step took 0.0004463 seconds. The weak reference objects processing took 0.0000140 seconds. The class unloading step took 0.0000990 seconds. The symbol table scrubbing step (needed if classes were unloaded) took 0.0000990 seconds. The string table scrubbing step (needed if classes were unloaded) took 0.0000251 seconds. "2127K(2320K)] 2342K(3472K)" tells me that total the Tenured Generation size was 2320K with 2127K used, and total heap size was 3472K with 2342K used. The entire phase took 0.0008695 seconds.
"[CMS-concurrent-sweep-start]" - Indicating the start of the sweeping phase. This phase removes non-marked (dead) objects, and is performed concurrently with all other threads running.
"[CMS-concurrent-sweep: 0.000/0.000 secs]" - Indicating the end of the sweep phase. The sweeping phase took 0.000 seconds of CPU time and 0.000 elapsed time.
"[CMS-concurrent-reset-start]" - Indicating the start of the reset phase. In this phase, the CMS data structures are reinitialized so that a new cycle may begin at a later time.
"[CMS-concurrent-reset: 0.000/0.000 secs]" - Indicating the end of the reset phase. The reset phase took 0.000 seconds of CPU time and 0.000 elapsed time.

As you can see, the CMS GC gives us lots of information in the log. However, it does not clearly tell us how much memory was released. It would be nice if it can report the total size of objects removed in the sweeping phase.

Last update: 2015.

Table of Contents

About This Book

Downloading and Installing JDK 1.8.0 on Windows

Downloading and Installing JDK 1.7.0 on Windows

java.lang.Runtime Class - The JVM Instance

java.lang.System Class - The Operating System

ClassLoader Class - Class Loaders

Class Class - Class Reflections

Sun's JVM - Java HotSpot VM

JRockit JVM 28.2.7 by Oracle Corporation

JVM Runtime Data Areas