Non-Blocking Asynchronous Log4J 1.2.x Appender

If you need to log useful information in a high-performance system, you probably want to avoid waiting for the logging system to do its thing and put a brake on your application's throughput. If your logging system is Log4J 1.2.x then you're perhaps using the AsyncAppender to reduce the cost of logging calls made by the application. I offer a high-performance, non-blocking alternative, compatible with Log4J 1.2.x on a Java 5 JVM: the ActiveAsynchronousAppender with the UseCAS parameter.

The ActiveAsynchronousAppender, even in its default configuration, performs better than the AsyncAppender.  When the ActiveAsynchronousAppender's new UseCAS parameter is set to true, the ActiveAsynchronousAppender provides roughly twice the LoggingEvent throughput of the AsyncAppender.

Here's a sample configuration:

<appender name="active-async-appender" class="uk.org.simonsite.log4j.appender.ActiveAsynchronousAppender">
<appender-ref ref="console" />
<param name="BufferSize" value="16" />
<param name="FailToSync" value="false" />
<param name="UseCAS" value="true" /> <!-- false by default -->
</appender>

The profile of the application, the nature of Appenders attached to the ActiveAsynchronousAppender (or AsyncAppender for that matter), amongst other things, can affect the actual throughput.  As with everything there is a trade-off in order to achieve the throughput advantage.  When UseCAS=true, the ActiveAsynchronousAppender is configured such that the LoggingEvent dispatcher thread will continually poll for the presence of LoggingEvents in the queue and yield where non are found, i.e. the dispatch thread continually spins, relying upon the JVM's thread scheduler to allow other threads - application threads - to be executed.  The net result is the cost of higher CPU usage with the gain of higher application throughput.

The AsyncAppender provided by the Apache Foundation's Log4J 1.2.x uses synchronization to block application threads whilst a LoggingEvent is added into the AsyncAppender's event queue. This use of synchronization is relatively expensive since the lock is quite coarse-grained. As previously noted elsewhere in this blog, the AsyncAppender implementation can unpredictably block for longer periods of time when the buffer fills up and it is operating with Blocking=true.  When Blocking=false, LoggingEvents can be discarded by the AsyncAppender such that the unpredictable pause is essentially avoided at the cost of discarded information.  (If the information can be discarded, then I would question why it is being logged in the first place.)

Perhaps worth noting that the synchronization locks used by the AsyncAppender are probably not going to be elided by the JVM.

For more information, including downloads, Maven POM files, test coverage reports, and Javadoc, see www.simonsite.org.uk.