Performance of log4j2 compared to log4j1

问题:

I'm trying to migrate my app into using log4j2. It is currently using log4j 1.2.16. I also have a performance build for my project, and after upgrading to log4j 2, the performance seemed to have improve a lot.

That is, until I read about bridging. According to the doc, I have to exclude log4j1 JAR from the classpath, and include the bridging JAR - which I assume is named 'org.apache.logging.log4j:log4j-1.2-api'. Once I did this, performance dropped again.

So to summarise:

1. Performance with log4j2 + bridging jar + log4j-1.2-api + log4j1 : good
2. Performance with log4j2 + bridging jar + log4j-1.2-api : bad (to the point that it drops back to performance of just log4j1)

I have checked that the log4j-1.2-api is earlier in the classpath. So it should have been loaded first.

Any idea what could cause this problem?

Thank you very much in advance!

Oh my complete classpath for logging are:

• org.slf4j:slf4j-api
• org.slf4j:log4j-over-slf4j
• org.slf4j:jcl-over-slf4j
• org.apache.logging.log4j:log4j-slf4j-impl
• org.apache.logging.log4j:log4j-core
• org.apache.logging.log4j:log4j-api
• org.apache.logging.log4j:log4j-1.2-api
• log4j:log4j (with & without, as described above)

Versions:

• Log4j2 : 2.6.2
• slf4j: 1.7.20
• log4j1: 1.2.16

My config file looks like:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration
        xmlns:xi="http://www.w3.org/2001/XInclude">

    <xi:include href="log4j2-xinclude-appenders.xml" />

    <Loggers>

        <Root level="info">
            <AppenderRef ref="rollingFileAppender"/>
            <AppenderRef ref="stdOutAppender"/>
        </Root>
    </Loggers>
</Configuration>

And the log4j2-xinclude-appenders.xml looks like:

<?xml version="1.0" encoding="UTF-8"?>
<appenders>
    <RollingRandomAccessFile name="_rollingFileAppender" fileName="./logs/foo-${sys:app.name.suffix}.log"
                 filePattern="./logs/foo-${sys:foo.app.name.suffix}.log.%i">
        <PatternLayout>
            <Pattern>%d|%X{active.profiles}| %-5p |%X{fcp.session}|%X{StateMachine.key}|%X{StateMachine.currentState}| %m | %t | %c{1.}%n</Pattern>
        </PatternLayout>
        <Policies>
            <OnStartupTriggeringPolicy minSize="0" />
            <SizeBasedTriggeringPolicy size="100 MB" />
        </Policies>
        <DefaultRolloverStrategy max="10"/>
    </RollingRandomAccessFile>

    <Async name="rollingFileAppender" blocking="false" bufferSize="10000">
        <AppenderRef ref="_rollingFileAppender"/>
    </Async>

    <Console  name="_stdOutAppender" target="SYSTEM_OUT">
        <PatternLayout pattern="%d|%X{active.profiles}| %-5p |%X{fcp.session}|%X{StateMachine.key}|%X{StateMachine.currentState}| %m | %t | %c{1.}%n"/>
    </Console>     
    <Async name="stdOutAppender" blocking="false" bufferSize="10000">
        <AppenderRef ref="_stdOutAppender"/>
    </Async>
</appenders>

EDIT: This is the log4j 1 xml file that gets included in the classpath

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="A1" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/>
        </layout>
    </appender>

    <appender name="R" class="com.bar.common.util.RollingFileAppender">
        <param name="File" value="./logs/bar.log"/>
        <param name="MaxFileSize" value="100MB"/>
        <param name="MaxBackupIndex" value="10"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/>
        </layout>
    </appender>

    <!-- Performance Appender -->
    <appender name="OneSecondStatsAppender"
              class="com.foo.perf.AggregatedStatisticsAppender">
        <param name="TimeSlice" value="1000"/>
        <appender-ref ref="OneSecondStatsLogger"/>
    </appender>
    <appender name="FiveMinuteStatsAppender"
              class="com.bar.perf.DatafabricAggregatedStatisticsAppender">
        <param name="TimeSlice" value="300000"/>
        <appender-ref ref="FiveMinuteStatsLogger"/>
    </appender>

    <!-- Aggregated Performance Statistics Appender -->
    <appender name="OneSecondStatsLogger" class="org.apache.log4j.FileAppender">
        <param name="File" value="./logs/bar-performance.log"/>
        <layout class="com.bar.perf.AggregatedStatisticsCsvLayout"/>
        <filter class="com.bar.perf.CategorisedStatisticExclusionFilter"/>
    </appender>
    <appender name="FiveMinuteStatsLogger" class="org.apache.log4j.FileAppender">
        <param name="File" value="./logs/bar-minutes.log"/>
        <layout class="com.bar.perf.AggregatedStatisticsCsvLayout">
            <param name="ShowEmptyStatistics" value="true"/>
        </layout>
    </appender>

    <!-- Loggers -->
    <logger name="org.perf4j.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="OneSecondStatsAppender"/>
        <appender-ref ref="FiveMinuteStatsAppender"/>
    </logger>

    <logger name="com.bar">
        <level value="INFO"/>
    </logger>

    <logger name="com.gemstone.gemfire">
        <level value="INFO"/>
    </logger>

    <logger name="org.springframework.data">
        <level value="INFO"/>
    </logger>

    <!-- Root logger configuration -->
    <root>
        <priority value="INFO"/>
        <appender-ref ref="R"/>
    </root>

