Concurrent Mark-Sweep Collector GC Log Message Format

Java GC Tutorials - Herong's Tutorial Examples

∟Concurrent Mark-Sweep (CMS) Collector - "+XX:+UseConcMarkSweepGC"

∟Concurrent Mark-Sweep Collector GC Log Message Format

This section describes the log message format of HotSpot JVM Concurrent Mark-Sweep (CMS) Collector.

Warning: the Concurrent Mark-Sweep (CMS) Collector has been removed from JVM 15. But if you still have JVM 14 or older installed, you can continue to use it.

Before doing any testing with the Concurrent Mark-Sweep (CMS) Collector, let's look at log messages generated by the Concurrent Mark-Sweep Collector first:

herong> java -Xms2m -Xmx64m -XX:+UseConcMarkSweepGC \ \
   -Xlog:gc,gc+heap=info GarbageCollection

Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was
deprecated in version 9.0 and will likely be removed in a future release.

[info][gc] Using Concurrent Mark Sweep
Step/TotalMemory/FreeMemory/UsedMemory:

[info][gc,heap] GC(0) ParNew: 987K->128K(1152K)
[info][gc,heap] GC(0) CMS: 0K->737K(1344K)

[info][gc] GC(0) Pause Young (Allocation Failure) 0M->0M(2M) 4.756ms

[info][gc] GC(1) Pause Initial Mark 1M->1M(2M) 0.442ms
[info][gc] GC(1) Concurrent Mark
[info][gc] GC(1) Concurrent Mark 1.446ms
[info][gc] GC(1) Concurrent Preclean
[info][gc] GC(1) Concurrent Preclean 0.039ms
[info][gc] GC(1) Pause Remark 1M->1M(2M) 0.799ms
[info][gc] GC(1) Concurrent Sweep
[info][gc] GC(1) Concurrent Sweep 0.159ms
[info][gc] GC(1) Concurrent Reset
[info][gc] GC(1) Concurrent Reset 0.244ms
[info][gc,heap] GC(1) Old: 737K->737K(1344K)

[info][gc,heap] GC(2) ParNew: 1152K->126K(1152K)
[info][gc,heap] GC(2) CMS: 737K->1658K(2056K)
[info][gc] GC(2) Pause Young (Allocation Failure) 1M->1M(3M) 1.440ms

[info][gc] GC(3) Pause Initial Mark 1M->1M(3M) 0.192ms
[info][gc] GC(3) Concurrent Mark
[info][gc] GC(3) Concurrent Mark 0.979ms
[info][gc] GC(3) Concurrent Preclean
[info][gc] GC(3) Concurrent Preclean 0.027ms
[info][gc] GC(3) Pause Remark 1M->1M(3M) 0.580ms
[info][gc] GC(3) Concurrent Sweep
[info][gc] GC(3) Concurrent Sweep 0.319ms
[info][gc] GC(3) Concurrent Reset
[info][gc] GC(3) Concurrent Reset 0.038ms
[info][gc,heap] GC(3) Old: 1658K->1656K(2764K)

1   2555904   826608   1729296
...

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:

"Pause Initial Mark 1M->1M(2M) 0.442ms" - 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 the application paused for 0.442ms.
"Concurrent Mark" - Indicating the beginning of concurrent marking phase. In this concurrent marking phase, the application is started again and all the objects transitively reachable from the objects marked in first phase are marked here.
"Concurrent Mark 1.446ms" - Indicating the end of concurrent marking phase and how long it took
"Concurrent Preclean" - 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.
"Concurrent Preclean 0.039ms" - Indicating the end of precleaning phase and how long it took.
"Pause Remark 1M->1M(2M) 0.799ms" - 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 Rescan step took 0.799ms.
"Concurrent Sweep" - Indicating the start of the sweeping phase. This phase removes non-marked (dead) objects, and is performed concurrently with all other threads running.
"Concurrent Sweep 0.159ms" - Indicating the end of the sweep phase and how long it took.
"Concurrent Reset]" - 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.
"Concurrent Reset 0.244ms" - Indicating the end of the reset phase and how long it took.
"Old: 737K->737K(1344K)" - Indicating the end of the CMS process on the Old (tenured) generation. and how much memory was released. Unfortunately, the CMS process did not release any memory. The Old generation heap usage changed from 737K to 737K.