JEP 158: Unified JVM Logging

Summary

Introduce a common logging system for all components of the JVM.

Goals

• Common logging command-line options for all components
• Log messages are enabled and configured by component (e.g. compiler, gc, classload, …)
• Logging is performed at different levels: error, warning, info, debug, trace
• Logging messages are in human-readable plain text
• Default logging is to stderr
• Possible to redirect log per component to a file
• File rotation of log files by size (similar to what is available for GC logs today)
• Tested and supported – should not crash if/when enabled by user/customer
• Print line-at-a-time (no interleaving within same line)
• Messages can be “decorated” with level, component, thread id, timestamp
• Decorations can be configured
• Multi-line output: several lines can have the same timestamp, but will not necessarily be printed together
• Logging can be configured dynamically at runtime via jcmd or MBeans
• Define formatting guidelines and helpers for commonly used values (KBs, MBs, GBs, dates, elapsed time, etc.)

Stretch goals:

• Enable/disable individual log messages by message id (for example by using __FILE__ / __LINE__)
• Implement syslog and Windows Event Viewer backends
• Make message decorations configurable

Non-Goals

It is outside the scope of this JEP to add the actual logging calls from all JVM components. This JEP will only provide the infrastructure to do the logging.

It is also outside the scope of the JEP to enforce a logging format, apart from the format of the decorations and the use of human-readable plain text.

This JEP will not add logging to Java code in the JDK.

Motivation

The JVM is complex system-level component where root-cause analysis is often a difficult and time-consuming task. Without extensive serviceability features it is often close to impossible to find the root cause of intermittent crashes or performance quirks in a production environment. Fine-grained, easy-to-configure JVM logging available for use by support and sustaining engineering is one such feature.

JRockit has this feature and it has been instrumental in providing support to customers. The proposed design is heavily influenced by what exists in JRockit.

Description

Components

The logging framework defines a set of components in the JVM. Each component is identified by its name (for example: gc, compiler, threads, etc). The set of components can be changed in the source code as required. A component does not have to correspond to a particular part of the JVM, but could also identify a topic of interest (for example gcpause or inlining). Logging can be enabled or disabled for a specific component, and logging can be redirected to file based on the component.

Levels

Each log message has a logging level associated with it. The available levels are error, warning, info, debug and trace in increasing order of verbosity. For each component, a logging level can be selected to control the amount of information from that component.

Decorations

Logging messages can be decorated with information about the message. Here is a list of the possible decorations:

• level – The logging level
• component – The component where the message originated
• timestamp – Time since the start of the JVM in seconds and milliseconds (e.g., 6.567s)
• datestamp – Current time and date
• millis – The same value as generated by System.currentTimeMillis()
• millisstart – Milliseconds since the JVM started
• nanos – The same value as generated by System.nanoTime()
• nanosstart – Nanoseconds since the JVM started
• pid – The process identifier
• threadid – The thread identifier

The active set of decorations can be controlled by the user. The same active set is used for all components. The default set of decorations is: component, level, and timestamp since start of VM. Decorations will be prepended to the log message:

[gc][info][6.456s] Old collection complete

Command-line options

There will be single set of command-line options to control logging from all components of the JVM. The following command-line options exists:

-Xverbose:<component>[=<level>],<component>[=<level>],...

This will set the logging level of the specified components. By default, each enabled component has a logging level of info. There is a meta-component called all to simplify the enabling of all components.

-Xverboselog:<filename>
-Xverboselog:<component>=<filename>,<component>=<filename>,...

This will redirect the output from a component to the specified filename.

-Xverbosedecorations:<decoration>,<decoration>,...

This sets the active decorations for all log messages.

File rotation

When redirecting logging to a file, file rotation will be implemented in a fashion similar to the current GC log files.

Enabling at runtime

Logging can be enabled at runtime through Diagnostic Commands (the jcmd utility). Everything that can be specified on the command line can also be specified dynamically with Diagnostic Commands.

JVM interface

In the JVM a new Log class will be created with an API with functionality similar to:

Log::warning(LogComponent comp, const char* format_string, ...)
Log::info(LogComponent comp, const char* format_string, ...)
Log::debug(LogComponent comp, const char* format_string, ...)

Log::message(LogComponent comp, LogLevel level,
             const char* format_string, ...)

bool Log::enabled(LogLevel level, LogComponent comp)
LogLevel Log::getLevel(LogComponent comp)

Performance

The different log levels will have guidelines that define the expected performance overhead for the level. For example: “error and warning level shouldn’t affect performance; info level should be acceptable for production; debug and trace levels do not have performance requirements.”

Backward compatibility

The JVM already has a number of different flags to control logging. It is a goal to continue to support these as much as possible (at least for some time). The current flags should be mapped to the new flags as much as possible. In some cases this may not be possible and we will have to consider them on a case-by-case basis.

Future extensions

In the future, it may make sense to add a Java API for writing log messages to this infrastructure, for use from classes in the JDK.

Initially, only two backends will be developed: stderr and file. Future projects could add other backends. For example: syslog, Windows Event Viewer, socket, etc.

Open issues

• Should decorations be surrounded by something else than [] to make it easier to parse the output?
• Should the component namespace be hierarchical? For example gc.g1, compiler.c1.inlining, etc.
• What is the exact format of the datestamp and timstamp decorations? ISO 8601 is proposed.
• Using __FILE__ / __LINE__ for message ids is problematic since these changes between releases. Can we find a better solution?
• If we have a message id, we should also add that as a possible decoration.

Testing

It is extremely important that logging in itself does not cause any instabilities, thus extensive testing is required.

Functional testing will have to be done by enabling certain log messages and checking for their presence on stderr or files.

Because it will be possible to dynamically enable logging, we need to stress test this by continuously enabling and disabling logging while running applications.

Risks and Assumptions

The design outlined above may not satisfy all uses of logging in the JVM today. If that is the case, the design will have to be revisited.

Impact

• Compatibility: Log message formats will change and possibly the meaning of some JVM options.
• Security: File permissions need to be verified.
• Performance/scalability: Performance will be impacted if lots of logging is enabled.
• User experience: Command-line options will change. Logging output will change.
• I18n/L10n: Log messages will not be localized or internationalized.
• Documentation: The new options and their usage will have to be documented.