JVM Logging - Sip of Java
Billy Korando on November 7, 2022
VM logging has long been part of the JDK. It can be an excellent tool for performing root cause analysis and figuring out performance quirks. In JDK 9, several changes were made to how VM logging is handled, making it more user-friendly and configurable. Let’s look at how to use VM logging in this article.
Enabling and Configuring Logging
VM logging can be enabled at the most basic level by adding -Xlog to your java command. This will enable VM logging with a default configuration of:
-Xlog:all=info:stdout:uptime,levels,tags
The above will turn VM logging on for all the different categories at the info level. It will print out VM logs to stdout, including the uptime of the JVM, the level of the log statement, and the tags associated with it. Here’s an example of a log statement:
[1.043s][info][methodhandles ] lookup_polymorphic_method => intrinsic {method} {0x000000010a38c880}
In most scenarios, the default VM logging will be too noisy to be useful. Luckily VM logging can be configured to suit many needs.
Configuring Tags
A developer will often look into a specific issue when enabling VM logging. VM logging can be configured to only produce logs that match specific categories such as; garbage collection (gc), the just-in-time compiler (jit), CPU usage (cpu), and more. Limiting logging to specific categories can help to reduce noise and allow you to focus on the areas of concern:
-xlog:gc,heap
The above example will limit log output to log statements that only contain gc or heap tags. Alternatively, the following examples can be used to print out logs that contain both gc AND head, and * can be added so that any log containing either gc or heap tags will be printed:
-xlog:gc+heap
-xlog:gc*,heap*
Tags can be set to different levels of logging; off, trace, debug, info, warning, error; for example, if I wanted debug logging for heap but error for gc, it would look like this:
-Xlog:'gc*=error,heap*=debug'
Configuring Output Location
By default, VM logging will print to stdout; however, this might not often be the desired location for VM logging to be sent to; in many cases, it would be preferred for VM logging to be written to a separate file which can be done like so:
-Xlog:'gc*,heap*':vm-logging.log
It’s also valid to have multiple instances of -Xlog in a java command, which can be useful for writing VM logs to different locations based on type. In the below example, gc log statements are written to gc.log while heap log statements are written to heap.log.
-Xlog:'gc*':gc.log -Xlog:`heap*`:heap.log
Reducing Performance Overhead
VM logging can cause a non-trivial amount of overhead to a Java application. To help address this, consider enabling asynchronous logging -Xlog:async, which will write log statements to an in-memory buffer, which will be periodically flushed. The buffer size can be configured with -XX:AsyncLogBufferSize=<bytes>. Like in this example:
-Xlog:'gc*=trace':gc-trace.log -Xlog:async -XX:AsyncLogBufferSize=102400
Configuring Logging on a Running JVM
VM logging can be configured on a JVM with jcmd and VM.log. All configuration options available when configuring VM logging with the java command are available, but supplying the options is done through the output, output_options, what, and decorators arguments like in the below example:
jcmd <pid> VM.log output="file=heap.log" output_options="filecount=5,filesize=10m" what="heap=info" decorators="time,level"
Additional Reading
Enable Logging with the JVM Unified Logging Framework
Configuring Logging with jcmd Example
Happy coding!