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.

ActiveAsynchronousAppender Overhauled

I originally wrote the ActiveAsynchronousAppender back in 2008 as an alternative to the out-of-the-box Log4J AsyncAppender.  The reasons for having done so back then still hold today:

• The AsyncAppender appends all events from its logging event buffer in a single loop before rechecking the buffer.  This can block the application if application threads are queueing for the buffer lock - behaviour somewhat similar to a GC pause.
• The AsyncAppender fails to synchronous appending if a RuntimeException is encountered by its logging event dispatch thread.

The original incarnation of the ActiveAsynchronousAppender was designed for operation on Java 1.4 VMs.  It could also take advantage of the backport-util-concurrent if so configured.  There were some problems:

• The original ActiveAsynchronousAppender depended upon the backport-util-concurrent in order to take advantage of newer concurrency features.  If you either didn’t want to or couldn’t put the backport-util-concurrent 3.1 JAR in your CLASSPATH, then the ActiveAsynchronousAppender was stuck with Java 1.4 synchronization.
• It was unable to take advantage of the native concurrency APIs on Java 1.5 and higher VMs.
• Due to a similarity with the AsyncAppender, the ActiveAsynchronousAppender shared a bug caused by LoggingEvents not having been fully rendered before being handed off to an attached Appender.

All of the above problems have been solved in the new version of the ActiveAsynchronousAppender.  Check it out at www.simonsite.org.uk.

uk.org.simonsite.log4j.appender.TimeAndSizeRollingAppender

I have been thinking for a little while now that the name of the package in which the TimeAndSizeRollingAppender (TASRA) lives is perhaps inappropriate.  From its original inception back in 2008, through successive releases to date, the TASRA has lived in the package org.apache.log4j.appender.  However, development of the TASRA is neither sponsored nor otherwise supported by the Apache Foundation: the code is not bundled with any Log4J distros, it is not managed within an Apache repository, nor is there any reference to it on the Apache websites outside of forum postings and JIRA items that refer to it.  The only connection with Apache is the fact that the TASRA is distributed under the Apache 2.0 license.

At a technical level, a user recently requested a change of package name such that the TASRA could be more readily deployed within a JBoss environment.  I have no experience of JBoss, nor the use of signed JARs which drove the user’s particular request.  However, this has provided a concrete reason to change the name of the package within which the TASRA will reside.

Provided there is no significant objection from users all future releases the TASRA will live in the uk.org.simonsite.log4j.appender package.

For most users, the only difference will be that configuration must change to use the new fully-qualified class name (uk.org.simonsite.log4j.appender.TimeAndSizeRollingAppender).  For advanced users, import declarations will need to be updated and code recompiled.  Outside of that the TASRA will continue to work as before.

I intend to make this change soon.

Compression Added

I received a code contribution for the TimeAndSizeRollingAppender from Eduardo Simioni, providing two new features:

1. Backup log files can be compressed.
2. The scavenger thread that deletes older files can be configured not to run, thereby conserving resources whilst allowing a virtually unlimited number of backups.

I've extended the contribution to support both GZIP and ZIP via configuration. Obviously you can use only one compression algorithm at a time. New source and binaries available in the usual place.

TimeAndSizeRollingAppender Updated

Thanks to Eduardo and Nick who pointed out a couple of bugs in the TimeAndSizeRollingAppender. The first was a start-up bug which meant that the writer was not being initialised with the size of an existing log file. The second was an NPE issue that occurred if a filename was configured without a path. Both are fixed and the new code is available for download at http://www.simonsite.org.uk/resources/lib/log4j-rolling-appender.jar.