Asynchronous Logging with Log4J 2

Asynchronous Logging with Log4J 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:

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.

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

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

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

</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.

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 a BufferedOutputStream. 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>.

Conclusion

In this post, I’ve discussed configuring asynchronous logging in Log4j 2 using the Log4jContextSelector system 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.

3 comments on “Asynchronous Logging with Log4J 2”

Kishore Challa

May 11, 2017 at 11:13 am

When I try this, I am getting below exception

Exception in thread “main” java.lang.NoClassDefFoundError: org/apache/commons/logging/LogFactory
at org.springframework.boot.SpringApplication.(SpringApplication.java:190)
at monsanto.datainsights.sostreaming.SoStreamingApiApplication.main(SoStreamingApiApplication.java:16)
Caused by: java.lang.ClassNotFoundException: org.apache.commons.logging.LogFactory
at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:335)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
… 2 more

Do we also need apache common logging dependency ? If so y ? any explanation would really be appreciated.

Sridhar

January 22, 2018 at 9:48 pm

Hi, It is helpful !

From which part of memory area(System RAM,Heap etc) from the system , the ring buffer size memory has been utilized 256 * 1024 bytes, if i will increase the Ring buffer memory with (1024 * 1024) then how will it impact to the application performance i mean from which memory the 1GB buffer size will get utilized.