How to use isDebugEnabled() efficiently

Go to >> Java Tutorials

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 .