RSS Feed for This PostCurrent Article

Why You Should Use “isDebugEnabled” ?

This is a simple mistake that I noticed is commonly made by developers. Often I saw the code like the followings

.....
log.debug("my debug message");
...
log.debug("variable A is set to " + myVariableA);

Whenever I saw this, I always change them to

.....
if (log.isDebugEnabled())
   log.debug("my debug message");
...
if (log.isDebugEnabled())
    log.debug("variable A is set to " + myVariableA);

It may seem troublesome but it in fact gives us a little bit of performance gain. Though nowadays the processing power of computer has increased significantly, we should always adhere to good programming practice as much as we can.

Imagine that you are coding for a very complex application, and you need to put a lot of debugging statements for troubleshooting purpose in case things go wrong.

Consider the following simple example


import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;


public class TestLogger {

    // Logging object
    protected Log log = LogFactory.getLog(TestLogger.class);

    private void withoutCheck() {
        long startTime = System.currentTimeMillis();
        for (int i = 0; i < 10000000; i++) {
            log.debug("this is a test");
        }
        System.out.println(
         ((System.currentTimeMillis() - startTime)) 
           + " milliseconds");
    }


    private void withCheck() {
        long startTime = System.currentTimeMillis();
        for (int i = 0; i < 10000000; i++) {
            if (log.isDebugEnabled())
                  log.debug("this is a test");
        }
        System.out.println(
           ((System.currentTimeMillis() - startTime)) 
          + " milliseconds");
    }


    public static void main(String[] args) {
        TestLogger testLogger  = new TestLogger();
        testLogger.withoutCheck();
        testLogger.withCheck();
    }

}

I set the output to INFO level, which we normally set in production server.

The output

703 milliseconds
640 milliseconds

As you can see, the performance is better when we use "isDebugEnabled".

However, most of the time our debug statement is not as simple as printing out some static text. Most of the time we may need to print out value of a variable, call a function, etc...

So now I change the debug line to the following

log.debug("this " + " is " + " a " +  " test");

The output

625 milliseconds
516 milliseconds

Previously the difference is only about 63 milliseconds, but now is more than 100 milliseconds.

This is because if we do not use "isDebugEnabled", the debug statement has to concatenate all strings before doing the actual work of checking the debug level. This will increase processing time.

The performance gain may seem insignificant but in a high load application every millisecond counts...

The program footprint will increase also it you put a lot of "if log.isDebugEnabled", so use it wisely. Judge for yourself if it is necessary for you to use it. E.g. if the function is called very frequently and there are a lot of debug statements then it may be good to use it.


Trackback URL


