Replacing logging APIs with the Java System Logger

Logging in the JVM, unfortunately, has never become fully standardized, resulting in a proliferation of logging frameworks and causing a problem for library authors who want to include logging facilities in their libraries.

Given how Java has had, since Java 9, a System.Logger right in the standard library, I decided to investigate whether that has the potential to change things, or whether it’s just another logging API in a growing list of options on the JVM.

But before we get to that, let’s discuss how we got ourselves in this situation.

A quick history of logging in the Java world

The first solution to the problem was JUL (the java.util.logging package), released with Java 1.4 back in early 2002! To understand why JUL didn’t catch on, check out the StackOverflow question Why not use java.util.logging?.

Basically, JUL used to be slow, missed basic features and, most importantly, it’s not just a logging API but a full framework. It’s possible to create your own Handler and forward the implementation to another framework (this is how SLF4JBridgeHandler works), but that has an overhead that may not be acceptable where performance is important.

A little bit later, the Apache Foundation released another logging API, Apache Commons Logging which for some reason didn’t become very popular (though you might see older libraries using it from time to time), likely due to it being too complex and having class loading issues, apparently.

The next solution, which is still in widespread use as of 2022, was SLF4J (Simple Logging Facade for Java), first released in April 2005. The slf4j-api jar contains no logger implementation because SLF4J was designed, as the name says, to be just a façade for a backing implementation framework. This solves the problem of multiple libraries wanting to use their own favourite frameworks for logging, while addressing issues with the design of JUL which made things harder and slower than they needed to be.

When a library logs using the SLF4J API, it doesn’t know or need to care about which framework will be used by the final application. Because it’s just an API, it has very little need to evolve with time, there’s hardly a lot that can change in a logging API over the years (though implementations are free to evolve to support new features and performance improvements). Because of the slow and backwards-compatible evolution of the SLF4J API in practice, even today it’s still probably possible to use a library written in 2006 that used SLF4J for logging, even if we use the very latest version of an implementation framework at runtime.

Applications can then choose between several implementation frameworks (which only need to be available at runtime), the most popular of which are Logback and Apache Log4j2.

According to qos.ch, as of December 2021, 48% of Java projects on mvnrepository use Logback, 37% use Log4j1, and 15% use Log4j2. If you’re still using Log4j1 implementation (which has reached End-Of-Life), you’re strongly advised to upgrade to the drop-in replacement, reload4j, which forks Log4j1 to fix important security vulnerabilities (not directly related to log4shell). Needless to say, if you use Log4j2, make sure you don’t have any projects still relying on versions affected by log4shell (check log4j2’s latest version here).

This state of matters remained mostly unaltered, except perhaps at Google, which has its own logging API, flogger (which appears to be the main influence for the upcoming slf4j 2) until Java 9 was released in 2017, when JEP 264: Platform Logging API and Service was introduced.

This API is centered around the System.Logger interface and is available in the java.base module, as opposed to java.logging.

This new API is still mostly unknown in the Java world, so let’s have a look at it and try to understand why it was created and when it should be used… and, importantly, whether it is the final answer to logging standardization in the JVM!

Understanding the Java Platform Logging API and Service

JEP 264 has a few curious, seemingly contradictory statements. For example, it lists as one if its goals:

• Be easily adoptable by applications which use external logging framework, such as SLF4J or Log4J.

Great, so it looks like it can be a substitute for SLF4J, right?!

However, it also lists this as a non-goal:

• It is not a goal to define a general-purpose interface for logging. The service interface contains only the minimal set of methods that the JDK needs for its own usage.

The Motivation section clarifies things a little bit more.

• The proposed service enables applications to configure the JDK to use the same logging framework as the application…
• The application would continue to use the facade provided by the logging framework it is using. The LoggerFinder service makes it possible to configure the JDK to use that same framework.

Ok, so it looks like the idea is to use this API in the JDK itself, not in applications.

However, one has to ask: why would I keep using SLF4J, forcing an additional library on users of my own library, when I could easily switch to the standard library’s System.Logger instead, specially given its API is quite nice, as we’ll see soon. As a bonus, it even defaults to sending messages to JUL if the java.logging module is present!

I think the JEP authors anticipate people will want to do that when they say, in the Description section:

• An implementation of the LoggerFinder service should make it possible to distinguish system loggers (used by system classes from the Bootstrap Class Loader (BCL)) and application loggers (created by an application for its own usage).

So, I think we’re allowed to use that in our own libraries!

The System.Logger API

To obtain a System.Logger instance, the java.lang.System#getLogger method is used.

Using it is straightforward, as this example shows:

package util;

import java.lang.System.Logger;
import java.util.Arrays;

public class Testing {
    private static final Logger logger = System.getLogger(Testing.class.getName());

