All geek questions in one place

Why is a large volume of log entries written with Log4J2 slower when using the Async logger

I'm currently looking for a way to get the best performance from a logging utility using log4j2. Log4j.properties 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

Writing 100,000 journal entries takes about 4623 ms in my system.

If I create log4j2.component.properties in my classpath with the following settings to make all logs 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 7891 ms to write all 100,000 journal entries.

According to the log4j2 documentation, an asynchronous logger should be able to log messages 6–68 times the speed of a synchronous logger.

What is configured incorrectly?

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

JUnit Log4jContextSelector.

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

disruptor Log4jContextSelector, - 10000 /.

jar system Configuration log4j2.xml 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 ==

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

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

+4
1

SoaJSONLogger::error , , 10 , org.apache.logging.log4j.Logger. , .

, - AsyncLogger:

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

Source: https://habr.com/ru/post/1656726/

More articles:


All Articles