Fix extended stack trace (i.e., %xEx) rendering performance regression

[alan0428a]

• Fixes the extended stack trace rendering performance regression introduced in Consolidate stack trace rendering in Pattern Layout #2691. The issue is reported in Performance regression in 2.25.0-SNAPSHOT #3106, due to Disruptor + many logger.error("aa", new Exception("aaa"))，stuck on Th… #3093.
• Switches the default exception handler of Pattern Layout from %xEx to %ex

[alan0428a]

@ppkarwasz @vy

2.24.1 baseline: around 150MB

2.25.0 SNAPSHOT: around 2.5GB Initial fix ea9944f reduce to around 300 MB

Will continue to check for improvement

[jengebr]

My benchmark shows that these changes are ~10% slower than 2.24.1, and use 3x the heap. That is far better than previous 2.25.0, which was more than 2x slower and used ~15x the heap.

What level of performance regression is acceptable?

[github-actions]

Job	Requested goals	Build Tool Version	Build Outcome	Build Scan®
build-macos-latest	clean install	3.9.8	✅
build-ubuntu-latest	clean install	3.9.8	✅
build-windows-latest	clean install	3.9.8	✅

Generated by gradle/develocity-actions

[ppkarwasz]

My benchmark shows that these changes are ~10% slower than 2.24.1, and use 3x the heap. That is far better than previous 2.25.0, which was more than 2x slower and used ~15x the heap.

What level of performance regression is acceptable?

They seem more than acceptable to me.

These are figures using synchronous logging, right? They seem more than acceptable to me. For asynchronous loggers, the performance regression is probably higher, since the getCurrentStackTrace() trick only gives a meaningful result if it is called near to the point, where the exception was generated.

Regardless of the results of asynchronous loggers, I think that the throwable chapter of 2.25.0 is almost over. I think that we only need to:

• Replace %xEx with the much improved %ex as default throwable formatter.
• Remove all the calls to LogEvent.getThrownProxy() from the codebase. They are useless and expensive.

If users complain about the asynchronous performance of %xEx, we could think about introducing an option that collects the packaging information on the calling thread and passes it in the LogEvent.

[vy]

I am still observing a ~10x performance regression. I use the following crude script:

import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter;

import java.net.Socket;

public class Log4j2Issue3123 {

    public static void main(String[] args) {
        final Exception error = createException();
        final LogEvent logEvent = Log4jLogEvent.newBuilder().setThrown(error).build();
        final ExtendedThrowablePatternConverter converter = ExtendedThrowablePatternConverter.newInstance(null, null);
        long startInstantNanos = System.nanoTime();
        final StringBuilder buffer = new StringBuilder();
        for (int i = 0; i < 5_000_000; i++) {
            buffer.setLength(0);
            converter.format(logEvent, buffer);
        }
        double durationSeconds = (System.nanoTime() - startInstantNanos) / 1e9;
        System.out.format("took %.3f s%n", durationSeconds);
        // 2.24.1 - 1.753 s
        // 2.25.0 - 11.281 s
    }

    private static Exception createException() {
        try {
            new Socket("localhost", -1);
            throw new IllegalStateException("should not have reached here");
        } catch (final Exception error) {
            return error;
        }
    }

}

[vy]

My benchmark shows that ...

@jengebr, mind sharing the details about your benchmark, please?

[jengebr]

Sure - my benchmark is attached. Be sure to use -Xmx3g -Xms3g -XX:+UseParallelGC.

I vary the scenario by changing the classpath to include the desired log4j version.

log4j_benchmark.zip

[jengebr]

@vy I confirm your results; profiling shows your script is bottlenecked on the String.format calls which are no longer called by my benchmark (after the Lazy objects were used).

[alan0428a]

@vy @jengebr
I also can confirm the regression by running vy's script.
But in my profiling, the String.format() still takes a lot of time after we wrap it with Lazy object.
So I replace it with 3fa242a. This can reduce the time for render part. The total time now reduce to around 9 seconds on my PC.

[alan0428a]

And I noticed that compare to 2.24.1 baseline, the context creation part 2.25.0 is much more slower.
In 2.24.1, context creation is done in Log4jLogEvent.getThrownProxy(). And in 2.25.0, it's done in ThrowableExtendedStackTraceRenderer#createContext. And the same code takes way more time in 2.25.0.

2.24.1 2.25.0 commit 3fa242a

[alan0428a]

Oh...I think I know the reason. The test script is actually not fair. The 2.24.1 will store the ThrowableProxy in the Log4jLogEvent, so context creation only called once. But in the new implementation, the context creation gets called every time.
If we move this line final LogEvent logEvent = Log4jLogEvent.newBuilder().setThrown(error).build(); into the for-loop in the script. I can get similar CPU time result compare to 2.24.1. But the memory allocation is 2x.

[alan0428a]

I found that current way to load class wastes 4GB more memory, compare to old approach(simple if-else way) according to the profiler. I guess it's the overhead of Stream API.
Maybe it's better to switch back to old way?

[alan0428a]

Also the current way of using Throwable as a key for the map in metadata might be memeory expensive?
https://github.com/alan0428a/logging-log4j2/blob/1e154d446fe9d56046281966c60091f0d5d2f48b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableStackTraceRenderer.java#L77

[vy]

in my profiling, the String.format() still takes a lot of time after we wrap it with Lazy object.
...
The test script is actually not fair.
...
I found that current way to load class wastes 4GB more memory, compare to old approach (simple if-else way)

Awesome findings @alan0428a! 🤩
Thanks so much for helping with the troubleshooting! 🙇
I will incorporate the changes you suggested and re-run the benchmark.

[vy]

Also the current way of using Throwable as a key for the map in metadata might be memory expensive?

@alan0428a, what do you mean by this? What would be your suggestion instead?

[vy]

I can confirm that with the ClassResourceInfo and ThrowableExtendedStackTraceRenderer#loadClass() fixes @alan0428a tipped, 2.25.0-SNAPSHOT shows an (almost) identical performance to 2.24.1. 🥳 I think the performance regression hunt is over. Let's wrap up this work.

• Replace %xEx with the much improved %ex as default throwable formatter.
• Remove all the calls to LogEvent.getThrownProxy() from the codebase. They are useless and expensive.

@ppkarwasz, agreed. I will implement the changes you suggested.