    public static void main(String[] args) {
        logger.log(Logger.Level.INFO, "Started main with arguments: {0}",
                Arrays.toString(args));
    }
}

Running it:

▶ java util.Testing hello world
Jan. 15, 2022 12:31:12 PM util.Testing main
INFO: Started main with arguments: [hello, world]

Nice! The formatting String, unlike with slf4j, is based on java.text.MessageFormat, meaning it has richer options available for formatting numbers, dates and times.

Unlike slf4j format strings, MessageFormat expects at least an index in each placeholder, therefore instead of something like ("Name: {}, Age: {}", name, age), you need to do ("Name: {0}, Age: {1}", name, age).

Notice also that you would normally want to avoid making logging calls that allocate an object, as above, with the Arrays.toString(args) call, because if the logging level is not enabled, that would just be wasteful.

To fix that, we can do as with slf4j and check if the log level is enabled first:

if (logger.isLoggable(Logger.Level.INFO)) {
    logger.log(Logger.Level.INFO, "Started main with arguments: {0}",
            Arrays.toString(args));
}

Another option would be to use a lambda to supply the message. That would still allocate memory for the lambda, but it might be better than allocating the objects required to form the message directly:

logger.log(Logger.Level.INFO, () ->
        "Started main with arguments: " + Arrays.toString(args));

In this case, we lost the nice formatting String, though. We could, of course, use the MessageFormat class directly (even if in this example, that would be mostly pointless):

logger.log(Logger.Level.INFO, () ->
        MessageFormat.format("Started main with arguments: {0}", Arrays.toString(args)));

Unfortunately, it seems that the Java compiler won’t check usages of the format String, which is a let-down compared to other languages like Rust, where the format String is fully checked by the compiler.

Trying to do something like this results in an incorrect message being logged, but no warnings at compile-time or runtime (tested on Java 11 and 17):

logger.log(Logger.Level.INFO,
        // incorrectly expecting two arguments, but given only one!
        "Started main with arguments: {0} and {1}",
        Arrays.toString(args));

Result:

▶ javac util/Testing.java

▶ java util.Testing hello world
Jan. 15, 2022 1:05:32 PM util.Testing main
INFO: Started main with arguments: [hello, world] and {1}

Maybe one day.

The available logging levels are very similar to SLF4J’s:

One last noticeable thing about this API is that all logging methods may take a ResourceBundle as an argument, in which case messages are expected to be keys to internationalized objects (i.e. the actual message will depend on the user’s Locale).

To try that, we can add a resource to the classpath like this:

# file: messages.properties
main.started = Started main with arguments: {0}

Then, change the Java code to:

var bundle = ResourceBundle.getBundle("messages");

logger.log(Logger.Level.INFO, bundle,
        "main.started", Arrays.toString(args));

Now, running works as before:

▶ java util.Testing hello world
Jan 15, 2022 2:05:15 PM util.Testing main
INFO: Started main with arguments: [hello, world]

But if we add a more Locale-specific file to the classpath, then it will use that instead:

# file: messages_en_AU.properties
main.started = Good day mate, starting with: {0}

Running again (my locale happens to be en_AU):

▶ java util.Testing hello world
Jan 15, 2022 2:17:07 PM util.Testing main
INFO: Good day mate, starting with: [hello, world]

More about formatting Strings

The MessageFormat class has lots of examples of how to use formatting Strings, but I thought it would be useful to show some common patterns here.

To format numbers is as easy as it gets:

logger.log(INFO, "π is equal to {0,number,#.#########}..., " +
        "or approx. {0,number,#.###}", Math.PI);

Result:

Jan 15, 2022 3:11:19 PM util.Testing main
INFO: π is equal to 3.141592654..., or approx. 3.142

Formatting date and time:

var eventTime = Instant.parse("2021-02-21T10:11:12Z");
logger.log(INFO, "An event occurred on the {0,date} at {0,time}", Date.from(eventTime));

Result:

Jan 15, 2022 3:16:35 PM util.Testing main
INFO: An event occurred on the 21 Feb 2021 at 11:11:12 am

Notice that in the above example, we had to convert Instant to Date. That’s because the date and time format instructions are based on DateFormat, which uses the older Java API for date-time.

Finally, there’s also a choice format type which is based on ChoiceFormat. It allows choosing one item to log out of some given options. Each option is an interval between the previous choice and the given number. The choice is separated from the value to be logged by a #, and options are separated by |.

