JEP 158: Unified JVM Logging

AuthorsStaffan Larsen, Fredrik Arvidsson
OwnerFredrik Arvidsson
Created2012/02/27 20:00
Updated2014/10/30 23:01
TypeFeature
StatusTargeted
Componenthotspot / svc
ScopeImplementation
Discussionserviceability dash dev at openjdk dot java dot net
EffortM
DurationM
Priority2
Reviewed byMikael Vidstedt
Endorsed byMikael Vidstedt
Release9
Issue8046148

Summary

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

Goals

Stretch goals:

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

Loggers

The logging framework defines a set of loggers in the JVM. Each logger is identified by its name (for example: gc, compiler, threads, etc). The set of loggers can be changed in the source code as required. Loggers are hierarchical to their nature. Sub loggers are identified by having the parent loggers name followed by an underscore and then the sub loggers name (for example: gc_g1, gc_g1_init, etc).

Configuration for loggers are inherited by sub loggers if not explicitly overridden. A logger 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 logger, and logging can be redirected to stdout, stderr or a file based on the logger.

Levels

Each log message has a logging level associated with it. The available levels are disabled, error, warning, info, debug and trace in increasing order of verbosity.

For each logger, a logging level can be configured to control the amount of information output from that logger. The alternative disabled disables logging completely. Logging levels are inherited by sub loggers.

Decorations

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

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

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

Adapters

Adapters are logging output backends. There are three types of adapters currently:

A logger can have zero or more adapters assigned. Only one adapter of each kind can be assigned, except for the file adapter where multiple fileadapters with unique filenames can be used. Adapters are inherited by sub loggers if not explicitly overridden. Override will take place as soon one adapter is assigned to a sub logger.

Some adapters may require extra configuration. Adapter configuration parameters are passed by appending {<parameter>,<parameter>,...} to the adapter name. Adapters implement a simple interface and more types of adapters could easily be added in the future.

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:

-Xlog:[<logger>=]<level>,<logger>=<level>,...

This will set the logging level of the specified loggers.

-Xlogadapter:<adapter>,<adapter>,... 
-Xlogadapter:<logger>=<adapter>[{<param>:<param>,...}],
     <logger>=<adapter>[{<param>:<param>:...}], ...

By omitting the logger name identifier all loggers will be configured to use the same adapter(s). Same logger can be specified multiple times to assign multiple adapters.

-Xlogdecorations:<decoration>,<decoration>,...

This sets the active decorations for all log messages on all loggers.

Examples:

Disables all logging except for logger _gc_g1_ for which level trace is set.

-Xlog:disabled,gc_g1=trace

Sets _vm_init_ log to use debug and gc log to use trace, default level will still be warning for all other loggers.

-Xlog:vm_init=debug,gc=trace

Disables all logging.

-Xlog:disabled

Sets _vm_init_ logger to log to stdout.

-Xlogadapter:vm_init=stdout

Sets vm_init to log on stdout, gc to log to a single file named gclog.txt.

-Xlogadapter:vm_init=stdout,gc=gclog.txt

Sets logger compiler to log to a rotated file named compiler.log using 5 files in rotation with a size of 10 megabytes.

-Xlogadapter:compiler=compiler.log{5:10M}

Sets log decorations to be logger, level, timestamp, tid and pid.

-Xlogdecorations:logger,level,timestamp,tid,pid

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. Since diagnostic commands are automatically exposed as MBeans it will be possible to use JMX to change logging configuration in runtime.

JVM interface

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

Logging:
Log& Log::log(const Log &logger, const LogLevel &level, const char* format, ...);
Log& Log::<logger>(const LogLevel &level, const char* format, ...);
Log& Log::<logger>.<level>(const char* format, ...);

The default behaviour is that all log messages will be committed to the adapter(s) immediately when the call is made to the log method. One call -- one entry. All Log methods return a this reference to the logger for chaining purposes.

Buffered logging:
Log& Log::<logger>().begin_transaction();
bool Log::<logger>().commit_transaction();

By calling begin_transaction() on a logger it is possible to have multiple calls to the log methods generating one single entry in the log. Multiple calls -- one entry. The transaction is comitted by calling commit_transaction method on the logger. The level of the committed entry will be the logger's configured level. Level configured for the logger will still be in play during transaction. The begin_transaction() method returns a this reference for chaining purposes.

Level information:
LogLevel Log::<logger>.level();  
bool Log::<logger>.is_<level>();
bool Log::<logger>.is_level(const LogLevel &level);

To avoid running code that produces data only used for logging it is possible to ask a logger about what log level it currently is configured as. The is_() and is_level(LogLevel) methods will return true if configured level is >= request level.

Examples:
long int time = 1000;
Log::log(Log::vm_init(), LogLevel::info(), "Init took %lu ms to complete.", time);

const char* method = "run";
Log::gc(LogLevel::error(), "The method %s should never be called.", method);

int count = 155;
Log::compiler().error("Only %d bytes are available.", count);

if (Log::vm_init().is_debug()) {
    Log::vm_init().begin_transaction();
    for (int i = 0; i < 500; i++) {
      Log::log(Log::vm_init(), LogLevel::debug(), "Iteration: %d\n", i);
    }
    Log::vm_init().commit_transaction();
 }

 Log::gc().begin_transaction()
   .error("Error in file %s", "__FILE__").info(" at line %d ", __LINE__)
   .commit_transaction();

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." Running with logging disabled should have as little performance impact as possible. It will always cost to log though.

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 three backends will be developed: stdout, stderr and file. Future projects could add other backends. For example: syslog, Windows Event Viewer, socket, etc.

Open issues

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.

The logging framework will be tested using unit tests.

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