The JVM has a lot of logging libraries. There's the built-in java.util.logging
package, the venerable log4j project (now log4j2), logback, Scala-specific libraries like scribe, etc.
As a library author, I've long been partial to logging facades, where you write to one API, and can choose which among the multiple "backends" will log the messages.
The idea was pioneered by Apache Commons Logging. slf4j is I think the most popular logging facade these days. I long ago wrote my own facade, mlog
, initially in support of the c3p0 library, but I've used it for many, many projects. I've also wrapped it beneath a concise Scala API that I really like.
JVM logging facades, if written with care, are quite performant in practice. They are not a meaningful bottleneck. Nevertheless, there is a bit of overhead. You call the facade API, bytecode is generated for those calls, which then transform inputs and forward them to a logging library.
I've been intrigued for a while by the possibility in Scala 3 of writing logging facades that eliminate this small bit of overhead. Scala 3 has a souped up inline functionality, by which facade API calls can be transfomed into back-end API calls at compile-time, eliminating any facade overhead at runtime.
I'm building a bunch of "daemon"-style services now, for which logging will be important, so it seemed like a good time to give this a try. The result is called LogAdapter
.
The logging API style I developed for mlog-scala
, which I am very happy with, is to call log
methods directly on logging levels. The messages get routed to "loggers" determined by context (more specifically, by what Scala given
or implicit
values are in scope). For example, I might call:
SEVERE.log("This is bad.")
SEVERE
is a logging level defined in my logadapter
package, but which is not defined in log4j
, the backend I am using.
Although it looks like I'm calling a method on SEVERE
, there is no sign of such a method in the generated bytecode:
236: aload_0
237: invokevirtual #103 // Method logAdapter:()Llogadapter/log4j2/LogAdapter;
240: astore 22
242: aload 22
244: astore 23
246: aload 23
248: invokevirtual #107 // Method logadapter/log4j2/LogAdapter.logger:()Lorg/apache/logging/log4j/Logger;
251: astore 24
253: getstatic #113 // Field org/apache/logging/log4j/Level.ERROR:Lorg/apache/logging/log4j/Level;
256: astore 25
258: aload 24
260: aload 25
262: invokeinterface #119, 2 // InterfaceMethod org/apache/logging/log4j/Logger.isEnabled:(Lorg/apache/logging/log4j/Level;)Z
267: ifeq 284
270: aload 24
272: aload 25
274: ldc #138 // String This is bad.
276: invokeinterface #125, 3 // InterfaceMethod org/apache/logging/log4j/Logger.log:(Lorg/apache/logging/log4j/Level;Ljava/lang/String;)V
The bit of bytecode referencing logadapter
constructs is just a field lookup, which would be necessary even using the logging libraries directly. (Typically logging libraries reference a "logger" cached as a field of an object.) The field lookup is nested behind two accessors, it's like this.logAdapter().logger()
.
While in Java, accessing a logger might mean accessing a static
field directly, in Scala, even using the native libraries, the field lookup would be behind an accessor. So the only additional overhead is the second, inner accessor call. Using a back-end library directly might provoke only a single hit to an accessor. But the cost of the additional accessor call is negligible.
(And, a bit overzealously, the library actually economizes accessor calls on the backend by caching in ways typical library users do not. Note that logger
and Level.ERROR
are looked up once, rather than twice, in the bytecode above, although they are ultimately referred to twice, as in the code snippet below. These accessor calls are likely optimized away by modern JVMs at runtime anyway.)
Beyond looking up the logger, the bytecode refers only to construct of the backend library, org.apache.logging.log4j
constructs in this case. There is no method call on a logadapter.Level
. There are method calls on an org.apache.logging.log4j.Logger
supplying an org.apache.logging.log4j.Level
as arguments.
It's exactly as if we'd called the following methods directly on the log4j2
library (referencing that library's Level.ERROR
, since it does not support a level SEVERE
):
import org.apache.logging.log4j.*
if logger.isEnabled( Level.ERROR ) then logger.log( Level.ERROR, "This is bad." )
Again, since logging facades are not really a performance bottleneck, there's not any spectacular improvement over using mlog
. In informal testing of just the facade — that is, excluding the cost of actual logging, by sending messages at levels below the loggable threshold — I see a roughly 25% improvement using this resolved-at-compile-time facade over resolved-at-runtime mlog
. In practice, the improvement would be even less, because many calls will hit logging IO (or add requests for logging IO to an asynchronous queue), rendering the facades, static and dynamic, a smaller part of the overhead.
Of course one of the benefits of facades — a reason why library authors often choose them! — is precisely because which backend gets hit can be resolved at runtime. If your library will be used as part of a larger application, it's nice if it can be configured to log to the same backend that the larger application will, without having to modify and recompile library code.
But the logadapter facade is so thin, there's very little cost to using it even if its "backend" will be a runtime-configurable facade like slf4j
or mlog
.
And for most applications, it's fine for the logging backend to be chosen at compile time. In which case the (small) runtime performance hit of a facade can be circumvented almost entirely.
LogAdapter
is much simpler and smaller than traditional logging facades, and can be layered on top of them at low cost where that makes sense. I think it will be a pretty good foundation for logging.