Reduce Stop-The-World with Concurrent Mark and Sweep

Java GC Tutorials - Herong's Tutorial Examples

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

∟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:

Application was stopped by the CMS Collector for Minor GC.
Application was stopped by the CMS Collector for Initial Mark and Final Mark steps of Major GC.
Application was not stopped by the CMS Collector for Concurrent Mark, Concurrent Preclean, Concurrent Sweep, and Concurrent Reset steps of Major GC.

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.