Rational Java: Allocation free logging with log4j2

Introduction

Recently I was working for a client trying to remove some GC pauses for a large well crafted Java system. After profiling I realised that most of the garbage was being produced by logging!! Was there a simple unobtrusive way to remove all that allocation? Turns out there was :)

Which framework should I use for GC free logging?

Let's turn our attention back to the age old question of which logging framework to use.

The usual candidates are

log4j2
logback
java.util.logging
slf4j (simple)

and unless you are doing something super funky you might not think it makes a huge difference which one you choose.

There have been many studies done comparing performance and those of course this can be important if you are playing in the ultra low latency arena. (see Benchmarking Java logging frameworks)

But what I'm concerned about is allocation!!

See my earlier post on the evils of allocation The First Rule of Performance Optimisation.

In a typical system 30%-50% of all allocation can be in logging!!

So even if most people don't mind if logging takes a couple of milliseconds longer in one framework than another they will almost certainly care about long GC pauses caused by the garbage created by the logging framework.

And all this logging allocation can be removed by simple configuration.

Log4J2 from 2.6 onwards is allocation free so really no excuse not to take advantage of it :)

Let's see it in action

It's one thing making the allocation free claim but let's see if this holds true in practice.

Consider this simple logging code below: Note that I've used slf4j in the code and therefore only need change the configuration to run with the different logging frameworks. It's a good idea to do this because although log4j2 might be the best framework at the moment who knows what tomorrow will bring...

Run with log4j2 - no allocation

If we configure the program to run with log4j2 using this maven configuration:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.25</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.9.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.9.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.9.1</version>
</dependency>

And we use this log4j2 configuration

xml version="1.0" encoding="UTF-8" ?><Configuration status="INFO">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss:SSS} [%t] %-5level %logger[36] %msg%n"></PatternLayout>
        </Console>
        <File name="MyFile" fileName="all.log" immeadiateFlush="false" append="false">
            <PatternLayout pattern="%d{dd MMM yyyy HH:mm:ss,SSS} [%t] %-5level %logger[36] %msg%n"></PatternLayout>
        </File>
    </Appenders>
    <Loggers>
        <Root level="debug">
            
            <AppenderRef ref="MyFile"></AppenderRef>
        </Root>
    </Loggers>
</Configuration>

Then we get 0 allocation!

We can prove this by running Flight Recorder on the program (see below):

The only memory being allocated is due to Flight Recorder (by the way FR can be configured so that this doesn't happen).

Run using logback

Try exactly the same this using Logback.

Use this Maven configuration

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

Use this logback configuration:

<configuration>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>myApp.log</file>
        <encoder>
            <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>
    <root level="debug">
        <appender-ref ref="FILE" />
        
    </root>
</configuration>

And when we run with Flight Recorder we see a hug amount allocation!

But a word of warning....

You need to use the log4j2 configuration exactly as specified in the documentation see supported layouts. If you even change date format slightly allocation will again be rampant.