Logging with log4J isDebugEnabled

Alot of times I have seen the questions popping up whether to use isDebugEnabled property or not. Arguably most of the times or rather always about performance. Some of the stuff that I feel important about using it follows.

The answer is simple. It is made to be used. However using it has to be with caution.

For instance
If I am using the following line in my code.

  1. log.debug("I am there");

Thats an example of a good practise

However I can really blow it out of proportions if I do the following.

  1. // Not good practise
  2. if (log.isDebugEnabled()){
  3.     log.debug("I am there"); 
  4. }

And why exactly is that so. This is because the method debug in the class Category i.e. extended by Logger in the log4j libraries explicitly checks the mode for the logging itself.

Extract from the class org.apache.log4j.Category is below

  1. public void debug(Object message) {
  2. if(repository.isDisabled(Level.DEBUG_INT))
  3. return;
  4. if(Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel())) {
  5. forcedLog(FQCN, Level.DEBUG, message, null);
  6. }
  7. }

Okay so thats the case where we say dont use it. What about the one where we actually do use the isDebugEnabled property.

For instance you have a large parameter going in the debug.

  1. // Bad Practise
  2.  log.debug("XML "+Tree.getXMLText());

In such a case it can clearly be said “No dont do it!” If Tree.getXMLText is going to pull out all the hair out of the app then there is no use. As it will be constructed first and if the debug level is not enabled that would be a performance cost.

  1. // Good Practise
  2. if (log.isDebugEnabled()){
  3.     log.debug("XML "+Tree.getXMLText());
  4. }

Thus in the example above it would be wiser to use log.isDebugEnabled() just to make sure the mileage or cost stays lesser.

7 thoughts on “Logging with log4J isDebugEnabled

  1. What do you think of keeping the result of isDebugEnabled() ?

    private static final Log log = …
    private static final boolean debugEnabled = log.isDebugEnabled();

    /* instructions */
    if(debugEnabled) {
    log.debug(“hey”);
    }
    /* instructions */
    if(debugEnabled) {
    log.debug(“ho”);
    }
    /* instructions */
    if(debugEnabled) {
    log.debug(“foo”);
    }

    1. @Sébastien Yes that certainly is a good option since we wont have to make the call again and again. Especially for instance we heavily are doing alot debug logging.

  2. This is still an issue with log4j however log4j’s successor – logback supports parameterized logging. So instead you would do something like – log.debug(“XML {}”, Tree.getXMLText());.

    1. @Alvin, @David If the thought is that the getXMLText() creates an expensive message for no purpose if isDebugEnabled is not enabled, How would SLF4J solve that?

  3. I agree with your suggestion of enclosing the debug call in the log.isDebugEnabled() and you can keep the result as suggested by @Sébastien

    I am not sure about how the SLF4J solved that issue, but for the reference check the following link. i have copied the text below that explains how you can improve the performance by using the SLF4J.

    http://www.slf4.org/faq.html#logging_performance
    ——————————————————————————
    What is the fastest way of (not) logging?

    SLF4J supports an advanced feature called parameterized logging which can significantly boost logging performance for disabled logging statement.

    For some Logger logger, writing,

    logger.debug(“Entry number: ” + i + ” is ” + String.valueOf(entry[i]));

    incurs the cost of constructing the message parameter, that is converting both integer i and entry[i] to a String, and concatenating intermediate strings. This, regardless of whether the message will be logged or not.

    One possible way to avoid the cost of parameter construction is by surrounding the log statement with a test. Here is an example.

    if(logger.isDebugEnabled()) {
    logger.debug(“Entry number: ” + i + ” is ” + String.valueOf(entry[i]));
    }

    This way you will not incur the cost of parameter construction if debugging is disabled for logger. On the other hand, if the logger is enabled for the DEBUG level, you will incur the cost of evaluating whether the logger is enabled or not, twice: once in debugEnabled and once in debug. This is an insignificant overhead because evaluating a logger takes less than 1% of the time it takes to actually log a statement.

    Better yet, use parameterized messages

    There exists a very convenient alternative based on message formats. Assuming entry is an object, you can write:

    Object entry = new SomeObject();
    logger.debug(“The entry is {}.”, entry);

    After evaluating whether to log or not, and only if the decision is affirmative, will the logger implementation format the message and replace the ‘{}’ pair with the string value of entry. In other words, this form does not incur the cost of parameter construction in case the log statement is disabled.


Leave a Reply

Your email address will not be published. Required fields are marked *