Why is writing a high volume of log-entries with Log4J2 slower when using the Async logger

Question

I am currently seeking a way to get the best performance out of a logging utility using log4j2. The log4j.properties are

status = error
name = PropertiesConfig

property.log-path = /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles

appender.console.type = Console
appender.console.name = SYSTEM_OUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %m%n

appender.rolling.type = RollingFile
appender.rolling.name = RollingFile
appender.rolling.immediateFlush = true 
appender.rolling.fileName = ${log-path}/jsonlogger.json
appender.rolling.filePattern = ${log-path}/%d{yyyyMMdd}_jsonlogger-%i.json

appender.rolling.layout.type = PatternLayout
appender.rolling.layout.pattern = %m%n

appender.rolling.policies.type = Policies
appender.rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.rolling.policies.size.size= 1MB

appender.rolling.strategy.type = DefaultRolloverStrategy
appender.rolling.strategy.max = 4


logger.rolling.name = JSONLogger
logger.rolling.level = debug
logger.rolling.additivity = false
logger.rolling.appenderRef.rolling.ref = RollingFile

rootLogger.level = FATAL
rootLogger.appenderRef.stdout.ref = SYSTEM_OUT

Writing 100.000 log entries takes on my system about 4623ms.

If i create a log4j2.component.properties in my classpath with the following settings to make all loggers asynchronous.

# Make all loggers asynchronous 
Log4jContextSelector = org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

AsyncLogger.RingBufferSize = 262144
AsyncLogger.WaitStrategy = Timeout
AsyncLogger.ThreadNameStrategy = CACHED
AsyncLogger.ExceptionHandler = default handler

Then it takes about 7891ms to write all 100.000 log entries.

According to the log4j2 documentation an asynchronous logger should be able to log messages at 6 - 68 times the rate of a synchronous logger.

What is configured wrong ?

== Update 1 ==

In the mean time there have been some changes. The log4j.properties has been replaced by the log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>

<configuration status="error" name="JSONLogger">

<Properties>
    <Property name="log-path">/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles</Property>
</Properties>

<Appenders>
    <Console name="Console" target="SYSTEM_OUT">
        <PatternLayout pattern="%m%n" />
    </Console>

    <RollingRandomAccessFile name="RollingFile" fileName="${log-path}/jsonlogger.json"
                 filePattern="${log-path}/%d{yyyyMMdd}_jsonlogger-%i.json" 
                immediateFlush="false"> 
        <PatternLayout>
            <pattern>%m%n</pattern>
        </PatternLayout> 

        <Policies>
            <TimeBasedTriggeringPolicy />
            <SizeBasedTriggeringPolicy size="10 MB" />
        </Policies>
        <DefaultRolloverStrategy max="4"/>
    </RollingRandomAccessFile>
   <Async name="Async">
  <AppenderRef ref="RollingFile"/>
    </Async>
</Appenders>
<Loggers>
    <Logger name="JSONLogger" level="trace" additivity="false">
        <AppenderRef ref="Async" />
    </Logger>
    <Root level="fatal">
         <AppenderRef ref="Console" />
    </Root>
</Loggers>

The system property Log4jContextSelector has been removed from the log4j2.component.properties and now set using the maven shade plugin.

        <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-surefire-plugin</artifactId>
        <version>2.19.1</version>
        <configuration>
            <encoding>UTF-8</encoding>
            <argLine>-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector</argLine>
        </configuration>
    </plugin>       

Running the following JUnit test gives more or less the same performance results now with or without the Log4jContextSelector system property set.

@Test
public void orderD_logDebugMessageXMLToJSONFileTest() {

    SecureRandom random = new SecureRandom();
    String randomString = new BigInteger(130, random).toString();

    String xmlString = "<logMessage xmlns=\"http://reddipped.com/jsonlogger\">\n"
        + "  <Application>Application Name</Application>\n"
        + " <UserName>User Name</UserName>\n"
        + " <Identifier><FileID>F_" + randomString + "</FileID></Identifier>\n"
        + " <CorrelationID>" + randomString + "</CorrelationID>\n"
        + "</logMessage>";


    int messages = 100000;

    long start = System.nanoTime();
    for (int x = 0; x < messages; x++) {
        // Write a debug entry
        SoaJSONLogger.getInstance().error(xmlString);
    }
    Long stop = System.nanoTime();

    Long msgsPerSecond = messages / TimeUnit.NANOSECONDS.toSeconds((stop - start));

    System.out.println("Messages/s : " + msgsPerSecond) ;
    System.out.println("Duration  : " + (stop - start) ) ;
    Assume.assumeTrue("Slow performance " + msgsPerSecond + " < 10000 ", msgsPerSecond >= 10000);

}

All results are around Messages/s : 10000 Duration : 10630754228

== Update 2 ==

