"-XX:+PrintGCApplicationStoppedTime" - Application Pause Durations

Java 8 GC Tutorials - Herong's Tutorial Examples

∟"-XX:+PrintGCApplicationStoppedTime" - Application Pause Durations

This section describes the garbage collection logging option, '-XX:+PrintGCApplicationStoppedTime', which prints how much time it lasted when the JVM pauses the execution of the application for garbage collection or other JVM event.

In this tutorial, let's try the "-XX:+PrintGCApplicationStoppedTime" garbage collection logging option to see what we will get in the log file:

herong> \progra~1\java\jdk1.8.0\bin\java -Xms2m -Xmx64m \
   -XX:+PrintGCApplicationStoppedTime -Xloggc:gc.log \
   GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:
1   2031616   698848   1332768
2   3874816   1473392   2401424
3   3874816   425688   3449128
4   8970240   4442016   4528224
...
(Ctrl-C)

herong> more gc.log
CommandLine flags: -XX:InitialHeapSize=2097152 -XX:MaxHeapSize=67108864
   -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps
   -XX:-UseLargePagesIndividualAllocation
0.151: [GC (Allocation Failure)  889K->755K(1984K), 0.0023940 secs]
0.153: Total time for which application threads were stopped:
   0.0026422 seconds, Stopping threads took: 0.0001156 seconds
1.146: [GC (Allocation Failure)  1557K->1540K(2500K), 0.0043665 secs]
1.150: [Full GC (Allocation Failure)  1540K->1540K(2500K), 0.0026525 secs]
1.153: Total time for which application threads were stopped:
   0.0076895 seconds, Stopping threads took: 0.0002393 seconds
2.147: [GC (Allocation Failure)  2601K->2580K(3784K), 0.0049479 secs]
2.152: Total time for which application threads were stopped:
   0.0053164 seconds, Stopping threads took: 0.0001463 seconds
...

Notes on the output:

Three JVM options: "-XX:+PrintGC", "-XX:+PrintGCTimeStamps" and "-XX:-UseLargePagesIndividualAllocation" were added by default.
"Total time for which application threads were stopped..." log messages were reported after each GC events. For example, at 0.153, JVM reported that the application was stopped for 0.0026422 seconds for the GC that just ended at 0.151. I will explain how to read log messages later when we have better understandings on how each garbage collector works.

Obviously, reporting how much time the application are stopped by the JVM does help if you want to troubleshoot any performance issues. So you should use "-XX:+PrintGCApplicationStoppedTime" all the time.