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.

5 Responses to “Performance issues with GString logging”

  1. Ted Naleid says:

    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’ } }”

  2. Dierk says:

    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”.

  3. Burt says:

    @Dierk – that’s a good point – I should probably actually do some benchmarking.

  4. [...] 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 [...]

  5. Iure says:

    Hi Burt, do you have any updates about this issue? Specially related with @Dierk question?

Leave a Reply

Creative Commons License
This work is licensed under a Creative Commons Attribution 3.0 License.