The Curious Schemer

My transformation into a nagging old man is becoming more and more complete everyday I see something like this sprinkled liberally throughout the code:

// some code
log.debug("The result: " + doSomethingReallyExpensive());
// some code

The reason is that even when the log level is not DEBUG and that string ends up not being used at all, doSomethingReallyExpensive() is still evaluated, its result is still being concatenated with the string “The result: “, only to be discarded soon after. In other words, we’re wasting cycles evaluating something that is not going to be used at all, except in DEBUG mode. I’ve worked in a project where fixing these wasteful premature processing improved the performance by more than 30%.

(This doesn’t apply only to Commons Logging, which I used in the examples in this post. Here’s a similar entry in Log4j FAQ. It’s a general case of Java evaluating a method’s arguments first before executing the method itself. The same applies to C# applications using log4net, for instance.)

Fortunately, fixing it is easy. Just check whether we’re in DEBUG mode first:

if(log.isDebugEnabled()) {
    log.debug("The result: " + doSomethingReallyExpensive());
}

This way, doSomethingReallyExpensive() is only evaluated when it is needed, that is, in DEBUG mode. (Of course, it’s good to check whether doSomethingReallyExpensive() has side effects first! Or else other parts that depends on its side effects may stop working because it is no longer called when we turn off DEBUG. But then again, anybody who relies on the evaluation of logging arguments to get side effects should really be sent to Timbuktu. No, not the real Timbuktu. The one Donald Duck often goes to.)