Logging is a not a sexy subject but it’s important nonetheless. In the Java world, logging frameworks range from Log4J to SLF4J via Commons Logging and JDK logging (let’s exclude Log4J 2 for the time being). Though different in architecture and features, all of their API look the same. The logger has a method for each log level e.g.:
debug(String message)info(String message)error(String message)- etc.
Levels are organized into a hierarchy. Once the framework is configured at a certain level, only messages logged with the same or a higher priority will be written.
So far, so good. The problem comes when messages contain variables so that they must be concatenated.
LOGGER.debug("Customer + " customer.getId() + " has just ordered " + item.getName() + " (" + item.getId() + ")");String concatenation has a definite performance cost in Java, and whatever the configured log level, it will occur.
For this reason, modern logging frameworks such as SLF4J provide improved signature accepting a message format typed as String and variables as varargs of Object.
In that case, concatenation occurs only when the logger effectively writes.
LOGGER.debug("Customer {} has just ordered {} ({})", customer.getId(), item.getName(), item.getId());Sometimes, however, variables are not readily available but have to be computed explicitly solely for the purpose of logging.
LOGGER.debug("Customer {} has just ordered {}", customer.getId(), order.expensiveComputation());SLF4J doesn’t help there, as the method is evaluated even if the logger decides latter not to write because the framework is configured with a higher priority. In that case, it’s therefore advised to wrap the logger method call inside a relevant priority check.
if (LOGGER.isDebug()) {
LOGGER.debug("Customer {} has just ordered {}", customer.getId(), order.expensiveComputation());
}That has to be done for every expensive method call, so it requires a strong coding discipline and reviews to make sure the wrapping occurs when it’s relevant - but only then. Besides, it decreases readability and thus maintainability. To achieve the same result automatically without those cons, one could use AOP at the cost of extra-complexity.
Comes Java 8 and the Supplier<T> interface which returns a String, so that a method can be created like so:
public void debug(Supplier<String> s) {
if (LOGGER.isDebugEnabled()) {
LOGGER.debug(s.get());
}
}In that case, the get() method is called only when the wrapping condition evaluates to true.
Using this method is as simple as that:
debug(() -> ("Customer + " customer.getId() + " has just ordered " + order.expensiveComputation());Great! But where to put this improved debug() method?
- In the class itself: and duplicate for every class. Really?
- In an utility class: one should add the
LOGGERas the first parameter. Did you say cumbersome? - In the logger: one can create a wrapper and keep a standard logger as a delegate but the factory is
final(at least in SLF4J) and has a lot ofprivatemethods. - In an aspect: back to square one…
That’s the step where things start not being so nice in the Java realm.
What about Kotlin? It comes with extension functions (and properties). This will probably be the subject of a future post since you should adopt Kotlin if only for this feature. Suffice to say that Kotlin can make it look like one can add state and behavior for already defined types.
So debug() can be defined in a aptly named file:
fun Logger.debug(s: () -> String) {
if (isDebugEnabled) debug(s.invoke())
}And calling it really feels like calling a standard logger, only a lambda is passed:
LOGGER.debug { "Customer + " customer.getId() + " has just ordered " + order.expensiveComputation() }As a finishing touch, let’s make the defined function inlined. By doing that, the compiler will effectively replace every place the method is called with the method in the bytecode. We get the readable syntax benefit and avoid the overhead of un-wrapping the lambda at runtime:
inline fun Logger.debug(s: () -> String) {
if (isDebugEnabled) debug(s.invoke())
}Note that it can still be called in Java, albeit with a not-so-nice syntax:
Slf4KUtilsKt.debug(LOGGER, () -> "Customer + " + customer.getId() + " has just ordered " + order.expensiveComputation());Also note that Log4J 2 already implements this feature out-of-the-box.
At this point, it’s simple enough to copy-code the above snippet when required. But developers are lazy by nature so I created a full-fledged wrapper around SLF4J methods. The source code is available on Github and the binary artifact on Bintray so that you only need the following dependency to use it:
<dependency>
<groupId>ch.frankel.log4k</groupId>
<artifactId>slf4k-api</artifactId>
<version>1.0.0</version>
</dependency>