Not another logger!

Java is not short of logging libraries: Log4J, SLF4J, JBoss Logger Manager, Flogger, Apache Commons Logger, Logback plus probably many more I've not heard of. There is the also much unloved java.util.logger (or JUL) which is part of Java since v1.4. Even with all these options I've been thinking that we need a new logger.

Step away from the pitch fork and hear me out.

Many of these libraries were created to address a particular concern, primarily performance:

• Avoiding array allocation or auto-boxing causing memory churn,
• IO performance to console or file,
• Asynchronous execution,
• Low/zero garbage.

With all these other libraries it's a really crowded space and it doesn't help with minimal microservices. Low/zero garbage would require a total re-write and if that's a concern stick with Log4J v2, but we can address the others... so I did: dansiviter.uk:juli.

Oh no, not another logging framework I hear you groan... well, kinda, but first lets see it in action.

Spring Clean

It's March, so what better time to clean up your code. The current way of using JUL would typically look something like this:

var log = Logger.getLogger(getClass().getName());
if (log.isLoggable(Level.INFO)) {  // <- needed to avoid array initialisation and auto-boxing
  log.log(Level.INFO, "Hello {0}", "world");  // Grrr, can't use #info(...) with params!?
}

This could be simplified to look like this:

var log = LogProducer.log(MyLog.class);
log.hello("world");

What is this heresy?! Well, I've created an interface which, via annotation processing, creates an implementation that delegates to JUL but layers on the #isLoggable(...) call automatically to avoids the dreaded array initialisation and auto-boxing unless it's strictly needed.

@Log
public interface MyLog {
  @Message("Hello {0}")
  void hello(String str);
}

To verify if we get a performance hit I wrote a small JMH benchmark comparing the two ways except forcing both auto-boxing and array initialisation in the scenarios:

Benchmark                                          Mode  Cnt      Score       Error  Units
LogBenchmark.legLog                               thrpt   25  27921.784 ±  1280.815  ops/s
LogBenchmark.legLog:Used memory heap              thrpt   25  26950.054 ±  8478.381     KB
LogBenchmark.newLog                               thrpt   25  40111.066 ±  1170.407  ops/s
LogBenchmark.newLog:Used memory heap              thrpt   25  25288.212 ± 10124.257     KB

Figures are based on my i7-1065G7 using Docker for Desktop so are purely indicative, however the new approach gives both a ~44% increase in throughput and a ~6% decrease in memory usage. I should mention that on repeat runs I did see some cases where memory usage was higher but throughput was consistently around 40% improvement.

This is great start, but we can go further.

Asynchronicity

Every single implementation of java.util.logger.Handler provided with Java is synchronous; it puts IO directly within the critical path of execution. Log4J and Logback have asynchronous implementations to decouple this and speed up the code, so why can't JUL? So, I created uk.dansiviter.juli.AsyncHandler to address this.

There is a concrete implementation of this which delegates to java.util.logging.ConsoleHandler. So I created some more JMH tests:

Benchmark                                               (handlerName)   Mode  Cnt      Score       Error  Units
ConsoleHandlerBenchmark.handler                        ConsoleHandler  thrpt   25  31041.836 ±  7986.031  ops/s
ConsoleHandlerBenchmark.handler:Used memory heap       ConsoleHandler  thrpt   25  37237.451 ± 15369.245     KB
ConsoleHandlerBenchmark.handler                   AsyncConsoleHandler  thrpt   25  85540.769 ±  6482.011  ops/s
ConsoleHandlerBenchmark.handler:Used memory heap  AsyncConsoleHandler  thrpt   25  41799.724 ± 16472.828     KB

For a ~12% increase in memory usage amount of memory usage we get a ~175% increase in throughput is great, however it's important to have some context with these results. This uses java.util.concurrent.Flow under the hood and it uses a default buffer size of 256. To prevent log messages being dropped backpressure is handled by blocking when the buffer is full. Therefore, buffer saturation will slow it down, hence the increased variance. However, in reality saturation will rarely occur and this will decouple IO from the log message creation improving performance. In smaller, less 'chatty' tests, massive (often incalculable) improvements are common:

x50 - Sync=PT0.018177S, Async=PT0S (NaN%)  // <- async so fast it didn't even register
x100 - Sync=PT0.0317765S, Async=PT0S (NaN%)  // <- ...and again
x200 - Sync=PT0.0644191S, Async=PT0.0009579S (6725.03400%)
x400 - Sync=PT0.1168272S, Async=PT0.0450558S (259.294500%)  // <- dramatic slow down
x800 - Sync=PT0.2164862S, Async=PT0.1705798S (126.912000%)
x1600 - Sync=PT0.4423355S, Async=PT0.4237862S (104.377000%)  // <- almost parity

See uk.dansiviter.juli.RoughBenchmark for code.

ℹ️ With modern containerised workloads a FileHandler is pretty pointless as they rarely have persistent disks to write to and generally write directly to STDERR/STDOUT or to the log aggregator directly. So I've not created an asynchronous version.

Summary

So, with this logging wrapper and asynchronous handlers I can have my cake an eat it:

• Cleaner code,
• Performance improvement (often huge!),
• Minimal increase in binary size (~14KB).

However, I feel I should address the title of this post. No, this isn't a new logger, but it does make the existing logger a much nicer experience. Check out the README which explains more about how it's used including exception handling.

I'm already using this with a CDI project which injects instances into the code making unit testing super-simple. I plan on seeing if this plays nicely with JPMS and GraalVM soon for even more leanness.

I'm ready for my lynching now... do your worst!