</log4j:configuration>

EDIT 2: Classpath order for poor performance:

log4j-1.2-api-2.6.2.jar
jcl-over-slf4j-1.7.20.jar
slf4j-api-1.7.20.jar
log4j-slf4j-impl-2.6.2.jar
log4j-core-2.6.2.jar
log4j-api-2.6.2.jar
log4j-1.2.16.jar

Classpath order for good performance

log4j-1.2-api-2.6.2.jar
jcl-over-slf4j-1.7.20.jar
slf4j-api-1.7.20.jar
log4j-over-slf4j-1.7.20.jar
log4j-slf4j-impl-2.6.2.jar
log4j-core-2.6.2.jar
log4j-api-2.6.2.jar
log4j-1.2.16.jar

回答1:

I ran into more strange findings. I enabled '-verbose:class' JVM options to see which classes were loaded, and I can confirm that only classes from the following JARs were loaded (in the order):

• slf4j-api-1.7.20.jar
• log4j-slf4j-impl-2.6.2.jar
• log4j-api-2.6.2.jar
• log4j-core-2.6.2.jar
• log4j-1.2-api-2.6.2.jar
• jcl-over-slf4j-1.7.20.jar

Yet, the following two tests yield different result:

1. Performance test with including log4j-over-slf4j-1.7.20 & log4j-1.2.16 : GOOD
2. Performance test with including log4j-over-slf4j-1.7.20 & but excluding log4j-1.2.16 : BAD
3. Performance test with excluding log4j-over-slf4j-1.7.20 & including log4j-1.2.16 : BAD

Note that these two JARs were not loaded at all.

回答2:

I there there are two questions here:

1. Why does log4j 1 get used in certain classpath configurations
2. Why is log4j 2 not faster than log4j 1

1. Why is log4j 1 used

I suspect that the following slf4j dependencies caused the old log4j 1.2 to be used:

org.slf4j:log4j-over-slf4j
org.slf4j:jcl-over-slf4j

If you use maven these could bring in the old Log4j 1 as a transitive dependency even if you don't explicitly declare it in your POM.

Please remove these. Log4j 2 has log4j-slf4j-impl and log4j-jcl modules that will accomplish the same but use Log4j 2 instead.

You should not have Log4j 1 in the classpath. If your application (or any of the libraries you use) depend on the Log4j 1 API, then add the log4j-1.2-api module.

2. Why is log4j 2 not faster than log4j 1

The configuration you describe does not take advantage of log4j 2 features. It uses AsyncAppender (which is roughly equivalent in log4j 1 and 2) and ConsoleAppender (which is slightly worse in log4j 2). ConsoleAppender is about 60 times slower than file appender. Be extremely careful when logging to the console in production systems.

Here is what I suggest: remove the following (which now seems to give better performance, but bear with me)

• log4j-over-slf4j-1.7.20
• log4j-1.2.16
• the old lo4j.xml configuration

Add the LMAX Disruptor dependency:

<!-- https://mvnrepository.com/artifact/com.lmax/disruptor -->
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.2.0</version>
</dependency>

Use the following log4j2.xml configuration. Temporarily just make it a simple file without includes, you can put that back later. (Notice I added <Configuration status="trace" to the beginning of the file: that will output internal log4j2 debugging statements so you can confirm that configuration completed without problems.)

Note that I made Console logging WARN level as I suspect it is impacting performance.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="TRACE" xmlns:xi="http://www.w3.org/2001/XInclude">

  <appenders>
    <RollingRandomAccessFile name="_rollingFileAppender" 
                 fileName="./logs/foo-${sys:app.name.suffix}.log"
                 filePattern="./logs/foo-${sys:foo.app.name.suffix}.log.%i">
        <PatternLayout>
            <Pattern>%d|%X{active.profiles}| %-5p |%X{fcp.session}|%X{StateMachine.key}|%X{StateMachine.currentState}| %m | %t | %c{1.}%n</Pattern>
        </PatternLayout>
        <Policies>
            <OnStartupTriggeringPolicy minSize="0" />
            <SizeBasedTriggeringPolicy size="100 MB" />
        </Policies>
        <DefaultRolloverStrategy max="10"/>
    </RollingRandomAccessFile>

    <Console  name="_stdOutAppender" target="SYSTEM_OUT">
        <PatternLayout pattern="%d|%X{active.profiles}| %-5p |%X{fcp.session}|%X{StateMachine.key}|%X{StateMachine.currentState}| %m | %t | %c{1.}%n"/>
    </Console>     
  </appenders>

    <Loggers>
        <Root level="info">
            <AppenderRef ref="_rollingFileAppender"/>
            <AppenderRef ref="_stdOutAppender" level="WARN" />
        </Root>
    </Loggers>
</Configuration>

Now, the final (key) point: enable log4j 2 async loggers by setting system property Log4jContextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.

This last bit should make a large performance difference. (Together with disabling Console logging.)