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

11 comments:

  1. Mark DerricuttMay 19, 2007 at 4:18 PM

    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.

    ReplyDelete
  2. AnonymousJune 7, 2007 at 8:42 PM

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

    ReplyDelete
  3. AnonymousJune 8, 2007 at 10:31 PM

    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.

    ReplyDelete
  4. AnonymousSeptember 7, 2007 at 7:40 PM

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

    ReplyDelete
  5. AnonymousOctober 25, 2007 at 5:03 PM

    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

    ReplyDelete
  6. AnonymousDecember 18, 2007 at 6:09 PM

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

    ReplyDelete
  7. MattAugust 15, 2008 at 5:07 PM

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

    ReplyDelete
  8. javin paulApril 16, 2011 at 4:09 PM

    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

    ReplyDelete
  9. AnonymousOctober 25, 2011 at 4:51 AM

    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 ?

    ReplyDelete
  10. bamalMarch 22, 2012 at 5:53 PM

    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.

    ReplyDelete
  11. periyannanFebruary 9, 2022 at 10:40 AM

    This article is very much helpful and i hope this will be an useful information for the needed one. Keep on updating these kinds of informative things...

    This is a great post. I like this topic.This site has lots of advantage.I found many interesting things from this site. It helps me in many ways.Thanks for posting.

    evs full form
    raw agent full form
    full form of tbh in instagram
    dbs bank full form
    https full form
    tft full form
    pco full form
    kra full form in hr
    tbh full form in instagram story
    epc full form

    ReplyDelete