Performance issues with GString logging

Everybody knows about wrapping Log4j log.debug() statements in if (log.isDebugEnabled()) {} blocks to make sure that the message being sent to the log method isn’t evaluated unnecessarily if the DEBUG level isn’t enabled for the logger. This is true in regular Java apps as well as Groovy/Grails apps.

For example, suppose you have large Collection foo and you log it with a logger whose level is set to INFO:

log.debug("foo is " + foo);

This will concatenate "foo is " with foo.toString() but then discard the combined string since the logger isn’t at the DEBUG level. If there are a lot of these debug statements in your code then you’ll waste a lot of cycles concatenating strings, especially if you’re logging in loops. This is trivially fixed with this though:

if (log.isDebugEnabled()) {
   log.debug("foo is " + foo);
}

But if there’s no string concatenation and evaluation, then you don’t need to wrap the call – the cost of a discarded log() invocation is about the same as the isDebugEnabled() test;

log.debug("just a simple string");

incurs next to zero overhead.

---

Enter Groovy. What happens if you use a GString, e.g.:

log.debug "foo is ${foo}"

It turns out that this needs to be wrapped also, since although GStrings are lazy evaluated, they must be converted to a String for the debug() invocation, so you’re right back where you started. To test this, try out this code in a Groovy/Grails console.

Note that to test whether toString() is called there’s a println statement in toString():

import org.apache.log4j.Level
import org.apache.log4j.Logger

class Thing {
  String toString() {
    println "calling thing tostring"
    return "a thing"
  }
}

def thing = new Thing()

def log = Logger.getLogger('foo')
log.level = Level.INFO
log.debug "Debug: Thing: $thing"
log.error "Error: Thing: $thing"

When running this the output to the shell is

[2344] foo Error: Thing: a thing

and in the console is

calling thing tostring

so it didn’t log the debug message, but it did log the error message since it’s above the INFO level that the logger is set at. But it only printed the message from the toString() method once, meaning it didn’t evaluate the GString in the debug message. Hmmm.

Turns out I was wrong in an earlier assumption – the signatures of the various Logger methods take an Object, not a String, e.g.

public void debug(Object message)

and

public void debug(Object message, Throwable t)

So there’s nothing to evaluate, and the GString is discarded. Cool – Groovy to the rescue, no performance issues with logging GStrings.

I wondered though what it would take to coerce a GString to a String:

This doesn’t; nothing gets printed:

log.debug "Debug: Thing: $thing" + " now"

This also doesn’t, since it’s concatenating two GStrings:

log.debug "Debug: Thing: $thing at " + "${System.currentTimeMillis()}"

This does trigger toString() since it’s no longer concatenating strings:

log.debug "Debug: Thing: $thing at " + System.currentTimeMillis()

and of course

String message = "Debug: Thing: $thing"
log.debug message

triggers toString() since it explicitly creates a String.

So it turns out that you’d pretty much have to work at causing a performance issue with logging GStrings.

Everybody knows about wrapping Log4j log.debug() statements in if (log.isDebugEnabled()) {} blocks to make sure that the message being sent to the log method isn’t evaluated unnecessarily if the DEBUG...

This entry was posted on Sunday, December 28th, 2008 at 9:40pm and is filed under grails, groovy, java, log4j. You can follow any responses to this entry through the RSS 2.0 feed. Both comments and pings are currently closed.