If i remove the disruptor jar from the classpath and the Log4jContextSelector system property the performance is still around 10000 messages/s.

When restoring the jar and system property and setting the attribute status of element Configuration in the log4j2.xml to TRACE the logger output to SYSTEM shows

2017-01-23 21:45:14,392 main DEBUG LoggerContext[name=AsyncContext@232204a1, org.apache.logging.log4j.core.async.AsyncLoggerContext@58695725] started OK.
2017-01-23 21:45:14,393 main DEBUG AsyncLogger.ThreadNameStrategy=CACHED
2017-01-23 21:45:18,961 AsyncAppender-Async TRACE DefaultRolloverStrategy.purge() took 2.0 milliseconds
2017-01-23 21:45:18,966 AsyncAppender-Async DEBUG RollingFileManager executing synchronous FileRenameAction[/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-1.json, renameEmptyFiles=false]
2017-01-23 21:45:18,972 AsyncAppender-Async TRACE Renamed file /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-1.json with Files.move
2017-01-23 21:45:21,987 AsyncAppender-Async TRACE DefaultRolloverStrategy.purge() took 0.0 milliseconds
2017-01-23 21:45:21,991 AsyncAppender-Async DEBUG RollingFileManager executing synchronous FileRenameAction[/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-2.json, renameEmptyFiles=false]
2017-01-23 21:45:21,991 AsyncAppender-Async TRACE Renamed file /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/jsonlogger.json to /Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles/20170123_jsonlogger-2.json with Files.move

Based on that i only can conclude that the logger is made asynchronous. Only the performance is the same.

== Update 3 ==

Replaced the RollingRandomAccessFile with the RandomAccessFile.

<Properties>
    <Property name="log-path">/Users/petervannes/NetBeansProjects/JSONLogger_2/logfiles</Property>
</Properties>
<Appenders>
    <Console name="Console" target="SYSTEM_OUT">
        <PatternLayout pattern="%m%n" />
    </Console>
    <RandomAccessFile name="RollingFile" fileName="${log-path}/jsonlogger.json"> 

        <PatternLayout>
            <pattern>%m%n</pattern>
        </PatternLayout> 

        <Policies>
            <TimeBasedTriggeringPolicy />
            <SizeBasedTriggeringPolicy size="10 MB" />
        </Policies>
        <DefaultRolloverStrategy max="4"/>
    </RandomAccessFile>
   <Async name="Async">
  <AppenderRef ref="RollingFile"/>
    </Async>
</Appenders>
<Loggers>
    <Logger name="JSONLogger" level="trace" additivity="false">
        <AppenderRef ref="Async" />
         <!--<AppenderRef ref="Console" />-->
    </Logger>
    <Root level="fatal">
         <AppenderRef ref="Console" />
    </Root>
</Loggers>

Create instance of SoaJSONLogger outside loop and added some 'warm-up' log events.

    int messages = 100000;

    SoaJSONLogger l = SoaJSONLogger.getInstance() ;
    l.error(xmlString);l.error(xmlString);l.error(xmlString);l.error(xmlString);l.error(xmlString);

    long start = System.nanoTime();
    for (int x = 0; x < messages; x++) {
        // Write a debug entry
        l.error(xmlString);
    }
    Long stop = System.nanoTime();

No change in performance; Messages/s : 10000 Duration : 10996023059

== Update 4 ==

Added by remco suggested test code

    // plain logger
    org.apache.logging.log4j.Logger log4j2Logger = org.apache.logging.log4j.LogManager.getLogger("JSONLogger") ;
    log4j2Logger.error(xmlString);

    long startl = System.nanoTime();
    for (int x = 0; x < messages; x++) {
        // Write a debug entry
        log4j2Logger.error(xmlString);
    }
    Long stopl = System.nanoTime();
    System.out.println("startl : " + startl) ;
    System.out.println("stopl : " + stopl) ;

     Long msgsPerSecondl = (long) 0 ;
    if (TimeUnit.NANOSECONDS.toSeconds(stopl - startl) == 0) {
            msgsPerSecondl = (long) messages ;
    } else {
      msgsPerSecondl = messages / TimeUnit.NANOSECONDS.toSeconds((stopl - startl));

    }

    System.out.println("Messages/s : " + msgsPerSecondl) ;
    System.out.println("Duration  : " + (stopl - startl) ) ;


    //  plain logger end

Performance is now 100000 messages/s (10x previous performance)

Answer 1

There seems to be some logic in SoaJSONLogger::error that causes the performance to be 10x worse than when logging with a standard org.apache.logging.log4j.Logger. Perhaps that is a good place to investigate.

One more thing you can try is to configure with AsyncLogger:

<AsyncLogger name="JSONLogger" level="trace" additivity="false">
   <AppenderRef ref="RollingFile" />
</AsyncLogger>