Slf4j Logging Enables Your Grails Apps To Avoid isDebugEnabled Code Clutter and String Creation Overhead

Using ‘isDebugEnabled’ to wrap logging statements that involve String concatenation is standard Java best practice, especially in loops, and in cases where the objects being logged have expensive toString operations. Performance will certainly be better this way, but I always disliked having to add three lines of clutter to my code just to emit some debugging information, as in the example below:

      ObjWithExpensiveToStringMethod object =
            new ObjWithExpensiveToStringMethod(1,2,3,4,...)
      if(logger.isDebugEnabled()) {
               logger.debug("This is my object: " +  object );
      }

Since Grails makes just about everything else easier, I was wondering if I could dispense with using isDebugEnabled and still avoid the performance hit that it was intended to prevent. I did a bit of research and came across this blog entry which demonstrated that that GStrings don’t get evaluated when they are used within logging statements whose level is is finer than the the current threshold.

Problem Solved?
Well unfortunately, no.

Upon my second read I noticed a comment from Dierk Koenig (who is certainly someone to pay attention to when it comes to Groovy) which warned that even though the GString doesn’t get evaluated, it still gets created, and GString creation just might be computationally intensive enough to warrant using the cursed ‘if’ block around one’s logging statements. Now I’m thinking that I’m right back where I started.

I then recallled that Grails uses Slf4j, and I also remembered that Slf4J has a pretty cool parameterized logging feature. Using this feature you can write code like the following:

    import org.slf4j.Logger;
    import org.slf4j.LoggerFactory;

    class BookController {
        private static Logger loggy =
                    LoggerFactory.getLogger(BookController.class);

        def list = {

          ObjWithExpensiveToStringMethod object =
                new ObjWithExpensiveToStringMethod(1,2,3,4,...) 

            // This next usage doesn't work reliably for me...>
            //log.info(". INJECTED LOGGER> with {} parameters {} {} ", 3,
                       'tres', object)

            loggy.info(". >> with {} parameters {} {} ", 3, 'tres', object)

                etc. etc.

        }

Note how the logging statements include the string {}. Each occurence of {} is a placeholder for a parameter which is positionally substituted in at run-time. With Slf4j the second through final parameters are never coerced to Strings, and a message with those toString()’d values is never created if the logging level of the logger issuing the statement is below the current threshold.

Note that you need to set the level of whatever your logger you want to see output for in Config.groovy. For our BookController logger, we did the following:

    // log4j configuration
    log4j = {

        error  'org.codehaus.groovy.grails.web.servlet',  //  controllers
                        etc. etc. etc....
                   'org.hibernate'

        debug  'com.blah', 'grails.app.controller.com.blah.BookController'

        warn   'org.mortbay.log'
    }

I found that it was best to avoid using the Grails injected loggers with positional parameters. They work fine when the current threshold matches or exceeds the debug level matches of the logging statement. But when debugging is turned off for an injected logger I found you can get some strange backtraces when statements that use the injected logger are reached. Use the manually constructed slf4j logger and you’ll be fine.

Rely on GString Lazy Evaluation, or Use Slf4J Positional Parameters?

It’s true that if you rely on GString’s lazy evaluation you can write logging code a little more clearly and conveniently than if you use Slf4j positional parameters. But until some convincing benchmarking is done to prove that GString creation overhead does not introduce potential performance bottlenecks in logging code, I think I’ll be going with the slf4j positional approach.

Posted in Grails | 2 Comments »

2 Responses to “Slf4j Logging Enables Your Grails Apps To Avoid isDebugEnabled Code Clutter and String Creation Overhead”

By John Smith
on December 30th, 2009
“Using ‘isDebugEnabled’ to wrap logging statements that involve String concatenation is standard Java best practice, especially in loop”
No it isn’t. 99% percent of the time, all it does is clutter up the code. It should only be used rarely. Only when you are logging huge object graphs.



By admin
on December 30th, 2009
well.. I certainly agree with you that isDebugEnabled clutters up one’s code !
Thanks for reading…
– c/b