Back to Zing Documentation Home

Unified Garbage Collection Logging Recommendations

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.

ZVM 20.09.0.0 introduces support for unified GC logging in Zing 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 Zing Virtual Machine (ZVM) 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 Zing.

By default, unified GC logging is enabled in Zing.

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 Zing Virtual Machine

  • [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

Zing 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 Zing

[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 Zing 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 Zing 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 Zing

109.288s 0.0003746 seconds

Example 10. A sample regex output on OpenJDK

103.339s 257668 ns

For Zing GC logs, you can also use Zing 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

See Also

Zing Monitoring and Management


© Azul Systems, Inc. 2021 All rights reserved.

Privacy Policy | Legal | Terms of Use