Friday, May 18, 2007

When to call isDebugEnabled() before writing debug messages

When using a logging framework like log4j most developers never check whether debug is enabled before writing a debug message or always makes the check. The theory behind it is to prevent unnecessary string concatenations if debug messages are disabled, which is the case most of the times on production environments.

logger.debug("Saved order successfully. Order ID : " + order.getId() +
" items in order " + order.getItems().size())
;

In the above case there is a new string object created by concatenating all the parameters before making the call to debug method. This is done regardless of debug is enabled or not which will be a unnecessary performance overhead if debug is disabled.

if( logger.isDebugEnabled()){
logger.debug("Before saving the order");
}

In the above code section the if condition is not necessary as there is no String concatenations involved and ends up adding two redundant lines of code.

Therefore the rule would be to do a isDebugEnabled check only if there is any String concatenation involved in the call to debug. This seems to be obvious but developers somehow keep getting this wrong.

Don' forget to click the +1 button below if this post was helpful.

10 comments:

Mark Derricutt said...

I could see this being a useful pattern for closures, where the closure could just be the string concat.

i.e. logger.debug({"Saved " + order.getId()});

The closure/block would only be evaluated if isDebugEnabled() is true...

Another alternative would be to use AOP to wrap all calls to debug() with the check.

Java Donkey said...

I blogged on this same topic here: Log4j - LogBack. The LogBack framework attempts to eliminate the need to call isDebugEnabled.

Werner said...

So far we have always wrapped the log4j framework and added convenience methods like
info(String theFormat, Object ... the Args);

where the string can be used to create a MessageFormat to convert the args into a string message inside the wrapper.

Reason: I don't like to clutter my code with if( enabled) log statements.

Eric Jablow said...

There's a better way to do this. Have you looked at Log4J object renderers? You can create a renderer class for a particular class in your application:


public class OrderRenderer implements ObjectRenderer

You then tell Log4J about it in your log4j.xml configuration file:

<renderer

renderedClass="com.example.Order"
renderingClass="com.example.log4j.renderer.OrderRenderer">

</renderer>

Then, you can just use the object itself in your log commands. Best is:

LOGGER.info("Saving order.");

LOGGER.debug(order);

LOGGER.info("Order saved successfully.");

vinoo said...

Well we can wrap the Log4j by a Logger wrapper where in we can do the log.isDebugEnabled check before logging the comment.OR log.isInfoEnabled

This way we solve three things.
1. Remove unwanted if(log.isDebugEnabled()) check in our code. This makes the code slimmer since those checks are happening in wrapper not in our business code.

2. Tommorow if Log4j is replaced by logBack changes in the code is not required , Interms of import statements etc since changes are happening behind the wrapper.

3. Any business object should do only business related activity ( single responsibility principle ) It should not have logic of how to log messages.

I have given the same comment at

http://www.javadonkey.com/blog/log4j-isdebugenabled-logback/#comment-2712

Anonymous said...

Hello guys

This topic is very instersting one that I am currently working on. I think that nor wrapping, nor ussing of specific methods like “logger.debug(stringMessage)” will prevent creating of stringMessage object. If there is enormous load over this line, a lot of garbage will be created. For me it seems that isEnabledDebug() is mandatory.

One of the approach I have been thinking about is one common log method but then we do not know with what severity the message is logged:

if(logger.isEnabledDebug()){
logger.log(stringMessage)
}

Matt said...

The rule is to do an isDebugEnabled check only if there is a method call required to create the argument to debug. A string concatenation requires several method calls.

"result: " + result
// gets compiled as
new StringBuilder().append("result: ").append(result).toString();

That's four method calls required to generate the argument to pass to debug, and that's not counting method calls made by those methods and so on.

Consider this case to see why this clarification is important:

debug(results.get(0));

There is no String concatenation there, but you definitely should wrap that debug call with an isDebugEnabled.

However, something like this doesn't need an isDebugEnabled check, because no methods need to be called to come up with the argument:

debug(result);

Javin Paul said...

Completely agree man and you have explained it on best possible manner I hope after reading your blog people will know when to put isDbugEnabled() check.

thanks
Javin
How to do java remote debugging in Eclipse

Anonymous said...

Why wasn't log.debug written to simply NOT build the message if DEBUG is not enabled ? the log.debug method could have had the if-condition and saved us all the trouble of thinking this thru.

Right ?

bamal said...

Good post, but I think limiting it just to String cancatination narrows donwn the scope.
The criteria should be to check if the log statement make any method call or calculation etc then check for debug level otherwise not.