Configuring a Perfect JVM GC Log Printing Strategy

In production or testing environments where GC issues need to be diagnosed, it is essential to configure JVM GC log printing parameters to capture sufficient information for analysis.

Print Content

To retain enough "on‑site evidence", print comprehensive GC information. The performance impact of the additional I/O is negligible.

Print Basic GC Information

The first step is to enable the basic GC logging flags:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

Print Object Age Distribution

Analyzing promotion and pause issues requires object age distribution logs: -XX:+PrintTenuringDistribution Sample output:

Desired survivor size 59244544 bytes, new threshold 15 (max 15)
- age   1:     963176 bytes,     963176 total
- age   2:     791264 bytes,    1754440 total
- age   3:     210960 bytes,    1965400 total
- age   4:     167672 bytes,    2133072 total
- age   5:     172496 bytes,    2305568 total
- age   6:     107960 bytes,    2413528 total
- age   7:     205440 bytes,    2618968 total
- age   8:     185144 bytes,    2804112 total
- age   9:     195240 bytes,    2999352 total
- age  10:     169080 bytes,    3168432 total
- age  11:     114664 bytes,    3283096 total
- age  12:     168880 bytes,    3451976 total
- age  13:     167272 bytes,    3619248 total
- age  14:     387808 bytes,    4007056 total
- age  15:     168992 bytes,    4176048 total

Print Heap Data After GC

Comparing heap memory before and after each GC gives a clear picture: -XX:+PrintHeapAtGC Sample output:

{Heap before GC invocations=0 (full 0):
 garbage-first heap   total 1024000K, used 324609K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 6 young (6144K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
Heap after GC invocations=1 (full 1):
 garbage-first heap   total 1024000K, used 21755K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
}

Print Stop‑The‑World (STW) Time

Pause time is the most critical GC metric: -XX:+PrintGCApplicationStoppedTime Sample output:

Total time for which application threads were stopped: 0.0254260 seconds, Stopping threads took: 0.0000218 seconds

Print Safepoint Statistics

Before entering STW, locating an appropriate safepoint is important (optional, useful for debugging GC issues):

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

Sample output:

vmop                [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.371: ParallelGCFailedAllocation       [      10          0          0    ]      [     0     0     0     0     7    ]  0   
Execute full gc...dataList has been promoted to cms old space
          vmop                [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.379: ParallelGCSystemGC               [      10          0          0    ]      [     0     0     0     0    16    ]  0   
          vmop                [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.396: no vm operation                 [       9          1          1    ]      [     0     0     0     0   341    ]  0

Print Reference Processing Information

Printing details about strong, weak, soft, phantom references and finalization can help diagnose issues: -XX:+PrintReferenceGC Sample output:

2021-02-19T12:41:30.462+0800: 5072726.605: [SoftReference, 0 refs, 0.0000521 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [FinalReference, 0 refs, 0.0000056 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [JNI Weak Reference, 0.0000131 secs], 0.4635293 secs]

Complete Parameter List

# required
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

Output Method

By default, these logs are printed to the console, which can become noisy if the application also logs to stdout. Appending to a single file (e.g., Tomcat's catalina.out) can cause the file to grow indefinitely.

JVM Log Rotation

The JVM provides parameters for rotating GC logs:

# GC log file path
-Xloggc:/path/to/gc.log
# Enable log rotation
-XX:+UseGCLogFileRotation 
# Maximum number of rotated files
-XX:NumberOfGCLogFiles=14
# Maximum size of each file before rotation
-XX:GCLogFileSize=100M

Issues with this approach include overwriting on each start and a fixed limit on the number of files.

Timestamped Log Files

An alternative is to name log files with a timestamp, avoiding overwrites:

# Use %t for timestamped log file name
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc-%t.log
# Example generated file: gc-2021-03-29_20-41-47.log

However, without rotation the single file can become very large.

Combining Both Strategies

By combining timestamped filenames with JVM rotation, you get both non‑overwriting and size‑controlled logs:

# Timestamped log file path
-Xloggc:/path/to/gc-%t.log
# Enable rotation
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=14
-XX:GCLogFileSize=100M

The resulting files look like gc-2021-03-29_20-41-47.log.0, gc-2021-03-29_20-41-47.log.1, etc.

Best Practice – Full Parameter Set

# Required
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# Optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

# GC log file path with timestamp
-Xloggc:/path/to/gc-%t.log
# Enable rotation
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=14
-XX:GCLogFileSize=100M