Log4j GC free performance

Question

We are moving to log4j v 2.6.1 (GC free) from version 2.5. I would like to appreciate how this improved our application (not the website).

Changes made to config:

• Use asyncloggers where possible. Only one asynchronous SMTP appender is used.
• Use only supported templates (% d {dd MMM yyyy HH: mm: ss, SSS}).
• It is not possible to set log4j2.is.webapp to false because we do not have servlets, which means that logging without garbage is enabled.

To compare performance, we record GC results - a new version sometimes takes longer for GC (minor). It preallocates memory as expected. Profiling shows that fixed memory is allocated.

eg. 2016-06-28T04: 39: 49.015 + 0100: 1078.995: [GC (distribution error) [PSYoungGen: 5603306K-> 91449K (6422528K)] 5603489K-> 91640K (7471104K), 0.0332092 secs] [Times: user = 0.21 sys = 0.00, real = 0.03 secs]

Any ideas if I am missing any configuration or other ways to measure it?

Java Version: JRE 1.8u40 64bit

    <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info" name="foo" packages="">
    <Appenders>
        <!--old appenders-->
        <!--<Async name="AsynchronousConsoleAppender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="ConsoleAppender"/>-->
        <!--</Async>-->
        <!--<Async name="AsynchronousFoo1Appender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="Foo1RollingFileAppender"/>-->
        <!--</Async>-->
        <!--<Async name="AsynchronousFoo2Appender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="Foo2RollingFileAppender"/>-->
        <!--</Async>-->
        <!--<Async name="AsynchronousFoo3Appender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="Foo3RollingFileAppender"/>-->
        <!--</Async>-->

        <Async name="AsynchronousSMTPAppender" blocking="false">
            <Filters>
                <RegexFilter regex=".*Reason: Refused invalid message \(Missing fo\):.*" onMatch="DENY"
                             onMismatch="NEUTRAL"/>
                <RegexFilter regex=".*log4j lib is not in the classpath java\.lang\.NoClassDefFoundError.*"
                             onMatch="DENY"
                             onMismatch="NEUTRAL"/>
                <ThresholdFilter level="${sys:smtpThreshold}" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <AppenderRef ref="smtpAppender"/>
        </Async>

        <Console name="ConsoleAppender">
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] &lt;%t&gt; [%-5p] [%c{1}] %m%n</pattern>
            </PatternLayout>
        </Console>

        <RollingFile name="Foo1RollingFileAppender" fileName="${sys:log.log-name}.log"
                     filePattern="${sys:log.log-name}-%d{yyyy-MM-dd}.log" append="true">
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"/>
            </Policies>
        </RollingFile>

        <RollingFile name="Foo2RollingFileAppender" fileName="${sys:log.log-name}.log"
                     filePattern="${sys:log.log-name}-%d{yyyy-MM-dd}.log" append="true">
            <ThresholdFilter level="INFO" onMatch="ACCEPT"/>
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"/>
            </Policies>
        </RollingFile>

        <RollingFile name="Foo3RollingFileAppender" fileName="${sys:log.log-name}.log"
                     filePattern="${sys:log.log-name}-%d{yyyy-MM-dd}.log" append="true">
            <ThresholdFilter level="INFO" onMatch="ACCEPT"/>
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"/>
            </Policies>
        </RollingFile>

        <!-- the buffer size needs to be bigger than the backlog.-->
        <ThrottlingSMTP name="smtpAppender" to="${sys:technicalIssueRecipients}"
                        from="test-${sys:mode}@xxx.com"
                        subject="test [${sys:instance.name}] Errors"
                        smtpHost="${sys:smtp.host}"
                        throttleTokens="3" throttleTokenRespawnMs="20000" throttleRestTimeMs="5000"
                        throttleMaxBacklogSize="100" ignoreExceptions="true">
            <HtmlLayoutWithTimesInUTC contentType="text/html"/>
        </ThrottlingSMTP>

    </Appenders>

    <Loggers>
        <!-- ============================== -->
        <!-- Noisy Loggers                  -->
        <!-- ============================== -->

        <AsyncLogger name="com.package1" level="fatal"/>
        <AsyncLogger name="com.package2" level="warn"/>

        <AsyncLogger name="com.package3" level="error"/>
        <AsyncLogger name="com.package4" level="error"/>
        <AsyncLogger name="com.package5" level="error"/>
        <AsyncLogger name="com.package6" level="error"/>

        <AsyncLogger name="com.package7" level="warn"/>
        <AsyncLogger name="com.package8" level="warn"/>
        <AsyncLogger name="com.package9" level="warn"/>
        <AsyncLogger name="com.package10" level="warn"/>
        <AsyncLogger name="com.package11" level="warn"/>
        <AsyncLogger name="com.package12" level="warn"/>
        <AsyncLogger name="com.package13" level="warn" />

        <AsyncLogger name="com.package14" level="warn"/>
        <AsyncLogger name="com.package15" level="warn"/>
        <AsyncLogger name="com.package16" level="warn"/>
        <AsyncLogger name="com.package17" level="warn"/>
        <AsyncLogger name="com.package18" level="warn"/>
        <AsyncLogger name="com.package19" level="warn"/>
        <AsyncLogger name="com.package20" level="warn"/>
        <AsyncLogger name="com.package21" level="warn"/>
        <AsyncLogger name="com.package22" level="warn"/>

        <AsyncLogger name="org.springframework" level="warn"/>
        <AsyncLogger name="com.package23" level="error"/>

        <AsyncLogger name="com.package24" level="warn"/>
        <AsyncLogger name="com.package25" level="warn"/>\
        <AsyncLogger name="com.package26" level="warn"/>
        <AsyncLogger name="com.package27" level="warn"/>

        <!-- ============================== -->
        <!-- DEBUG Loggers                  -->
        <!-- ============================== -->

        <AsyncLogger name="com.package28" level="debug"/>
        <AsyncLogger name="com.package29" level="debug"/>

        <!-- ============================== -->
        <!-- Different File loggers         -->
        <!-- ============================== -->

        <AsyncLogger name="EVENT_NOTIFICATION" additivity="false" level="${sys:event.logger.threshold}">
            <AppenderRef ref="ConsoleAppender"/>
        </AsyncLogger>


        <AsyncLogger name="FOO2_LOG" additivity="false">
            <AppenderRef ref="Foo2RollingFileAppender"/>
        </AsyncLogger>


        <AsyncLogger name="FOO3_LOG" additivity="false">
            <AppenderRef ref="Foo3RollingFileAppender"/>
        </AsyncLogger>

        <AsyncLogger name="FOO1_LOG" additivity="false">
            <appender-ref ref="Foo1FileAppender"/>
        </AsyncLogger>

        <Root level="info">
            <AppenderRef ref="ConsoleAppender"/>
            <AppenderRef ref="AsynchronousSMTPAppender"/>
        </Root>
    </Loggers>
