Investigation of Slow Asynchronous Log Printing in Log4j2: Disruptor Mechanism, JNI Overhead, and Optimization

1 Problem Background

Our business integrates multiple channels for online recycling, each with its own quality‑inspection standards. To unify these, we map external inspection items to internal ones. After importing a very large mapping set, the interface became extremely slow, and profiling revealed that excessive log printing was the root cause.

2 Problem Verification

In a test environment we stored more than 15,000 channel‑inspection mappings, and the conversion interface took about 4 seconds. Reducing the mapping count to around 100 brought the latency down to roughly 100 ms, confirming a strong correlation between mapping size and response time.

3 Initial Diagnosis

Using Alibaba's Arthas trace command we observed that most of the time was spent in log printing. The conversion process generates a huge amount of logs, and the more mappings there are, the more logs are produced. Commenting out the logging code immediately improved the response speed.

4 Preliminary Thoughts

4.1 Could the log configuration be synchronous?

We checked Log4j2 configuration and confirmed that logging is set to asynchronous, not synchronous.

4.2 Could multithreaded resource contention cause the slowdown?

We created a single‑thread test that logs 20,000 messages; it took over 600 ms, indicating that even in a single thread the logging is slow, so thread contention is not the primary factor.

5 Asynchronous Log Printing Principles

5.1 Disruptor Overview

The asynchronous logger uses the LMAX Disruptor framework. Producers write events into a ring buffer, and consumers read from it. Sequences are used to coordinate production and consumption.

public synchronized void start() { /* ... */ disruptor.handleEventsWith(handlers); }

5.2 How a LogEvent is Enqueued into the Ring Buffer

private void logToAsyncDelegate(final LogEvent event) {
    if (!isFiltered(event)) {
        populateLazilyInitializedFields(event);
        if (!delegate.tryEnqueue(event, this)) {
            handleQueueFull(event); // ENQUEUE, SYNCHRONOUS or DISCARD
        }
    }
}

public boolean tryEnqueue(final LogEvent event, final AsyncLoggerConfig asyncLoggerConfig) {
    final LogEvent logEvent = prepareEvent(event);
    return disruptor.getRingBuffer().tryPublishEvent(translator, logEvent, asyncLoggerConfig);
}

public
boolean tryPublishEvent(EventTranslatorTwoArg
translator, A arg0, B arg1) {
    try {
        final long sequence = sequencer.tryNext();
        translateAndPublish(translator, sequence, arg0, arg1);
        return true;
    } catch (InsufficientCapacityException e) {
        return false;
    }
}

The enqueue operation can fall back to a discard or synchronous strategy when the ring buffer is full.

5.3 Debugging the Test Code with Breakpoints

Debugging showed that the consumer processes events quickly and the handleQueueFull path is never taken, so the slowdown is not caused by the Disruptor’s discard policy.

6 Line‑by‑Line Code Annotation to Find the Slow Path

6.1 The Culprit is the getLocation Method

Commenting out the call to getLocation eliminated the delay. This method resolves %C, %F, %l, %L, %M placeholders in the log pattern by inspecting the stack trace.

private StackTraceElement getLocation(String fqcn) {
    return requiresLocation() ? StackLocatorUtil.calcLocation(fqcn) : null;
}

Further investigation traced the cost to the native stack‑trace extraction performed by StackLocator#calcLocation , which ultimately invokes Throwable.getStackTrace and native methods getStackTraceDepth / getStackTraceElement .

6.2 Official Data

Documentation shows that enabling location information can make logging 30‑100× slower.

6.3 JNI Overview

JNI bridges Java and native C/C++ code. It requires class and method look‑ups, data type conversion, and may introduce significant overhead due to context switches.

6.3.1 JNI Architecture

Java code calls native methods.

JNI header files generated by javac -h define the native signatures.

Native implementation provides the actual logic.

The JVM loads and executes the native library.

6.3.2 Data Type Conversion

Strings: GetStringUTFChars / NewStringUTF

Arrays: GetIntArrayElements , SetIntArrayRegion

Objects: GetObjectField , CallObjectMethod

6.3.3 Exception Handling

Native code can check and throw Java exceptions via env->ExceptionCheck() and env->Throw .

6.3.4 Thread Management

JNI provides AttachCurrentThread and DetachCurrentThread for managing Java threads from native code.

6.3.5 Performance Considerations

JNI calls have higher overhead than pure Java calls.

Excessive JNI usage can degrade performance despite its ability to execute fast native code.

6.4 Writing a Native Method Test

public class Hello {
    public native int helloFromCpp(int i);
    static { System.load(System.getProperty("user.dir") + "/libnative.dylib"); }
}

After compiling, generating header files, implementing the C++ side, building a dynamic library, and invoking the method in a loop, the total execution time was negligible, proving that JNI itself was not the bottleneck.

7 Conclusion

Avoid excessive unnecessary logs; use DEBUG level for detailed testing.

Set production logging level to INFO.

If location information is not required, remove %C, %F, %l, %L, %M from the log pattern.

8 Further Exploration (C‑level Implementation)

For readers interested in the underlying C implementation, refer to the OpenJDK source files:

jdk/src/share/native/java/lang/Throwable.c

hotspot/src/share/vm/prims/jvm.cpp

hotspot/src/share/vm/classfile/javaClasses.cpp