Reduce Stop-The-World with Concurrent Mark and Sweep

This section demonstrates how CMS Collector reduces Stop-The-World duration by running parts of Mark and Sweep steps concurrently with the application.

The main advantage of using the Concurrent Mark-Sweep (CMS) Collector is that CMS performs Major GC without stopping the application, or no stop-the-world pauses to the application. But there seems to be no easy way to measure this in JVM 9 or higher releases. I could not find any "-Xlog" options to generate any log messages about when and for how long application gets stopped by the CMS Collector.

However if you are still using JVM 8 or older releases, you can confirm stop-the-world behavior of the CMS Collector with "-XX:+PrintGCApplicationStoppedTime" and "-XX:+PrintGCApplicationConcurrentTime" JVM options:

herong> \Progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m
   -XX:+UseConcMarkSweepGC
   -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
   -XX:+PrintGCApplicationStoppedTime
   -XX:+PrintGCApplicationConcurrentTime
   GarbageCollection > output.txt
(Ctrl-C)

herong> more output.txt
Step/TotalMemory/FreeMemory/UsedMemory:

0.164: Application time: 0.0736917 seconds
0.178: [GC (Allocation Failure)
   0.178: [ParNew: 889K->64K(960K), 0.0013412 secs] ...
0.180: Total time for which application threads were stopped: 0.0016155 s
   Stopping threads took: 0.0000303 seconds
   -- Application stopped for Minor GC

1   2031616   693536   1338080
1.168: Application time: 0.9881569 seconds
1.168: [GC (Allocation Failure)
   1.168: [ParNew: 865K->63K(960K), 0.0054171 secs] ...
1.174: Total time for which application threads were stopped: 0.0059145 s
   Stopping threads took: 0.0001105 seconds
   -- Application stopped for Minor GC

2   2695168   292168   2403000
1.175: Application time: 0.0009359 seconds
1.175: [GC (CMS Initial Mark)
   [1 CMS-initial-mark: 1482K(1672K)] 2346K(2632K), ...
1.176: Total time for which application threads were stopped: 0.0009683 s
   Stopping threads took: 0.0001011 seconds
   -- Application stopped for Initial Mark step of Major GC

1.176: [CMS-concurrent-mark-start]
1.180: [CMS-concurrent-mark: 0.004/0.004 secs]
   -- Application not stopped for Concurrent Mark step of Major GC

1.180: [CMS-concurrent-preclean-start]
1.181: [CMS-concurrent-preclean: 0.000/0.000 secs]
   -- Application not stopped for Concurrent Preclean step of Major GC

1.181: Application time: 0.0050827 seconds
1.181: [GC (CMS Final Remark) [YG occupancy: 864 K (960 K)]1.181:
   [Rescan (parallel) , 0.0028359 secs]1.184: [weak refs processing, ...
1.186: Total time for which application threads were stopped: 0.0045256 s
   Stopping threads took: 0.0000785 seconds
   -- Application stopped for the Final Mark step of Major GC

1.186: [CMS-concurrent-sweep-start]
1.186: [CMS-concurrent-sweep: 0.000/0.000 secs]
   -- Application not stopped for the Concurrent Sweep step of Major GC
1.187: [CMS-concurrent-reset-start]
1.187: [CMS-concurrent-reset: 0.000/0.000 secs]
   -- Application not stopped for the Concurrent Reset step of Major GC

2.168: Application time: 0.9821720 seconds
2.168: [GC (Allocation Failure)
   2.168: [ParNew: 864K->64K(960K), 0.0065795 secs] ...
2.175: Total time for which application threads were stopped: 0.0070454 s
   Stopping threads took: 0.0000938 seconds
   -- Application stopped for Minor GC

2.175: Application time: 0.0003583 seconds
2.175: [GC (Allocation Failure)
   2.175: [ParNew: 913K->0K(960K), 0.0040371 secs]
2.180: Total time for which application threads were stopped: 0.0044262 s
   Stopping threads took: 0.0000405 seconds
   -- Application stopped for Minor GC

2.180: Application time: 0.0002606 seconds
2.180: [GC (CMS Initial Mark)
   [1 CMS-initial-mark: 3151K(3364K)] 3365K(4964K), ...
2.181: Total time for which application threads were stopped: 0.0013028 s
   Stopping threads took: 0.0000990 seconds
   -- Application stopped for the Initial Mark step of Major GC

2.181: [CMS-concurrent-mark-start]
3   5083136   1636512   3446624
2.185: [CMS-concurrent-mark: 0.003/0.003 secs]
   -- Application not stopped for the Concurrent Mark step of Major GC

2.185: [CMS-concurrent-preclean-start]
2.185: [CMS-concurrent-preclean: 0.000/0.000 secs]
   -- Application not stopped for Concurrent Preclean step of Major GC

2.185: Application time: 0.0040286 seconds
2.185: [GC (CMS Final Remark) [YG occupancy: 214 K (1600 K)]2.186:
      [Rescan (parallel) , 0.0047346 secs]2.190: [weak refs processing,
2.192: Total time for which application threads were stopped: 0.0062263 s
      Stopping threads took: 0.0000973 seconds
   -- Application stopped for the Final Mark step of Major GC

2.192: [CMS-concurrent-sweep-start]
2.192: [CMS-concurrent-sweep: 0.000/0.000 secs]
   -- Application not stopped for the Concurrent Sweep step of Major GC

2.193: [CMS-concurrent-reset-start]
2.193: [CMS-concurrent-reset: 0.000/0.000 secs]
   -- Application not stopped for the Concurrent Reset step of Major GC

...

The output shows that:

Conclusion: The CMS Collector reduces the duration of stop-the-world (application pause) of Major GC to only two steps: Initial Mark and Final Mark. This definitely improves the performance (response time) of the application.

Table of Contents

 About This Book

 Heap Memory Area and Size Control

 JVM Garbage Collection Logging

 Introduction of Garbage Collectors

 Serial Collector - "+XX:+UseSerialGC"

 Parallel Collector - "+XX:+UseParallelGC"

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

 What Is Concurrent Mark-Sweep (CMS) Collector

 Concurrent Mark-Sweep Collector GC Log Message Format

Reduce Stop-The-World with Concurrent Mark and Sweep

 Parallel New (ParNew) Collector for Minor GC

 ParNew Collector - Tenuring Age Distribution

 Maximum Logging of All Phases on Young GC

 "-XX:ParallelGCThreads=6" - Young GC Parallel Threads

 "-XX:MaxTenuringThreshold=0" - Tenuring Objects Immediately

 "-XX:CMSInitiatingOccupancyFraction=20" - Initiate CMS

 Maximum Logging of All Phases on Old GC

 Maximum Logging of All Phases on Full GC

 "-XX:ParallelGCThreads=6" - Old GC Parallel Threads

 "-XX:ConcGCThreads=3" - Old GC Concurrent Threads

 Garbage First (G1) Collector - "+XX:+UseG1GC"

 The Z Garbage Collector (ZGC) - "+XX:+UseZGC"

 Object References and Garbage Collection

 Garbage Collection Performance Test Program

 Performance Tests on Serial Collector

 Performance Tests on Parallel collector

 Performance Tests on Concurrent collector

 Performance Tests on G1 collector

 Garbage Collection Performance Test Summary

 References

 Full Version in PDF/EPUB