Not logging could be expensive

We don't mind to pay a fair price in terms of execution time and storage when logging. But if we still have to pay a substantial price even when the logging is off, we could start to wonder about the quality of our logging system.

In the C/C++ world is relatively easy to keep such unwanted cost limited, using low level mechanism as macros and defines. Things are less immediate in the Java world, still we can achieve good results, if the logger is designed properly, as SLF4J shows.

There is a tiny cost that we can't avoid to pay for each logging call, regardless if the logging is currently enabled for the severity associated to the message or not, and that is the actual cost to check it. It looks quite unavoidable, if we want to keep the log configurable at execution time, and in any case it is just a cheap read and compare operation, so we could usually live with it.

But let's think to a case like this:

SomeComplicatedStuff scf;
// ...
log.debug("The value is: " + scf);

SomeComplicatedStuff is some class that provides an expensive toString() method. We don't mind to pay for its huge cost when debugging, but notice that firstly we build the message, implicitly calling SomeComplicatedStuff.toString() and only later, inside the logging method, we check if we actually should log it. Doesn't matter whether logging is active or not, we still pay for the call to the SomeComplicatedStuff toString() method.

A solution is duplicating the check on the log status:

SomeComplicatedStuff scf;
// ...
if(log.isDebugEnabled())
    log.debug("Log config file: " + logConfigFile);

It works, but this code is painful to write and maintain. It would be better to move the check in the logging methods and delay the string building after the check. Good news is that is the SLF4J approach. Bad news is that we have to rework the way the parameters are passed to the logging methods.

In the case above we were passing a String, created joining a constant one and a variable generated calling implicitly SomeComplicatedStuff.toString(). The logging method can't do anything to avoid the cost of calling toString(), it is just too late. We should have a way to delay the creation of the String to be logged after. The SLF4J decision is to design these methods like simplified String.print(). They have only one tag in the destination string, a couple of opening/closing curly brackets:

SomeComplicatedStuff scf;
// ...
log.info("Log config file: {}.", logConfigFile);

Doesn't look too bad, after all, but there are a couple of caveats.

1) Primitive values can't be passed to the logging methods.

This usually is a minor issue, if we are not afraid of the price of wrapping a primitive in an object. Besides, in Java 5 and above, autoboxing shields the process. Only if you are working with an ancient Java version you are forced to explicitly wrap your primitive value by the relative wrapper class.

2) No more than two objects can be passed as parameter to the logging string.

At first sight this look awful, but we can use the fact that Java arrays are objects, and pass all the objects that we want to be logged in a single array instance:

SomeComplicatedStuff scf1, scf2, scf3;
// ...
log.info("Values: {}, {}, {}", new Object[] {scf1, scf2, scf3} );

Not the most elegant piece of code ever seen, and even a bit counterintuitive, but it works.

Bear in mind that we get this behavior only when just one Object array is passed to a logger method. If a String and two Object arrays are passed, they are seen a two unrelated variables, and as such printed.