Don’t Force Premature Processing in Your Logging Statements

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.)


One thought on “Don’t Force Premature Processing in Your Logging Statements

  1. I tend to lean the other way a bit – the extra lines that come from wrapping every log statement in an if block tend to clutter the code and discourage logging. I prefer to not make the log.debug conditional, wrapping it only when it’s clearly doing something expensive. I actively remove the conditionals when I see it on code like log.debug(“Finished processing”), or log.debug(“Processed records: “+records.size()).

Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s