Asynchronous Logging With Log4J Part 2

Log4J 2 is a logging framework designed to address the logging requirements of enterprise applications. If you are new to Log4J2, I suggest going through my introductory post on Log4J 2, Introducing Log4J 2 – Enterprise Class Logging.

Log4J 2 introduces configuration support via JSON and YAML in addition to properties file and XML. I’ve written about the different Log4J 2 configuration options in the following posts:

• Log4J 2 Configuration: Using Properties File
• Log4J 2 Configuration: Using XML
• Log4J 2 Configuration: Using JSON
• Log4J 2 Configuration: Using YAML

In this post, we’ll take a look at asynchronous loggers (async loggers) introduced in Log4J 2.

Asynchronous Logging: Introduction

Performance is critical for enterprise applications and nobody wants the underlying logging framework to become a bottleneck. In small programs with little volume, the overhead of logging is rarely an issue. However, enterprise services can see significant volume. If the service is getting invoked hundreds or even thousands of times per second, the overhead of logging can become significant. In such scenarios, two fundamental performance-related concepts are:

• Latency: Time required to perform some action or to produce some result. Time of a transaction, or service invocation.
• Throughput: The number of some actions executed or results produced per unit of time.

For increased logging performance, we want lower logging latency and higher throughput. The asynchronous logger in Log4J 2 does this by decoupling the logging overhead from the thread executing your code. An async logger has consistently lower latency than a synchronous logger and high throughput of logging messages at 6 – 68 times the rate of a synchronous logger.

I/O operations are notorious performance killers. This is because of locks and waits which are typical when dealing with I/O operations.  I/O operations can be executed in a separate thread, thereby freeing the main thread to perform other tasks. With the multicore architectures of modern CPUs, multithreaded operations are an ideal way to improve application performance.

Multi-threaded logging was present prior to Log4J 2 through asynchronous appenders, and its support still exist. The new asynchronous logger differs from asynchronous appender in how work is passed by the main thread to a different thread. Async appender uses an ArrayBlockingQueue – A first-in-first-out (FIFO) queue to hand off the messages to the thread which performs the I/O operations. The ArrayBlockingQueue class internally uses locks to ensure data integrity and data visibility between threads. As locks introduce latency, ArrayBlockingQueue is not the most optimal data structure to pass information between threads. Async logger is designed to optimize this area by replacing the blocking queue with LMAX Disruptor – a lock-free inter-thread communication library. The use of Disruptor results in higher throughput and lower latency in Log4J 2 logging. Martin Fowler has written an excellent article on the architecture of LMAX Disruptor here.

Maven Dependencies

To use async logger in your application, you need to add dependency of LMAX Disruptor in addition to the required Log4J 2 libraries to your Maven POM, like this.

. . .
<dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter</artifactId>
   <exclusions>
      <exclusion>
         <groupId>org.springframework.boot</groupId>
         <artifactId>spring-boot-starter-logging</artifactId>
      </exclusion>
   </exclusions>
</dependency>
<dependency>
   <groupId>org.apache.logging.log4j</groupId>
   <artifactId>log4j-api</artifactId>
   <version>2.5</version>
</dependency>
<dependency>
   <groupId>org.apache.logging.log4j</groupId>
   <artifactId>log4j-core</artifactId>
   <version>2.5</version>
</dependency>
<dependency>
   <groupId>com.lmax</groupId>
   <artifactId>disruptor</artifactId>
   <version>3.3.4</version>
</dependency>
. . .

Configuring Log4J 2

Before we configure Log4J 2 async loggers, lets create a logger class that uses the Log4J 2 API to log messages.

Log4J2AsyncLogger.java

package guru.springframework.blog.log4j2async;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Log4J2AsyncLogger {
    private static Logger logger = LogManager.getLogger();
    public void performSomeTask(){
               logger.debug("This is a debug message.");
               logger.info("This is an info message.");
               logger.warn("This is a warn message.");
               logger.error("This is an error message.");
               logger.fatal("This is a fatal message.");
     }
}

To test the preceding class, we will use JUnit.

Log4J2AsyncLoggerTest.java

package guru.springframework.blog.log4j2async;

import org.junit.Test;
public class Log4J2AsyncLoggerTest {
    @Test
    public void testPerformSomeTask() throws Exception {
        Log4J2AsyncLogger log4J2AsyncLogger=new Log4J2AsyncLogger();
        log4J2AsyncLogger.performSomeTask();
    }
}

