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:
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:
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;
incurs next to zero overhead.
Enter Groovy. What happens if you use a GString, e.g.:
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.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.
December 29th, 2008 01:20
Interesting analysis. Thanks!
One thing that I’ve always missed from ruby is the ability to pass a block (a closure in groovy) to the logging messages. That closure only gets evaluated if the logging level is enabled.
As you demonstrate, if you’re only using GStrings, you’re safe.
Actually, now that I think about it, you can get around it by putting your closure inside a GString to achieve the same thing, though it’s slightly clunkier:
log.debug “${ this.children.findAll { it == ‘expensive comparison’ } }”
December 30th, 2008 17:15
But you have to take into account that the GString object gets _created_ anyway, which may impose enough overhead to justify putting it inside a guarding “if”.
December 30th, 2008 17:55
@Dierk – that’s a good point – I should probably actually do some benchmarking.
December 29th, 2009 14:10
[...] 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 [...]