</Configuration>

Answer 1

What are your performance targets?

: , , - . /. .

- , . ( ) , . . . , . - ! : .

, , (, , ). , 100 000 - . , , . log4j 2.5 log4j 2.6.1 , log4j.

:

• log4j2 .
• , , log4j. (), , , .
• JMH ( Java), . . , .

. , , , 50% . , ( " " ) ( " " ). . , .

( ) log4j 2.5 log4j 2.6.1.

:

• Pacer Log4j2 ResponseTimeTest , .
• HdrHistogram - .
• , , .
• , Gil Tene .

GC, :

-XX:+UnlockDiagnosticVMOptions -verbose:gc -XX:+PrintGCDetails
-XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution 
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime

, - , . GC ApplicationStoppedTime ( GC, , safepoint). : Log4j 2.5 Log4j 2.6.1? , GC? , ?

, , GC. GC . , , .

? Java Flight Recorder ( JDK) . profResult.jfr, Mission Control.

java -XX:+UnlockCommercialFeatures -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints 
-XX:+FlightRecorder -XX:StartFlightRecording=duration=10m,filename=profResult.jfr
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime  -cp 
.;HdrHistogram-2.1.8.jar;disruptor-3.3.4.jar;log4j-api-2.6.1.jar;log4j-core-2.6.1.jar;myApp.jar
com.mycomp.Benchmark

Java Flight Recorder , , , , . , .