Tuesday 23 October 2007

Log4J Asynchronous Appender

I've been working on an alternative to the Log4J AsyncAppender. OK, but why bother when the standard Log4J AsyncAppender works well enough? In a heavily-threaded application the AsyncAppender can block when its buffer is full, and the dispatcher thread is still busy appending LoggingEvents. This is because AsyncAppender grabs all LoggingEvents from its buffer, and appends all those LoggingEvents in a single loop before checking the buffer contents again. Such blocking is analagous to a GC pause.

In trying to minimise such pauses whilst maximising throughput, I've come up with a slightly different solution to the same problem that AsyncAppender tries to address. The ActiveAsynchronousAppender I have developed blocks when the buffer is full, however it only appends a single LoggingEvent from its buffer at a time, before checking the buffer again. As soon as the buffer is below its maximum size, the appender ceases to block.

I've run the new code against the Log4J 1.2.15 unit tests for the AsyncAppender, and the important tests pass. The caveat is that my code is not designed for "non-blocking" operation, i.e. it cannot be configured to discard LoggingEvents when the appender's buffer is full.

What are the benefits of the new code? As with the standard Log4J AsyncAppender, it depends in no small part upon the nature of the application, and tuning the size of the appender's buffer. I don't yet have any hard figures to demonstrate whether my appender code offers any significant advantage over the existing Log4J AsyncAppender. A couple of things I'm looking at:

  • Reduced blocking should lead to higher application throughput
  • Fewer LoggingEvents on the stack of a daemon thread may mean more reliable logging at the end of an application lifecycle (not sure about this)

7 comments:

Simon said...

I've updated the code for the alternative asynchronous appender after expanding the original test suite, and ensured compatibility from Log4J 1.2.12 up to Log4J 1.2.15. More documentation etc. on my home page.

Unknown said...

I am currently using the ActiveAsyncAppender and it seems to be working great; however, it would be really great to tune the appender to behave between your approach and the normal Async Appender.

Let's say I could configure the amount of messages the Appender should write while blocking on full buffer, so Ithat each time I get a full buffer, I could tune the behaviour to match the application specific needs.

Simon said...

Hi schmiedel,

I'll take a look and see what I can come up with.

Anonymous said...

Awesome website, I hadn't noticed simonsiteblog.blogspot.com before in my searches!
Keep up the fantastic work!

Anonymous said...

Thanks for sharing the link, but unfortunately it seems to be offline... Does anybody have a mirror or another source? Please reply to my post if you do!

I would appreciate if a staff member here at simonsiteblog.blogspot.com could post it.

Thanks,
Jack

Simon said...

The link in this blog post works fine as far as I can tell. If you're still having issues with it, see my website at <a href="www.simonsite.org.uk>www.simonsite.org.uk</a>.

Anonymous said...

Thanks for sharing this link, but unfortunately it seems to be down... Does anybody have a mirror or another source? Please reply to my post if you do!

I would appreciate if a staff member here at simonsiteblog.blogspot.com could post it.

Thanks,
Peter