Log4J2 sync loggers faster than mixed async/sync loggers

Question

Based on https://logging.apache.org/log4j/2.x/manual/async.html I want to use the Mixing Synchronous and Asynchronous Loggers approach in order to benefit from some performance improvement over the all synchronous loggers.

The benchmark code:

public static void main(String[] args) {
    org.apache.logging.log4j.Logger log4j2Logger = org.apache.logging.log4j.LogManager
            .getLogger("com.foo.Bar");

    long start = System.currentTimeMillis();
    int nbLogMessages = 1 * 1000 * 1000;

    for (int i = 0; i < nbLogMessages; i++) {
        log4j2Logger.info("Log Message");
    }

    org.apache.logging.log4j.core.Logger coreLogger = (org.apache.logging.log4j.core.Logger) log4j2Logger;
    org.apache.logging.log4j.core.LoggerContext context = (org.apache.logging.log4j.core.LoggerContext) coreLogger
            .getContext();
    Map<String, org.apache.logging.log4j.core.Appender> appenders = context
            .getConfiguration().getAppenders();
    for (org.apache.logging.log4j.core.Appender appender : appenders
            .values()) {
        appender.stop();
    }

    long elapsed = System.currentTimeMillis() - start;
    System.out.println("Elapsed " + elapsed + "ms "
            + (nbLogMessages * 1000 / elapsed) + "logs/sec.");
}

The Log4j2 configuration is exactly the one in the doc (https://logging.apache.org/log4j/2.x/manual/async.html):

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <RandomAccessFile name="RandomAccessFile" fileName="/tmp/asyncWithLocation.log" immediateFlush="false" append="false">
      <PatternLayout>
        <Pattern>%d %p %class{1.} [%t] %location %m %ex%n</Pattern>
      </PatternLayout>
    </RandomAccessFile>
  </Appenders>
  <Loggers>
    <!-- pattern layout actually uses location, so we need to include it -->
    <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </AsyncLogger>
    <Root level="info" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </Root>
  </Loggers>
</Configuration>

With that mixed sync/async logger config I get around 33,400 logs/sec.

Now if I replace the AsyncLogger "com.foo.Bar" with a regular Logger I get around 35,300 logs/sec.

How come the synchronous logger strategy is faster, according to the graphs it should have a way higher throughput no?

I've tried various other things like "warming up" the JVM before doing the benchmark like they recommend but it didn't help.

Note that if I set the property Log4jContextSelector to "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector" to activate the "all async" loggers, I get around 86,400 logs/seconds. Unfortunately I can't use that option for other reasons.

Using log4j2-2.3, disruptor-3.3.2.
OS is Ubuntu, 8 cores.

Remko Popma Remko Popma · Accepted Answer · 2015-05-20T14:01:02

Before you start measuring, I would recommend that you log a smaller number of messages, say 100,000 or so, then sleep for one second before starting the measured loop. (You don't want to measure log4j's initialization or the JVM optimization here.)

What are your performance results if you measure until after the logging loop finishes (before trying to stop the appenders)?

Also try setting includeLocation="false" in your config. This should make a big difference.

I don't think you should manually stop the appenders (see my answer to your other question).

Log4J2 sync loggers faster than mixed async/sync loggers

1 Answers