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.

Reducing Threads in the TimeAndSizeRollingAppender

Several people have commented that the TimeAndSizeRollingAppender could, where many instances were configured, launch many threads.  With date roll enforcement, backup log file scavenging, and backup log file compression all configured, there could be 3 threads per TASRA instance.  That simply didn’t scale.  The original design assumption that only one or two TASRA instances would be configured per application was clearly broken.

I have begun some work to minimise the number of threads launched where multiple TASRA instances are configured.  The first fruits of that have been released and can be downloaded from www.simonsite.org.uk.

The changes permit an arbitrary number of TASRA instances to share a single thread for all backup log file scavenging and backup log file compression tasks.  Date roll enforcement is still carried out on a separate daemon thread, for now.

The benefit is best illustrated with some numbers; taking an arbitrary 10 TASRA instances as opposed to just one to better illustrate the effect:

TASRA configuration	Daemon thread count per 10 TASRA instances
	20120703-0826 Release	20130130-1840 Release
ScavengeInterval=300000, DateRollEnforced=true, CompressionAlgorithm=ZIP	30	11
ScavengeInterval=300000, DateRollEnforced=false, CompressionAlgorithm=ZIP	20	1
ScavengeInterval=300000, DateRollEnforced=false, CompressionAlgorithm=default (not set)	10	1
ScavengeInterval=-1, DateRollEnforced=false, CompressionAlgorithm=default	0	0

By default, all TASRA instances will now share the same thread.  Optionally, m TASRA instances may be configured to use n threads, where m >= n >= 1.  To do this, a common named object must be shared by all TASRA instances that will share the same thread, and distinct named object(s) for any other TASRA instances that will use different thread(s).  The following sample configuration illustrates two TASRA instances, “appender-1” and “appender-2”, each using its own thread, “executor-1” or “executor-2”, respectively, in this case for scavenging and compression tasks:

       <appender name="file-appender-1"

              class="uk.org.simonsite.log4j.appender.TimeAndSizeRollingAppender">

              <param name="File" value="${tasra.xml.test.log.file.1}" />

              <layout class="org.apache.log4j.SimpleLayout" />

              <param name="CompressionAlgorithm" value="ZIP" />

              <logTaskExecutorService class="uk.org.simonsite.log4j.appender.NamedLoggingTaskExecutorService">

                     <param name="Name" value="executor-1" />

              </logTaskExecutorService>

       </appender>

       <appender name="file-appender-2"

              class="uk.org.simonsite.log4j.appender.TimeAndSizeRollingAppender">

              <param name="File" value="${tasra.xml.test.log.file.2}" />

              <layout class="org.apache.log4j.SimpleLayout" />

<param name="CompressionAlgorithm" value="ZIP" />

              <logTaskExecutorService class="uk.org.simonsite.log4j.appender.NamedLoggingTaskExecutorService">

                     <param name="Name" value="executor-2" />

              </logTaskExecutorService>

       </appender>

Log4J 1.2.17 Support

A handful of things to report this time around.

First and foremost I've widened the testing for both TimeAndSizeRollingAppender and ActiveAsynchronousAppender to include Log4J 1.2.17.  There are only a few changes in 1.2.17 and no changes were required to either the TimeAndSizeRollingAppender or ActiveAsynchronousAppender to be fully compatible.  The Maven 2 POM file dependency still shows up as 1.2.16, however this is a fairly arbitrary choice based upon improvements in threading behaviour in 1.2.16; there's no reason not to edit this for use with 1.2.15 or 1.2.17 if desired.

Secondly, the unit test coverage for the ActiveAsynchronousAppender has been increased considerably.  Some slight inconsistencies in the behaviour of classes targeted towards specific Java versions have been ironed out.

Finally, the www.simonsite.org.uk hosting has been moved.  A problem with IPS tag provisioning, caused by my original hosting provider, resulted in the site going offline for over a week.  This was highly regrettable and I apologise for any inconvenience this may have caused.  The site is back online after having completed the move to its new home.  New versions of the TimeAndSizeRollingAppender and ActiveAsynchronousAppender can be downloaded from www.simonsite.org.uk as before.

I hope the Appenders continue to be useful.

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.

Test Coverage for the TimeAndSizeRollingAppender

I've noticed a habit that I've got into lately to pay more attention to freely available software if the unit test and coverage reports are available.  So I figured it might be useful to make the JUnit and EMMA results available with the latest release of the TimeAndSizeRollingAppender.  The test coverage is reasonably comprehensive and covers all the critical areas pretty well, I hope.  Take a look and let me know whether it's useful.

There are a couple of bug fixes and optimisations in the past couple of releases that mean the Appender should be moderately more performant.  I haven't got around to profiling it yet, which would obviously be the proof of the pudding, but at least one significant change will definitely help: at file roll there should be about half the regex pattern matching there used to be.

TimeAndSizeRollingAppender release 20101024-1105

Several fixes and new features in the release 20101024-1105 available from www.simonsite.org.uk.

Briefly these include:

• Still compatible with Java 1.4; now only compatible with Log4J 1.2.15+.
  
• Both ZIP and GZ compression now use NIO to offer dramatic performance improvements. NB This is compatible with Java 1.4.
• File rollover fix for a scenario where scavenging was turned off, compression was turned on. In the error scenario, slow compression combined with rapidly-filling log files could see backup files deleted erroneously. Backups are now identified by file name pattern matching instead of file modification time, thereby eliminating the cause of the scenario.
  
• RollOnStartup now rolls the current log file upon Appender activation (or re-activation). Previously the Appender would only do the start-up roll upon receiving the first logging event from the application. Therefore the first log roll may not have actually taken place until some considerable time after start-up.
• Thread-safety improvements including finer-grained synchronization and local copying.
• Daemon threads already running (i.e. scavenger, compressor, roll enforcer) are stopped when the Appender is re-activated (via activateOptions()). This will prevent memory leaks and unpredictable behaviour if the Appender's properties are changed after initial activation. This is only really of concern if the Appender's properties are managed programmatically.

Kudos are due to Oleksiy Pastukhov, Adrian Carcu, Scott Skinner, and Craig Chapel for their contributions and suggestions.