log4j GC free performance

Question

We are migrating to the log4j v 2.6.1 (GC free) from v2.5. would like to measure how this has improved our application (non web based).

Changes we made in config:

• Use asyncloggers where possible. The only async appender used is SMTP.
• Use only supported patterns (%d{dd MMM yyyy HH:mm:ss,SSS}) .
• Not setting log4j2.is.webapp to false explicitly as we do not have servlet classes which means garbage-free logging is enabled.

To compare the performance, we log the GC outputs - new version sometimes takes more time per GC(minor). It does preallocate some memory as expected. Profiling does show that a fixed memory is allocated.

eg. 2016-06-28T04:39:49.015+0100: 1078.995: [GC (Allocation Failure) [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 would be missing some configuration or other ways to measure this?

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

This is important: for some applications all that matters is to do as much work as possible in as short a period of time as possible. This is throughput, and is often measured in operations/time. A good example of such an application is a batch job.

A different kind of applications are responsive applications that need to react to some input within some period of time. Examples are user-facing applications (reacting to a click) or applications that react to messages or events. Here response time is important. Response time can be trickier to measure. Each event has its own response time, so you end up with many measurements. Averaging these measurements is a bad idea! You are interested in the outliers: how many there are and how bad they are.

To measure throughput, create a repeatable test where your application does a fixed amount of work (which hopefully also means a fixed amount of logging). For example, process 100,000 records or something like that. You measure how much time it takes to complete this fixed amount of work. Then run this test a few times with the log4j 2.5 libraries, and a few times with the log4j 2.6.1 libraries, and compare how long it takes to complete the task with the different log4j versions.

Tips:

• Be sure to use the same log4j2 configuration for both tests.
• In fact, make sure nothing changes except the log4j library version. Use the same test program (of course), but also ensure that the machine is not also running other tasks than the benchmarking.
• Take a look at JMH (Java benchmark harness) to help you write the benchmark. This helps with warmup and avoiding certain benchmarking pitfalls. This may be less important if the benchmark test runs for several minutes and actually exercises the full application.

Response time is best measured under some workload. Build a test that sends requests to your application at some rate, say 50% your max throughput rate. Measure for all requests how long they took to complete ("service time") and the impact of the slow outliers on the requests that followed ("queuing time"). One slow request can have ripple effect on many requests that follow. This effect is very real for your users but not easy to measure.

Again, run this test (for a certain workload) multiple times with log4j 2.5 and multiple times with log4j 2.6.1.

Tips:

• Take a look at the Pacer class in Log4j2's ResponseTimeTest for some idea on how to implement such a test.
• HdrHistogram is a great tool for efficiently capturing many measurements.
• Vary the workload to get some idea of how your response time behaves under various loads.
• To learn more, watch Gil Tene's eye-opening presentation How NOT to measure latency.

Garbage Collection log options

If you just want to see the difference in the GC logs, I recommend setting at least these options:

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

Perhaps the easiest way to compare is to use some fixed amount of work like in the throughput test above. The most important number in the GC log is the ApplicationStoppedTime (this includes not just GC pause time but also the time spent bringing all threads to a safepoint). Then gather the stats: How many minor collections did the application have when using Log4j 2.5 versus how many with Log4j 2.6.1? What was the total time spent in GCs? Finally, what do the histograms of the collection pauses look like?

Biggest bottleneck first

You may well find that your application has bigger bottlenecks than the GC pauses. In that case, optimizing the GC pauses may not help much. Always focus on the biggest bottleneck first, because the performance behaviour often completely changes when the biggest bottleneck is removed.

Have you used a profiler? I've found Java Flight Recorder (included in the JDK) to be very impressive. Below are example command line options to record statistics into a file profResult.jfr which can then be opened in 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 can give you insight in your application's memory usage, how often garbage collection happens, but also what type of objects are most often created. It also has a very good profiler to help you zoom in on where your application is spending its CPU cycles.