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 GString
s 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 GString
s.
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 GString
s:
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 GString
s.
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’ } }”
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”.
@Dierk – that’s a good point – I should probably actually do some benchmarking.
[…] 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 […]
Hi Burt, do you have any updates about this issue? Specially related with @Dierk question?