0

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.

Max Daroshchanka
  • 2,698
  • 2
  • 10
  • 14
  • What happens if you `log.debug("some message {}", myNestedMap)`? – Jeff Scott Brown Feb 15 '22 at 16:27
  • btw... I would expect `(CharSequence)"$myNestedMap"` and `(GString)"$myNestedMap"` to have the same performance characteristics as each other since `"$myNestedMap"` is already each of those types so no Groovy coercion has to happen. – Jeff Scott Brown Feb 15 '22 at 16:35
  • 1
    just tested in older versions of groovy with `def myNestedMap=(1..1000).collectEntries{ ["key-$it", "value-$it"] }` - it's even worse. definitely a bug. – daggett Feb 16 '22 at 07:29
  • @JeffScottBrown Thank you. `log.debug("some message {}", myNestedMap)` - `0.087 sec` - it's also well but requires to care about this. Since GStrings allowed for logging I'm concerned about someone will use a more natural approach and we'll get potential issues. – Max Daroshchanka Feb 16 '22 at 08:19
  • @daggett thanks for the Map generation, I'll include this in the code. For 1000 records it works 4 sec, for 1500 records - 10 sec, for 3k records 40 sec. – Max Daroshchanka Feb 16 '22 at 08:22
  • I've found this in the documentation: https://docs.groovy-lang.org/latest/html/groovy-jdk/java/lang/StringBuilder.html, but cannot find `StringBuilder append(GStringImpl gs)` method anywhere, IDE doesn't show this. Does it mean that this does not work when I run my classes with java, and not with groovy command? – Max Daroshchanka Feb 16 '22 at 08:29
  • 1
    https://github.com/apache/groovy/blob/master/src/main/java/org/codehaus/groovy/runtime/StringGroovyMethods.java#L233 – daggett Feb 16 '22 at 08:30
  • 1
    also there is Appendable.append: https://github.com/apache/groovy/blob/GROOVY_4_0_X/src/main/java/org/codehaus/groovy/runtime/FormatHelper.java#L494 – daggett Feb 16 '22 at 08:37
  • @daggett Thank you! I see these methods are not invoked and this might be the reason for such behavior.. Looks like `StringGroovyMethods` not applied to `StringBuilder`. – Max Daroshchanka Feb 16 '22 at 09:10
  • "Since GStrings allowed for logging I'm concerned about someone will use a more natural approach and we'll get potential issues." - I think `log.debug("some message {}", myNestedMap)` is a natural approach. – Jeff Scott Brown Feb 16 '22 at 14:31

1 Answers1

1

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) }
daggett
  • 26,404
  • 3
  • 40
  • 56