Tuesday, June 29, 2010

How to use isDebugEnabled() efficiently


Target audience: Beginners
We all use loggers for debugging the application in-case if there were any issues. We all write debug statements in our code.I would like to share my experience of how effectively we can use
debug statements. We should write the debug statements which do not impact on our application performance. Lets see how we can do it. I use log4j for logging.

this is how we write debug code

log.debug(" some informantion");
...
log.debug("some informantion : " + variale);

We can see, there are some string concatenations happening here. We all know that string concatenation is very expensive means that it badly affect the application performance.if you see the above code, it will be executed even if the log level is set to INFO,WARN or ERROR. if we restrict these code to be executed only if DEBUG level is enabled, then we can improve the performance of the application. How we can do it? See bellow

if(logger.isDebugEnabled()){
log.debug(" some informantion");
}
.....
if(logger.isDebugEnabled()){
log.debug("some informantion : " + variale);
}

These conditions we added will check whether the log level is set to DEBUG. The log statements will be executed only if the log level is set to DEBUG. This will help to improve the performance.
But the normal practice is the developers do not check for Debug level when there is no string catenation as they think that it does not impact on performance. But it slightly impacts.

Let me explain with sample code

package test;

import org.apache.log4j.Logger;

public class MyLogger {
private Logger logger = Logger.getLogger(this.getClass().getName());

public void check() {

long withCOunt = 0;
long withOutCount = 0;

for (int i = 0; i < 1000; i++) {

// with debug
long start = System.currentTimeMillis();
for (int n = 0; n < 1000; n++) {
if (logger.isDebugEnabled())
logger.debug(n);
}
long end = System.currentTimeMillis();
withCOunt = withCOunt + (end - start);

// with out debug
long start2 = System.currentTimeMillis();
for (int j = 0; j < 1000; j++) {
logger.debug(j);
}
long end2 = System.currentTimeMillis();
withOutCount = withOutCount + (end2 - start2);
}

System.out.println("Total Time Elapsed(With isDebugEnabled) : " + withCOunt);
System.out.println("Total Time Elapsed(Without isDebugEnabled) : " + withOutCount);
}

public static void main(String[] args) {
MyLogger myLogger = new MyLogger();
myLogger.check();
}
}

You should configure log4j or any other loggers. I do not cover configuration here. I use log4j here.
I have one method which has two loops and both of them do the same work but only the difference is one loop has isDebugEnabled() checking. I try to get the accumulated time by running 1000 times to get fairly good results.

// with out debug
....
logger.debug(j);

// with debug
....if (logger.isDebugEnabled())
logger.debug(n);


If you run the application with log level WARN.
The out put will be similar to the following:
Total Time Elapsed(With isDebugEnabled) : 15
Total Time Elapsed(Without isDebugEnabled) : 47

And you run the application with log level DEBUG.
Total Time Elapsed(With isDebugEnabled) : 119704
Total Time Elapsed(Without isDebugEnabled) : 118393

The results will vary based on the machine memory configurations. But if you see, the performance is much better when we use isDebugEnabled() check with log level greater than DEBUG and the performance is fairly equal with loge level DEBUG .

4 comments:

  1. I don't see why? You post is logical, in that any code that requires variable evaluation (like String concatenation) would perform better with isDebugEnable() check. However in the code snippets you written the logger.debug(i); does not evaluate any expression - so I see no reason why one should give better performance than the other!
    Also you should post results for what happens when the log level is set to Debug? I know the results but for the sake of completeness of course!

    ReplyDelete
  2. Two method does the same (no concatenation) except one has isDebugEnabled() check . They both log a message which has no sting concatenation (a single string). And the one has the check takes lesser time than the one without check. What gives the better performance here is the reduced method calls. If there is no check then logger.debug(i); statement will be called and then it will call some statements and methods internally in logger(e.g: log4j) implementation. The isDebugEnabled() check reduced these method calls.
    Than k you very much for your suggestion i’ll update the post with results while using log level DEBUG

    ReplyDelete
  3. I have updated the post with results of running the test with log level DEBUG.I also changed the class to have one method and two loops. Initially it had two methods.

    ReplyDelete
  4. So your text seems to say that what you're out to show, is that using isDebugEnabled is good to improve performance when the level is info or warn, as in:
    "We all know that string concatenation is very expensive means that it badly affect the application performance"
    and
    "These conditions we added will check whether the log level is set to DEBUG. The log statements will be executed only if the log level is set to DEBUG. This will help to improve the performance. "

    But what your code is showing, is that in the case where debug log level is disabled, calling isDebugEnabled() is quicker than calling a debug() that won't log anything.

    Those are two different issues: the main performance gain from using isDebugEnabled is to avoid constructing the string message. The slight gain from using isDebugEnabled rather than debug in the case where the log is off, is a different issue and nowhere near as important.

    If you put a string concatenation in those loops debug statements, you'd probably see that the gains are far more significant than the 30ms you shaved off looping over 1,000,000 ints.

    ReplyDelete