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
For detailed information, use unified
-Xlog:gc* instead of old
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: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
gcis 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:
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:
This command-line option logs messages tagged with the
safepoint tags using
info level to
By default, a GC log is written to
To get more detailed information, use:
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]
[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:
To log GC messages to a file rather than to a console, use:
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:
Example 3. A sample
-Xlog:gc command for configuring log rotation
gcis a tag to log GC-specific information.
nonespecifies no decorations.
gc.logspecifies the file name for GC log messages.
filesize=1Mis a size of a rotating file.
filecount=5specifies 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,
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
The resulting GC log contains all messages that feature the
[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
after the set of tags as follows:
This includes all messages with the
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:
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
[5.010s][info][gc] [VM has exited gracefully]
Example 6. A sample log entry with
[5.009s][info][gc,details] [Unmapping heap memory, 0 millis]
Inspecting GC Performance
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|
© Azul Systems, Inc. 2020 All rights reserved.