Garbage Collection Logging Options

Java 8 GC Tutorials - Herong's Tutorial Examples

∟Garbage Collection Logging Options

This section describes HotSpot JVM options to generate garbage collection log messages. '-XX:+PrintGCDetails' and '-XX:+PrintGCDateStamps' are two most important options.

The previous tutorial showed us how to use totalMemory() and freeMemory() methods to observe the JVM garbage collection (GC) process. Now let's use JVM logging options to do the observation.

Here is a list of JVM command line options related to garbage collection logging:

-Xloggc:<file> - Force garbage collection message to be logged into a file instead of the console. For example, "-Xloggc:gc.log" will send all GC log messages to a file called gc.log. Without this option, GC log messages will be displayed on the console.

-XX:+PrintGC - Print a shot message after each garbage collection is done. Here are some examples of log messages generated by the "-XX:+PrintGC" option showing two types of garbage collections.

41.418: [GC (Allocation Failure)
   43004K->42880K(55392K), 0.0306458 secs]
41.449: [Full GC (Allocation Failure)
   42880K->33711K(55392K), 0.0178224 secs]
108.889: [GC (Allocation Failure) , 0.0349956 secs]
108.924: [Full GC (Allocation Failure)
   63359K->32478K(63360K), 0.0235808 secs]

-verbose:gc - Same as "-XX:+PrintGC".

-XX:+PrintGCDetails - Print a long detailed message with more details after each garbage collection is done. "-XX:+PrintGCDetails" overrides "-XX:+PrintGC", if both are used. Here are some examples of log messages generated by the "-XX:+PrintGCDetails" option showing two types of garbage collections.

3.116: [GC (Allocation Failure)
   3.116: [DefNew: 1171K->127K(1216K), 0.0060344 secs]
3.122: [Tenured: 3492K->3604K(3604K), 0.0044445 secs] 3624K->3620K(4820K),
   [Metaspace: 1556K->1556K(4480K)], 0.0107617 secs]
   [Times: user=0.00 sys=0.00, real=0.00 secs]

-XX:+PrintGCTimeStamps - Print a timestamp relative to the JVM start time when a garbage collection occurs. The timestamp is printed at the beginning of each GB log message. "-XX:+PrintGCTimeStamps" is a default option. Here are two examples of log messages showing that two garbage collections occurred at 1.092 and 1.095 seconds after JVM started:

1.092: [GC (Allocation Failure)  1557K->1540K(2500K), 0.0028837 secs]
1.095: [Full GC (Allocation Failure)  1540K->1540K(2500K), 0.0043869 secs]

-XX:+PrintGCDateStamps - Print a calendar data and timestamp when a garbage collection occurs. Here are two examples of log messages showing that two garbage collections occurred at 2018-04-01T21:02:19.647-0100 and 2018-04-01T21:02:36.884-0100:

2018-04-01T21:02:19.647-0100: 92.929: [GC (Allocation Failure)
   92.929: [DefNew: 17451K->17451K(19648K), 0.0000665 secs] ...
2018-04-01T21:02:36.884-0100: 110.163: [GC (Allocation Failure)
   110.163: [DefNew (promotion failed) : 17472K->19647K(19648K), ...

-XX:+PrintGCApplicationStoppedTime - Print how much time it lasted when the JVM pauses the execution of the application. Most of the time, application pauses are caused by garbage collections. Some other JVM events can also causes application pauses. Here are two log messages generated from two application pauses. The first pause lasted for 0.0021977 seconds and the second pause lasted for 0.0065514 seconds.

0.102: Total time for which application threads were stopped:
   0.0021977 seconds, Stopping threads took: 0.0001416 seconds
...
1.114: Total time for which application threads were stopped:
   0.0065514 seconds, Stopping threads took: 0.0000849 seconds

-XX:+PrintGCApplicationConcurrentTime - Print how much time elapsed since the last application pause, or the elapsed time between two application pauses. Here are two log messages telling us two periods of time when the application were running without any pauses. The first period lasted for 17.0651013 seconds and the second period lasted for 16.0815864 seconds.

108.984: Application time: 17.0651013 seconds
...
125.114: Application time: 16.0815864 seconds

-XX:+PrintHeapAtGC - Print heap usage summary before and after each GC. Here is example of "-XX:+PrintHeapAtGC" log messages:

{Heap before GC invocations=1 (full 0):
 def new generation   total 4928K, used 4427K [0x04c00000, 0x051500...
  eden space 4416K,  94% used [... ...
  from space 512K,  47% used [...  ...
  to   space 512K,   0% used [...  ...
 tenured generation   total 10944K, used 3072K [0x0a150000, 0x0ac00...
   the space 10944K,  28% used [0x0a150000, 0x0a450030, 0x0a450200,...
 Metaspace used 1560K, capacity 2246K, committed 2368K, reser...

0.104: [GC (Allocation Failure)  7499K->7412K(15872K), 0.0045222 se...

Heap after GC invocations=2 (full 0):                              ...
 def new generation   total 4928K, used 244K [0x04c00000, 0x0515000...
  eden space 4416K,   0% used [... ...
  from space 512K,  47% used [...  ...
  to   space 512K,   0% used [...  ...
 tenured generation   total 10944K, used 7168K [0x0a150000, 0x0ac00...
   the space 10944K,  65% used [0x0a150000, 0x0a850070, 0x0a850200,...
 Metaspace used 1560K, capacity 2246K, committed 2368K, reser...
}

-XX:+PrintTenuringDistribution - Print a list of objects in the survivor space grouped by their ages after each minor GC. It also provides the suggested survivor space size and new setting of object tenuring age based on the analysis done in this minor GC. Here is example of "-XX:+PrintTenuringDistribution" log messages:

Desired survivor size 75497472 bytes, new threshold 10 (max 15)
- age   1:   19321624 bytes,   19321624 total
- age   2:      79376 bytes,   19401000 total
- age   3:    2904256 bytes,   22305256 total

-XX:+PrintReferenceGC - Print number of references processed for each reference type, and time used at each GC. Here is example of "-XX:+PrintReferenceGC" log messages:

0.367: [SoftReference, 0 refs, 0.0000448 secs]
0.367: [WeakReference, 0 refs, 0.0000098 secs]
0.367: [FinalReference, 2052 refs, 0.0818372 secs]
0.449: [PhantomReference, 0 refs, 0 refs, 0.0000137 secs]
0.449: [JNI Weak Reference, 0.0000192 secs]

-XX:+PrintGCTaskTimeStamps - Print time stamps for every individual garbage collection worker thread task. Here is an example of "-XX:+PrintGCTaskTimeStamps" output in the console when used with the Parallel Collector:

GC-Thread 0 entries: 6
  [ noop task 260045 260047 ]
  [ old-to-young-roots-task 260049 260070 ]
  [ old-to-young-roots-task 260071 260088 ]
  [ thread-roots-task 260089 260129 ]
  [ thread-roots-task 260129 260506 ]
  [ steal-task 260506 261816 ]
GC-Thread 1 entries: 8
  [ thread-roots-task 260147 260149 ]
  [ scavenge-roots-task 260150 260152 ]
  [ scavenge-roots-task 260153 260154 ]
  [ scavenge-roots-task 260154 260157 ]
  [ scavenge-roots-task 260157 260204 ]
  [ scavenge-roots-task 260204 261783 ]
  [ steal-task 261784 261815 ]
  [ waitfor-barrier-task 261815 261882 ]