Unified Logging In Java 9 With The -Xlog Option

Java 9 comes with a unified logging architecture (JEP 158) that pipes a lot of messages that the JVM generates through the same mechanism, which can be configured with the -Xlog option. This gives uniform access to log messages from different subsystems such as class loading, threading, the garbage collector, the module system, or the interaction with the underlying operating system.

The -Xlog option can be a bit intimidating, so in this post we will master it step by step, learning how to use it to select which messages and information to show.

What Is Unified Logging?

The unified logging infrastructure is very similar to known logging frameworks

The JVM-internal, unified logging infrastructure is very similar to known logging frameworks like Log4j or Logback that you might have used for your application. It generates textual messages, attaches some meta information like tags (describing the originating subsystem), a log level (describing the importance of the message), and time stamps before printing them somewhere. The logging output can be configured according to your needs.

Logging can be activated with the java option -Xlog. This is the only flag regarding this mechanism – any further configuration is immediately appended to that option. Configurable aspects of logging are:

  • which messages to log (by tag and/or by log level)
  • which information to include (for example time stamps and process IDs)
  • which output to use (for example a file)

We’ll look at each of them in turn, but before doing that, we can have a look at the kind of messages -Xlog produces. Simply execute java -Xlog (maybe append -version to get rid of the helpful but long display of command line options) and have a look at the output – of which there is a lot. One of the first messages tells us that the HotSpot virtual machine begins its work:

It shows how long the JVM has been running (2 ms), the message’s log level ( info), its tags (only os), and the actual message.
Let’s see how to influence these details.

Defining Which Messages Should Be Shown

The log level and tags can be used to define what exactly the logs should show by defining pairs <tag-set>=<level>, which are called selectors. All tags can be selected with all and the level is optional and defaults to info. Here’s how to use it:

Let’s try something else:

Lucky shot! I had to truncate the output but trust me, there’s a lot of helpful information in those messages. You don’t have to take that route, though, -Xlog:help shows the same information but more beautifully formatted (see below).

A little surprising (at least at first) is the detail that messages only match a selector if their tags exactly match the given ones. Given ones? Plural? Yes, a selector can name several tags by concatenating them with +. Still, a message has to contain exactly those to be selected.

Hence, using gc (for garbage collection) versus gc+heap, for example, should select different messages. This is indeed the case:

Several selectors can be defined – they just have to be separated with commas:

Using this strategy it is very cumbersome to get all messages that contain a certain flag. Luckily, there is an easier way to do that, namely the wildcard *, which can be used with a single tag to define a selector:

Using selectors, there are three easy steps to get to know a subsystem of the JVM:

  • Find interesting tags in the output of java -Xlog:help.
  • Use them with -Xlog:tag_1*,tag_2*,tag_n* to display all info messages that were tagged with any of them.
  • Selectively switch to lower log levels with -Xlog:tag_1*=debug.

Defining Where Messages Should Go

Compared to the non-trivial selectors, the output configuration is really simple. It comes after the selectors (separated by a colon) and has three possible locations:

  • stdout: The default output. On the console that is the terminal window unless redirected, in IDEs it is often shown in a separate tab or view.
  • stderr: The default error output. On the console that is the terminal window unless redirected, in IDEs it is usually shown in the same tab/view as stdout but printed red.
  • file=<filename>: Defines a file to pipe all messages into. Putting in file= is optional.

Unlike with common logging frameworks, it is unfortunately not possible to use two output options simultaneously.

Here’s how to put all debug messages in the file application.log:

More output options are available that allow log file rotation based on file size and number of files to rotate.

Defining What Messages Should Say

As I said in the introduction, each message consist of text and meta-information. Which of these additional pieces of information will be printed, is configurable by selecting decorators, which are listed in the following table. This happens after the output location and another colon.

Option Description
time Current time and date in ISO-8601 format.
uptime Time since the start of the JVM in seconds and milliseconds (e.g., 6.567s).
timemillis The same value as generated by System.currentTimeMillis().
uptimemillis Milliseconds since the JVM started.
timenanos The same value as generated by System.nanoTime().
uptimenanos Nanoseconds since the JVM started.
pid The process identifier.
tid The thread identifier.
level The level associated with the log message.
tags The tag-set associated with the log message.

Let’s say we want to print the time stamp, the uptime in milliseconds, and the thread ID for all garbage collection debug messages to the console. Here’s how to do that:

Putting The Pieces Together

Formally, the -Xlog option has this syntax:

Each of the parameters following -Xlog is optional but if one is used, so have to be all the others that come before it.

  • Selectors are pairs of tag sets and log levels. This part is also called the what-expression, a phrase you will likely encounter when the configuration is not syntactically correct.
  • With output the target location for the log messages (in short, the terminal window or a log file) can be defined.
  • Decorators can be used to define what information the messages should include.
  • Yes, annoyingly the output mechanism and further output options are split, with decorators in between.

For more details, have a look at the online documentation or the output of java -Xlog:help:

Reflection

In Java 9, most JVM subsystems use a unified logging mechanism. This makes it easier than before to configure logging, so you get the exact messages you need. The -Xlog option allows the definition of <selectors>, <output>, <decorators>, and <output-options>, which can be used to define precisely what gets logged, where the output shows up, and what it looks like.

Share & Follow

You liked this post? Then share it with your friends and followers!
twittergoogle_plusredditlinkedin
And if you like what I'm writing about, why don't you follow me?
twittergoogle_plusrss

Other Posts