RSS Feed for This Post17 Comment(s)

  1. jude | Mar 9, 2008 | Reply

    instead of having an if statement at every place inside your code wherever you plan to use the logging system , it makes more sense to put the if statement inside the debug method . A strategy could be used to poly morphically control the use of if statement

  2. Stefan | Mar 9, 2008 | Reply

    @jude: The whole point of adding isDebugEnabled() is not calling a method. Usually you have some string concatenations (or toString calls) in your debug statement. And you don’t need that string (and the garbage for the strinbuffer etc.) when you don’t print it. Thus you need to add a isDebugEnabled() before the debug statement.
    Maybe thing will change when closures arrive and the evaluation of the argument for debug can be deferred.

  3. lunatix | Mar 10, 2008 | Reply

    use slf4j instead of jcl, and you’ll be able to write logger.debug(“The new entry is {}.”, entry); the price of string concatenation is only payed if log is enable, and you don’t have to write ugly bloat code like isDebugIsEnable()

    @see
    http://www.slf4j.org/faq.html#logging_performance

  4. Mark Turansky | Mar 10, 2008 | Reply

    Your application logging is largely useless and debug statement just makes for gigs of spam in a log file. It’s snowcrash, unreadable, and useless.

    I say omit the debug statements entirely.

  5. Ran | Mar 10, 2008 | Reply

    You missed the point of isDebugEnabled().
    The withCheck() method should’ve been written like this:
    private void withCheck() {

    if (log.isDebugEnabled())
    for (int i = 0; i < 10000000; i++){
    log.debug(“this is a test”);
    }
    }…

    The point of isDebugEnabled() is to save loops and temporary object creation for debug purposes when you have no need for the debug log.

  6. Mark Turansky | Mar 10, 2008 | Reply

    No, I didn’t miss the point.

    I think debug statements are useless, so I wouldn’t litter my code with them or with the log.isDebugEnabled call.

    Your mileage may vary, but I’ve not seen many apps that have meaningful debug logs.

  7. Ran | Mar 10, 2008 | Reply

    @Mark: My comment wasn’t directed at you. Rather, it was directed at the author of the article.
    However, regarding your comment, I disagree. Debug logs are just for that – debug time. When you’re working on a multi-threaded application (in an application server for example), it’s very hard to follow the flow of the code without logs. However, once you’ve finished the debugging of a specific area – close the debug logs for that area! Not only they clutter your log file (which should, IMHO, be almost clean), but they pose a security risk (since various data is usually written to debug, including session ids, user information and even whole packets).

  8. B. Waite | Mar 10, 2008 | Reply

    I almost agree with Mark. Almost.

    Logs lose utility when you have a multithreaded application running on several machines, each processing hundreds of simultaneous user requests. It’s like playing a combination of poker and 52-pickup at the same time–you just can’t sort out the signal from the noise.

    That’s why I created a batch logger. It aggregates all calls into a batch before logging them. This results in each request being output in one chunk. This makes deciphering logs *much* easier.

    The logger can be instructed to keep quiet unless a problem occurs, at which point it dumps the offending batch. Our logs are generally empty, except for startup info and errors.

    Finally, the batch logger can format the output as HTML. If our app is in debug mode, the log batch is appended to the bottom of each web page. The HTML is rendered per task, and uses JavaScript to allow us to drill down into the call stack.

    The end result is that we *rarely* need to look at the logs. If we can reproduce the error, we’ll see the details on page that caused it.

  9. Jim | Mar 10, 2008 | Reply

    This is a bad idea. To summarize to points above:

    – It confuses the designed intent of isDebugEnabled().
    – It unnecessarily clutters up readable code.
    – The performance gain is so negligible, that 10 million repetitions are necessary to even notice it. If you are logging >10 million occurences, your logs are worthless

    Further, you may not know this, but

    log.debug(“this is a test”)

    and

    log.debug(“this ” + ” is ” + ” a ” + ” test”);

    generate identical bytecode. (Try it.)

  10. Tech Per | Mar 10, 2008 | Reply

    I agree completely with Jim.

    I, myself, used to wrap my log.debug statements in an isDebugEnabled() call. I don’t anymore. In most, if not nearly all, applications of today, the performance gain will negligible and next to nothing.

    I will *much* rather put my emphasis on clearer code, which is easier to write, than to squeezing the last nano-second out of the CPU.

    In addition, the (perceived) problem of string concatenation is a hard one to kill, even though at least the last two production JVMs from Sun, have done a great job at making it go away. It was in the “old days”, that this was a problem.

  11. Eric Jablow | Mar 10, 2008 | Reply

    If one has a business reason to do a lot of logging, one can declare an object renderer class in the log4j.xml file, and then one simply writes,

    Person p = new Person(“Eric”, “Jablow”);
    // …
    LOGGER.debug(p); // Uses the declared renderer for Person.

  12. Andrey P.Rybin | Mar 11, 2008 | Reply

    I agree completely with lunatix.

    Use http://slf4j.org as logging facade and enjoy its .debug(“very fast logging (if disabled) {}”, myObjWithHeavyToString)

  13. Diego Parrilla | Mar 11, 2008 | Reply

    I used the “isDebugEnabled” recommendation early in 1999, 2000 and 2001 with java. But we stopped using it because it did not give us a lot in terms of performance using JVM 1.3. In server side development the database is the bottleneck and the ‘isDebugEnabled’ only makes the code less clear.
    I think this is an old fashion tip.

  14. Jim LoVerde | Mar 24, 2008 | Reply

    Actually, the approach taken by log5j (a wrapper around log4j) offer a much more elegant solution.
    http://code.google.com/p/log5j/

    Basically, instead of using:

    if (log.isDebugEnabled())
    log.debug(“variable A is set to ” + myVariableA);

    You take advantage of JDK 1.5 syntax and write:

    log.debug(“variable A is set to %s”, myVariableA);

    Notice that you still get the benefit of not having the String concatenation taking place unless debug is enabled, but now you don’t have to clutter your code with a bunch of if statements.

  15. satish | May 8, 2008 | Reply

    I tried doing this, as a good practice. But I see that it increases clutter a lot. I am back to plain old log.debug in most cases. I now check isDebugEnabled only when a toString operation is costly in terms of time.

  16. Suresh | Sep 30, 2008 | Reply

    How can I disable log at runtime. I am using log4j.xml file. I am able to generate the logs successfully. But now i would like to on and off this feature. Is there any way to enable and disable the generating logs.

  17. Tech Per | Sep 30, 2008 | Reply

    @Suresh:

    Yep. Take a look at http://www.nelz.net/roller/nelz/entry/log4j_runtime_configuration

1 Trackback(s)

  1. From 547e44d7969d | May 10, 2008

Sorry, comments for this entry are closed at this time.