java - 为什么在使用异步记录器时使用 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

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

根据log4j2 documentation异步记录器记录消息的速度应该是同步记录器的 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 系统属性中删除 disruptor jar，性能仍然在 10000 条消息/秒左右。

当恢复 jar 和系统属性并在 log4j2.xml 中设置元素 Configuration 的属性状态以跟踪记录器输出到 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 中似乎有一些逻辑导致性能比使用标准 org.apache.logging.log4j.Logger 记录时差 10 倍>。也许那是调查的好地方。

您可以尝试的另一件事是使用 AsyncLogger 进行配置:

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