为什么在使用异步记录器时使用 Log4J2 写入大量日志条目会变慢

Question

我目前正在寻找一种使用 log4j2 从日志实用程序中获得最佳性能的方法。log4j.properties 是

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

写入 100.000 个日志条目在我的系统上花费大约 4623 毫秒。

如果我使用以下设置在我的类路径中创建一个 log4j2.component.properties 以使所有记录器异步。

# 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

然后写入所有 100.000 个日志条目大约需要 7891 毫秒。

根据log4j2 文档，异步记录器应该能够以同步记录器速率的 6 - 68 倍记录消息。

什么配置错了？

== 更新 1 ==

与此同时，也发生了一些变化。log4j.properties 已被 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>

系统属性 Log4jContextSelector 已从 log4j2.component.properties 中删除，现在使用 maven shade 插件进行设置。

        <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>       

无论是否设置 Log4jContextSelector 系统属性集，运行以下 JUnit 测试都会提供或多或少相同的性能结果。

@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);

}

所有结果都在消息/秒左右：10000 持续时间：10630754228

== 更新 2 ==

如果我从类路径和 Log4jContextSelector 系统属性中删除干扰器 jar，性能仍然在 10000 条消息/秒左右。

当恢复jar和系统属性并将log4j2.xml中元素Configuration的属性状态设置为TRACE时，记录器输出到SYSTEM显示

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

基于这一点，我只能得出结论，记录器是异步的。只有性能是一样的。

== 更新 3 ==

用 RandomAccessFile 替换了 RollingRandomAccessFile。

<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>

在循环外创建 SoaJSONLogger 实例并添加一些“热身”日志事件。

    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();

性能无变化；消息/秒：10000 持续时间：10996023059

== 更新 4 ==

由 remco 添加建议测试代码

    // 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

性能现在是 100000 条消息/秒（10 倍以前的性能）

Answer 1

似乎有一些逻辑SoaJSONLogger::error导致性能比使用标准 .log 日志记录时差 10 倍org.apache.logging.log4j.Logger。也许那是一个调查的好地方。

您可以尝试的另一件事是配置AsyncLogger：

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