Next, we will use XML to configure Log4J2. The log4j2.xml file is this.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
    <Appenders>
        <Console name="Console-Appender" target="SYSTEM_OUT">
            <PatternLayout>
                <pattern>
                    [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
                </pattern>>
            </PatternLayout>
        </Console>
        <File name="File-Appender" fileName="logs/xmlfilelog.log" >
            <PatternLayout>
                <pattern>
                    [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
                </pattern>
            </PatternLayout>
        </File>
    </Appenders>
    <Loggers>
        <Logger  name="guru.springframework.blog.log4j2async" level="debug">
            <AppenderRef ref="File-Appender"/>he preceding c
        </Logger>
        <Root level="debug">
            <AppenderRef ref="Console-Appender"/>
        </Root>
    </Loggers>
</Configuration>

In the code above, we added the status="debug" attribute to the <configuration> tag to output internal Log4J 2 log messages. This is required to verify that log messages are indeed getting logged asynchronously. We then configured a console and a file appender. We also configured an application-specific logger and the root logger to use the file and console appenders respectively. Notice that we haven’t written any asynchronous logging configuration code as of yet.

All Async Loggers

The simplest way to enable asynchronous logging in Log4J 2 is to make all loggers async. This involves setting the Log4jContextSelector system property. On the command line, you can set it like this.

-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

To set the Log4jContextSelector system property in IntelliJ, you need to perform the following steps.

1. Click Run->Edit Configurations from the IntelliJ main menu.
2. Expand the JUnit node on the left pane of the Run/Debug Configurations window that appears, and select the test class.
3. Type -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector in the Vm options text field.

1. Click the OK button.

When you run the Log4J2AsyncLoggerTest test class, the configured loggers will start logging messages asynchronously. You can confirm this in the internal Log4J 2 output, as shown in this figure.

Mixed Sync and Async Loggers

A Log4J 2 configuration can contain a mix of sync and async loggers. You specify application-specific async loggers as <AsyncLogger>, like this.

. . .
<Loggers>
    <AsyncLogger  name="guru.springframework.blog.log4j2async" level="debug">
        <AppenderRef ref="File-Appender"/>
    </AsyncLogger>
    <Root level="debug">
        <AppenderRef ref="Console-Appender"/>
    </Root>
</Loggers>
. . .

In the preceding configuration code, the application-specific logger will asynchronously log messages to the file, while the root logger will synchronously log messages to console.

To make the root logger async, use <AsyncRoot>.

Random Access File Appender

A discussion on asynchronous logging won’t be complete without the mention of the random access file appender. A random access file is similar to the file appender we used, except it’s always buffered with a default buffer size of 256 * 1024 bytes. The buffer size, as of the current release, is not configurable. This means that once the buffer is pre-allocated with a size at first use, it will never grow or shrink during the life of the system. You can override the default size with the AsyncLoggerConfig.RingBufferSize system property. The random access file appender internally uses a ByteBuffer with RandomAccessFile instead of aBufferedOutputStream. This results in significant performance improvement. It is reported to have 20-200% more performance gain as compared to file appender.

Log4J 2 also provides the rolling random access file appender for high performance rolling files. This appender, similar to random access file, is always buffered with the default size of 256 * 1024 bytes, which is not configurable.

I have discussed configuring rolling files here, and also here. To configure a similar rolling random access file appender, replace the <RollingFile> tag with <RollingRandomAccessFile>.

The code to configure a rolling random access file appender, is this.

. . .
<RollingRandomAccessFile name="Rolling-Random-Access-File-Appender"
                          fileName="logs/rollingrandomaccessfile.log"
                          filePattern="archive/logs/rollingrandomaccessfile.log.%d{yyyy-MM-dd-hh-mm}.gz">
    <PatternLayout pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n"/>
    <Policies>
        <SizeBasedTriggeringPolicy size="1 KB"/>
    </Policies>
    <DefaultRolloverStrategy max="30"/>
</RollingRandomAccessFile >
. . .

You can access the above configured appender from an asynchronous logger, like this.

. . .
<Loggers>
    <AsyncLogger  name="guru.springframework.blog.log4j2async" level="debug">
        <AppenderRef ref="Rolling-Random-Access-File-Appender"/>
    </AsyncLogger>
    <Root level="debug">
        <AppenderRef ref="Console-Appender"/>
    </Root>
</Loggers>
. . .

The complete XML code of configuring an async logger to use a rolling random access file appender, is this.

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
    <Appenders>
        <Console name="Console-Appender" target="SYSTEM_OUT">
            <PatternLayout>
                <pattern>
                    [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
                </pattern>>
            </PatternLayout>
        </Console>
        <RollingRandomAccessFile name="Rolling-Random-Access-File-Appender"
                                 fileName="logs/rollingrandomaccessfile.log"
                                 filePattern="archive/logs/rollingrandomaccessfile.log.%d{yyyy-MM-dd-hh-mm}.gz">
            <PatternLayout pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n"/>
            <Policies>
                <SizeBasedTriggeringPolicy size="1 KB"/>
            </Policies>
            <DefaultRolloverStrategy max="30"/>
        </RollingRandomAccessFile>

    </Appenders>
    <Loggers>
        <AsyncLogger  name="guru.springframework.blog.log4j2async" level="debug">
            <AppenderRef ref="Rolling-Random-Access-File-Appender"/>
        </AsyncLogger>
        <Root level="debug">
            <AppenderRef ref="Console-Appender"/>
        </Root>
    </Loggers>
</Configuration>

Conclusion

In this post, I’ve discussed configuring asynchronous logging in Log4j 2 using the Log4jContextSelectorsystem property (for all async loggers) and through <AsyncLogger> and <AsyncRoot> (For mix of sync and async loggers). One common mistakes that programmers make is to mix both of them. Although it works, you will end up with two background threads – an unnecessary thread in the middle that passes a log message from your application to the thread that finally logs the message to disk.

The average Java application will not need the performance benefits of Log4J 2’s asynchronous logging. In many cases, it would simply be overkill. However, Java and the Spring Framework are often used for highly scalable applications processing enormous amounts of information. When you’re developing enterprise class applications, optimal performance does become critical. The option for asynchronous in Log4J 2 is a tool you can use to optimize the performance of your Java and Spring Applications.