Diagnosing Java Logging Performance Issues with JMH and Arthas

Problem Description

In order to support loss‑rate requirements, the original Log4j2 Async + custom Appender setup was replaced by moving the asynchronous logic into a modified Appender. After the change, logging performance dropped dramatically. The article reproduces the issue with a simple benchmark that logs 10,000 messages in a loop and measures the duration.

Two logger configurations are compared: a normal logger (defaultLogger) and a logger with includeLocation enabled (includeLocationLogger). The performance gap is evident in the test results.

JMH Overview

JMH (Java Microbenchmark Harness) is a framework for writing reliable Java micro‑benchmarks. It isolates benchmark code from boilerplate such as loops and warm‑up, allowing focus on the code under test. The article provides a minimal benchmark that measures the time to log a batch of 10,000 messages.

package com.bryantchang.appendertest;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class AppenderTest {
    private static final String LOGGER_NAME_DEFAULT = "defaultLogger";
    private static final String LOGGER_NAME_INCLUDE = "includeLocationLogger";
    private static final Logger LOGGER = LoggerFactory.getLogger(LOGGER_NAME_INCLUDE);
    public static final long BATCH = 10000L;

    public static void main(String[] args) throws InterruptedException {
        while (true) {
            long start, end;
            start = System.currentTimeMillis();
            for (int i = 0; i < BATCH; i++) {
                LOGGER.info("msg is {}", i);
            }
            end = System.currentTimeMillis();
            System.out.println("duration of " + LOGGER_NAME_INCLUDE + " is " + (end - start) + "ms");
            Thread.sleep(1000);
        }
    }
}

The benchmark class defines four methods with different thread counts (1, 4, 8, 16) and uses JMH annotations such as @Benchmark, @BenchmarkMode(Mode.AverageTime), @Fork(1), and @Threads. The main method configures JMH options (warm‑up iterations, measurement iterations, output file) and runs the benchmark.

@Benchmark
@BenchmarkMode(Mode.AverageTime)
@Fork(1)
@Threads(1)
public void testLog1() {
    LogBenchMarkWorker.getInstance().logBatch();
}

@Benchmark
@BenchmarkMode(Mode.AverageTime)
@Fork(1)
@Threads(4)
public void testLog4() {
    LogBenchMarkWorker.getInstance().logBatch();
}

// similar methods for 8 and 16 threads

The article also explains JMH parameters: Benchmark marks the method, BenchmarkMode selects the metric (AverageTime, Throughput, etc.), Fork controls process forking, and Threads sets concurrency.

Arthas: What Does My Code Do at Runtime

Arthas is an open‑source Java diagnostic tool from Alibaba. It can inspect JVM state, monitor method execution, generate flame graphs, and decompile bytecode. The article demonstrates using Arthas to investigate the same logging slowdown.

Actual Operation

First, obtain the target JVM PID with jps, then attach Arthas using ./as.sh pid. Once attached, several commands are used:

monitor – periodically shows method execution statistics.

trace – records the call stack of a method for a given number of invocations.

jad – decompiles a class to view its source.

watch – displays method arguments and return values.

Monitor Command

To monitor the info method of org.slf4j.Logger every 5 seconds: monitor -c 5 org.slf4j.Logger info The output shows that the logger with includeLocation incurs roughly three times the cost of the normal logger.

Trace Command & jad Command

The core method of an appender is append. Tracing it reveals different hot spots for the two configurations. For the logger with includeLocation, the longest‑running method is Log4jLogEvent.createMemento. Decompiling this method with jad shows its implementation.

jad org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento

watch command

Using watch on createMemento displays the method arguments. The result shows a boolean flag (true/false) indicating whether location information is captured, confirming that includeLocation triggers additional stack‑trace processing.

watch org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento "params" -x 2 -n 5 -b -f

The source of the flag is the LogEventProxy constructor, which conditionally calls event.getSource() when includeLocation is true. The getSource method captures a stack trace via new Throwable().getStackTrace(), which is expensive.

public LogEventProxy(final LogEvent event, final boolean includeLocation) {
    // ... other fields ...
    this.source = includeLocation ? event.getSource() : null;
    this.isLocationRequired = includeLocation;
}

public StackTraceElement getSource() {
    if (source != null) return source;
    if (loggerFqcn == null || !includeLocation) return null;
    source = Log4jLogEvent.calcLocation(loggerFqcn);
    return source;
}

By tracing createMemento, serialize, and the constructor of LogEventProxy, the article demonstrates how the extra stack‑trace collection accounts for the observed performance degradation.

In conclusion, combining JMH for controlled benchmarking with Arthas for live JVM inspection allowed the author to pinpoint the exact cause of the logging slowdown, illustrating a practical workflow for diagnosing Java performance issues.