A pattern like {0,choice,0# {0} | 2# fizz | 3# {0} | 4# buzz} could be a starting point to implement FizzBuzz (handling multiples of 15 requires some extra work)!

The first choice matches 0 (and anything smaller than that because it’s the first choice) up to the next choice, 2 (exclusive, so < 2). The result in this case is the recursive pattern {0}, which just prints the argument.

The second choice matches anything equal to or greater than 2 but smaller than the next choice, 3 which results in the literal string fizz. The next choice matches >= 3 && < 4 and again, prints {0}, or the argument itself.

The last choice matches anything equal to or above 4 and results in the literal buzz.

A simpler example:

package util;

import java.lang.System.Logger;

import static java.lang.System.Logger.Level.INFO;

public class Testing {
    private static final Logger logger = System.getLogger(Testing.class.getName());

    public static void main(String[] args) {
        logger.log(INFO, "You passed{0,choice,0# no |1# one |1< {0} }" +
                "argument{0,choice,0#|1<s}", args.length);
    }
}

Sample runs:

▶ java util.Testing
Jan 15, 2022 3:33:23 PM util.Testing main
INFO: You passed no argument

▶ java util.Testing 1
Jan 15, 2022 3:33:26 PM util.Testing main
INFO: You passed one argument

▶ java util.Testing 1 2
Jan 15, 2022 3:33:29 PM util.Testing main
INFO: You passed 2 arguments

▶ java util.Testing 1 2 3
Jan 15, 2022 3:33:31 PM util.Testing main
INFO: You passed 3 arguments

Configuring with JUL (default implementation)

Because I’ve been running the Java code with the simple java command, without using the Java module system, the JUL framework is available to the application, and that’s what is being used for logging in the previous examples without requiring any configuration.

However, we’re free to configure JUL to confirm that it is actually being used.

Create a file called jul.properties with the following contents:

handlers= java.util.logging.ConsoleHandler
.level= INFO
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format = %4$s: %5$s [%1$tc]%n

The format property uses the old format specified by the java.util.Formatter class.

Now, when running the program, specify the java.util.logging.config.file system property to use this config file:

▶ java -Djava.util.logging.config.file=jul.properties util.Testing 10
INFO: You passed one argument [Sat Jan 15 16:14:37 CET 2022]

To log only the message itself, use the format: %5$s%n.

As you would expect, changing the log level to WARNING, for example, results in no log message being printed.

Changing the logger framework implementation

The logger implementation is found by the System.LoggerFinder service.

How a particular framework can be integrated using this service depends on each framework.

Log4j2

Log4j2 has a module, log4j-jpl, that is supposed to add support for the JDK System.Logger. By placing that in the classpath along with log4j-core and log4j-api, logs from the System.Logger should be handled not by JUL, but by Log4j2.

To test it, I created a simple log4j2.xml config file like this:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Running my application, however, doesn’t do exactly what I expected it to do.

▶ java -cp "libs/*":. util.Testing 10 20 30
16:37:39.624 [main] INFO  util.Testing - You passed{0,choice,0# no |1# one |1< {0} }argument{0,choice,0#|1<s}

Oops! While Log4j is handling the logging now (you can see because of the pattern being used), the log4j2 implementation is not handling the format string correctly so that it works as specified by the API method I am using, log(System.Logger.Level,String,Object...). It expects the formatting String to use log4j’s formatting features instead (that one that lets you do things like {jndi:...}, as you may have heard), which would tie our program to log4j, defeating the purpose of using a logging API.

To get things working properly, the only way I found was to forget about log4j-jpl and use log4j-jul instead. This module does not integrate with System.Logger, but with JUL itself, so it lets JUL parse the format string before logging.

Now, running my application does work as expected (notice that we have to configure JUL to use log4j below by passing the -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager argument):

▶ java -cp "libs/*":. -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager util.Testing 10 20 30
18:58:23.084 [main] INFO  util.Testing - You passed 3 arguments

Logback

As far as I can see, Logback has not added any support for System.Logger yet. To use it, we’ll need to follow the same strategy as with Log4j and redirect JUL to it.

So, the first thing to do is to get the slf4j-api, logback-core and logback-classic jars in the classpath, as well as the JUL to slf4j bridge, jul-to-slf4j.

After that, we need a logback configuration file like this, for example (call it logback.xml):

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Finally, we need to change the JUL config file to use org.slf4j.bridge.SLF4JBridgeHandler as a handler:

#handlers= java.util.logging.ConsoleHandler
handlers = org.slf4j.bridge.SLF4JBridgeHandler

Running the application:

▶ java -cp "logback-libs/*":. -Djava.util.logging.config.file=jul.properties util.Testing 1 2 3
19:16:10.587 [main] INFO  util.Testing - You passed 3 arguments

Framework Performance Comparison

This is not a very scientific benchmark! Beware that performance may vary widely depending on actual usage patterns.

To test the performance of each of the logging frameworks shown above, i.e. the default JUL implementation (available in the JDK), Log4j2 and Logback, I have just the ideal project laying around!

It is an application that encodes phone numbers into easy-to-remember words, which I wrote about previously. The application was written as part of a performance comparison between Java implementations, and also against other languages implementations, but because in the original form of the problem, printing results became a bottleneck for large inputs, that will be ideal to test which frameworks perform better in a somewhat realistic test where logging performance is crucial!

See the full implementation here.

Here is the main function of my original solution, which just printed straight to System.out (faster implementations I did later used a buffer to minimize IO operations):

final class Main {
    public static void main( String[] args ) throws IOException {
        var words = new InputParser( WordsInputCleaner::clean )
                .parse( new File( args.length > 0 ? args[ 0 ] : "tests/words.txt" ) );

        var encoder = new PhoneNumberEncoder( words );

        new InputParser( PhoneNumberCleaner::clean )
                .parse( new File( args.length > 1 ? args[ 1 ] : "tests/numbers.txt" ) )
                .forEach( phone -> encoder.encode( phone, System.out::println ) );
    }

}

The important line is at the end:

encoder.encode( phone, System.out::println )

The callback takes an Item record that looks like this:

record Item(String original, String result) {

    Item( String result ) {
        this( result, result );
    }

    @Override
    public String toString() {
        return original + ": " + result;
    }
}

Notice that the toString() method is implicitly being called, as System.out.println is being called with Item instances as arguments… To test logging, we would want to avoid that and let the logging framework handle the format String instead.

Therefore, I ended up with the following logger-based implementation:

var logger = System.getLogger("Main");

// ...

encoder.encode(phone, item -> {
    logger.log(INFO, "{0}: {1}", item.original(), item.result());
}));

Very straightforward.

I also had to do a little bit of work to adapt the benchmarks and configure the loggers to use file appenders.

See the full commit here.

I used bufferedIO=true in Log4j2, but attempting to enable Logback immediateFlush caused it to fail the tests (I assume it was failing to flush all output by the end of the process, but I didn’t check that). I also tried using async loggers, which made Log4j2 slightly faster (just about enough to catch up with JUL) and Logback also a tiny bit faster, but that did not change the results significantly enough for me to include the results here. Feel free to run the benchmarks yourself and tweak configuration to see if you get different results.

Here’s the results of running the benchmark (x-axis is input size, y-axis is time, so lower is better):

All benchmarks were run on my MacBook Air with processor 1,1 GHz Quad-Core Intel Core i5, 8GB of RAM, using Java version openjdk 17.0.1 2021-10-19 LTS. The latest stable versions of all libraries, as of writing, were used.

Logback has much better performance for this limited benchmark, but JUL was not far behind and actually managed to beat Log4j2.

For small inputs, it may be surprising to see that JUL was actually the fastest of all… that’s probably because for small inputs, the smaller overhead due to not requiring any external libraries at all dominates over the actual performance of the logging implementation (yes, this is pure speculation).

I was curious to know if there would be any difference if I used the traditional slf4j-api with the standard bindings to Log4j2 and Logback, so I changed the code again to log via slf4j-api, not System.Logger.

Here’s the result:

This run used the slf4j-api, not System.Logger

Interestingly, there was no change in the performance for any of the frameworks. The two charts use the same scale and look nearly identical.

The raw data is available on a public Google Docs spreadsheet.

A lot more could be measured (async loggers, disabled logger overhead, heavy message patterns, multi-threaded logging), but at least with the results we get with this small comparison, it seems clear that JUL is performing in the same ballpark as the big frameworks, though Logback is ahead of either JUL or Log4j2.

The Log4j2 Website has a detailed performance comparison where it compares a lot more different cases and, unsurprisingly, Log4j2 comes ahead. On another benchmark I found at loggly.com, Log4j2 and Logback show very similar performance, but JUL is much slower… that was from 2017 though, so it’s likely that JUL has improved by a large margin since then. Anyway, take the results I found here with a grain of salt and run your own benchmarks.

Conclusion

In this blog post, we saw how the Java 9+ System.Logger API can be used to implement logging in any JVM library without having to rely on any external libraries. The API is just about as comfortable to use as slf4j-api.

Configuring System.Logger to use either JUL, Logback or Log4j2 is fairly simple, hence most JVM applications should be able to benefit from it as long as they are using Java 9+.

Given the System.Logger API even seems to have no performance penalty at all when compared with using the slf4j-api, I see absolutely no reason to not use it when you don’t know what Logging API the consumer of your library is likely to be using, which is the case for all open source libraries.

Furthermore, I would say that some FUD that has been spread about usage of JUL as an implementation framework might no longer be relevant, even if much of it used to be true. Sure, JUL is not the fastest logging framework on the JVM, but it certainly has decent enough performance to be a respectable choice, specially given it is the default option in the JDK.

Acknowledgments

Thanks to @glaforge on Twitter for bringing the System.Logger to my attention.