Search code examples
groovyappendlog4j2stringbuildergstring

Groovy StringBuilder append GString performance issue


I have an issue with log4j2 logging.

(groovy-all 4.0.0, org.apache.logging.log4j 2.17.1, gmavenplus-plugin 1.13.0)

I have a big nested Map object (10 keys and one value is a 100-lengths list of Maps).

And I call the log like:

Map myNestedMap = (1..1500).collectEntries{ ["key-$it", "value-$it"] }
log.debug("Some message, $myNestedMap")

And this line works 10+ seconds...

While debugging I've found that this invoked:

//org.apache.logging.log4j.message.ReusableSimpleMessage

@Override
public void formatTo(final StringBuilder buffer) {
    buffer.append(charSequence);
}

where charSequence is GString instance.

I've added some code to check the performance:

Map myNestedMap = ...

Closure measure = { String message,  Closure cl ->
    long start = Calendar.getInstance().getTimeInMillis()
    cl.call()
    long end = Calendar.getInstance().getTimeInMillis()
    println("$message ${(end-start)/1000} sec")
}
measure('StringBuilder:(GString, but no cast)') {
    new StringBuilder().append("$myNestedMap")
}

measure('StringBuilder:(cast to String)') {
    new StringBuilder().append((String)"$myNestedMap")
}
measure('StringBuilder:(cast to CharSequence)') {
    new StringBuilder().append((CharSequence)"$myNestedMap")
}
measure('StringBuilder:(cast to GString)') {
    new StringBuilder().append((GString)"$myNestedMap")
}

Output:

StringBuilder:(GString, but no cast) 0.354 sec
StringBuilder:(cast to String) 0.296 sec
StringBuilder:(cast to CharSequence) 13.479 sec
StringBuilder:(cast to GString) 12.937 sec

So I'm asking for some advice, on how to deal with this.

I can do:

Map myNestedMap = ...
log.debug("Some message, $myNestedMap" as String)

But I don't want to cast all the log records to String within the whole project.


Solution

  • you could extend your logger and override debug and other logging methods.

    or use metaclass to redefine methods for GString

    do it once on project init:

    Logger.metaClass.debug = {GString s-> delegate.debug(s as String) }