Visit Azul.com Support

Unified Garbage Collection Logging Recommendations

Table of Contents

Looking for Zing? The Azul Zing Virtual Machine is now Azul Zulu Prime Builds of OpenJDK and part of Azul Platform Prime. Learn more.

Starting with Java 9, the unified logging infrastructure in Java Virtual Machine (JVM) provides access to log messages from different subsystems (compiler, gc, classload, etc.). See JEP 158: Unified JVM Logging for more information.

The unified logging system for all JVM components includes reimplemented GC logging which is described in JEP 271: Unified GC Logging. Azul Platform Prime 20.09.0.0 introduces support for unified GC logging in Azul Platform Prime 8, 11, and 13. Both sets of GC logging options - old and unified - are supported.

For non-detailed GC logging, use unified -Xlog:gc instead of old -XX:+PrintGC. For detailed information, use unified -Xlog:gc* instead of old -XX:+PrintGCDetails. A unified log message has a tag and a level set associated with it. To quickly see examples of -Xlog usage syntax, available tags, levels, decorators, and sample command lines with explanations, use:

 -Xlog:help 

Understanding -Xlog:gc Format

-Xlog:gc is a command-line option to perform unified GC logging using the Azul Zulu Prime Builds of OpenJDK (Azul Zulu Prime JVM) unified logging framework.

Example 1. Syntax of the -Xlog option

 -Xlog:gc:<output>:<decorators>:<output_options> 

Where:

  • gc is a tag to log GC related information.

  • <output> specifies the target location for GC log messages.

  • <decorators> are used to define information that log messages include.

  • <output_options> are varied output options for logging additional information.

Unified logging is performed at six different levels that correspond to the amount of details included. You can choose messages to log based on the preferred level. The levels are listed in increasing order of verbosity:

  • off

  • error

  • warning

  • info

  • debug

  • trace

Enabling Unified GC Logging

-XX:+UseGCUnifiedLogging enables unified GC logging, and -XX:-UseGCUnifiedLogging disables it in Azul Zulu Prime JVM. By default, unified GC logging is enabled in Azul Zulu Prime JVM.

To start unified GC logging, use:

 -Xlog:gc,safepoint:gc.log 

This command-line option logs messages tagged with the gc and safepoint tags using info level to gc.log. By default, a GC log is written to stdout.

To get more detailed information, use:

 -Xlog:gc*,safepoint:gc.log 

Example 2. A sample unified GC log entry

 [2.308s][info][gc] [Safepoint max times: safepoint 21.697 ms, time to safepoint 14.273 ms] 

Where:

  • [2.308s] is the time since the start of the Azul Zulu Prime JVM

  • [info] is a default logging level

  • [gc] is the name of the GC-specific tag

  • [Safepoint max times: safepoint 21.697 ms, time to safepoint 14.273 ms] is a log message

Azul Zulu Prime JVM supports the following three output types:

  • stdout

  • stderr

  • text file

To log GC messages to a file rather than to a console, use:

 -Xlog:gc:file=<filename> 

Where file= is optional and can be omitted.

Configuring Rotation of Large Log Files

To configure log files to handle file rotation based on file size and a number of files to rotate, use:

 -Xlog:gc:<decorators>:<filename>:filesize=<size>:filecount=<number_of_files_in_rotation> 

Example 3. A sample -Xlog:gc command for configuring log rotation

 -Xlog:gc:none:gc.log:filesize=1M:filecount=5 

Where:

  • gc is a tag to log GC-specific information.

  • none specifies no decorations.

  • gc.log specifies the file name for GC log messages.

  • filesize=1M is a size of a rotating file.

  • filecount=5 specifies the number of files in a rotating set.

By default, that is when using -Xlog:gc:gc.log, the size of a rotating file is 20 MB and the number of files in rotation is 5.

To turn off rotation, specify 0 in the filecount, for example, -Xlog:gc:none:gc.log:filesize=1MB:filecount=0

Concatenating Tags

To include messages tagged with different tags in your GC log output, you can concatenate the tags with + as shown in Example 4.

Example 4. A sample -Xlog:gc command for concatenating tags

 -Xlog:gc+phases:gc.log 

The resulting GC log contains all messages that feature the gc and phases tags:

 [2.299s][info][gc] [SPS 0.000 0.000 0.001 0.178 0.005 0.000 0.008 0.087 0.142 0.420 NewGC_pause2 2.299078
[2.299s][info][gc, phases] [New GC cycle 3-2: concurrent ref processing] 

Additionally, you can specify a logging level by adding =<level> after the set of tags as follows:

 -Xlog:gc+task+stats=debug:gc.log 

This includes all messages with the gc, task, and stats tags at the debug logging level.

Configuring Multiple Logs

To simultaneously log messages from different subsystems to separate files, specify particular tags (or a combination of tags) and file names in the command line, for example:

 -Xlog:gc:gc.log::filesize=1M -Xlog:gc+details:gcdetails.log::filesize=5M 

This creates a gc.log file with GC related messages and a gcdetails.log file with detailed GC related messages.

Example 5. A sample log entry with a gc tag

 [5.010s][info][gc] [VM has exited gracefully] 

Example 6. A sample log entry with gc and details tags

 [5.009s][info][gc,details] [Unmapping heap memory, 0 millis] 

Inspecting GC Performance

With the safepoint tag, you can compare the performance of GC implementations over different JVMs as it produces similar log lines on all JVMs for pauses affecting application performance. The highest performance regarding latency is achieved when pauses are as short as possible.

Example 7. A sample output on Azul Zulu Prime JVM

 [105.482s][info][safepoint] Total time for which application threads were stopped: 0.0003760 seconds, Stopping threads took: 0.0000014 seconds 

The snippet above shows -Xlog:gc,safepoint:gc.log output on Azul Zulu Prime JVM with a pause of 0.376 ms at 105 seconds after application start.

Example 8. A sample output on OpenJDK

 [55.350s][info][safepoint] Safepoint "CollectForAllocation", Time since last: 553327366 ns, Reaching safepoint: 188921 ns, At safepoint: 94660058 ns, Total: 94848979 ns 

The log entry above shows -Xlog:gc,safepoint:gc.log output on OpenJDK with a pause of 94.848 ms at 55 seconds after application start.

To filter Azul Zulu Prime JVM and Hotspot logs to always select the total time, use the following script:

 grep safepoint.*Total gc.log | sed -E 's/^\[([0-9\.s]+).*Total[a-z ]*: ([0-9\.]+ [a-z]+).*/\1 \2/' 

Example 9. A sample regex output on Azul Zulu Prime JVM

 109.288s 0.0003746 seconds 

Example 10. A sample regex output on OpenJDK

 103.339s 257668 ns 

For Azul Zulu Prime JVM GC logs, you can also use Azul Zulu Prime JVM GCLogAnalyzer which displays performance-related metrics as graphs.

Mapping Old and Unified GC Logging Options

The table below contains a list of old GC logging command-line options and their unified GC logging equivalents.

Old GC Logging Option Unified GC Logging Configuration

PrintGC

-Xlog:gc

PrintGCDetails

-Xlog:gc*

PrintGCTimeStamps

-Xlog:gc

PrintGCDateStamps

-Xlog:gc:time,uptime,level,tags

PrintGCApplicationConcurrentTime

-Xlog:safepoint

PrintGCApplicationStoppedTime

-Xlog:safepoint