Using asynchronous log4net appenders for high performance logging

Although you can get pretty decent logging performance out of log4net with the out-of-the-box appenders there will be times when you need greater throughput. You may be logging repetitive actions at a very low level that trigger hundreds of thousands of log messages a second. If you want to log to a shared data source such as a database then the extra latency could create a real processing bottleneck.

Log4net is a synchronous engine. A pretty well designed one, but a synchronous engine all the same. Ultimately you will need an asynchronous implementation for high performance logging, though a little caution is advised as you will need to ensure that you do not lose control over what is getting logged.

Don’t make any assumptions

You shouldn’t assume that log4net is acting as a bottleneck as it may be adding less latency than you think. It depends very much on the appender that you’re using. The out-of-the-box FileAppender can work through entries at a fair pace and I have benchmarked it at more than 35,000 1k log entries per second on my (creaking) laptop.

The file appenders aren’t your only option as you can get even faster throughput with the TraceAppender depending on how you output the messages. If you need short bursts of high logging performance then consider using the BufferingForwardAppender to buffer log writes until you have an opportunity to flush them through.

Logging with asynchronous tasks

For serious throughput you can consider making your log calls asynchronous. The simplest way to do this is to “fire and forget” and queue the task on the thread pool:

Task.Run(() => logger.Debug("This is a log entry"));

Although this is the preferred way of queuing work to the thread pool, you won’t need the extra functionality that comes with the TPL such as status reporting, custom scheduling, cancellation and exception management. Given that logging is such as fire and forget activity you might prefer to use the QueueUserWorkItem in the ThreadPool:

This approach does have a couple of significant drawbacks, both related to the fact that you lose control over when the log events are written. Firstly, you won’t be able to control the order of log events so they will not be written sequentially. A more subtle yet serious problem is that log messages are not formatted until the task actually executes, which can give rise to erroneous state information being reported as part of the logging message.

For example, the code sample below appends a sequential counter onto a set of ten log statements:

This is happening because the thread is not actually getting round to executing the log action until after the for\next loop has completed. To avoid getting this inaccurate state information you would have to wrap the call into a method as shown below.

Writing an asynchronous appender

You can log asynchronously with log4net, but this should be done at the appender level rather than the logger level. Log4net is synchronous until the final call to the appender and this is the point at which you can push the formatted messages out using threads from the pool.

There is no default solution for an asynchronous appender, but they are pretty easy to write so you can tailor one to your own specific requirements. At the very most basic level you just need to implement the abstract AppenderSkeleton class and override the Append method.

The listing below shows a bare bones asynchronous file appender. A StreamWriter is wrapped into a synchronized TextWriter to provide thread safety. The Append method just sets off a task to writer the message that has been passed in by the logger. This approach will give you the full performance boost of asynchronous logging without the loss of logging accuracy, though you will still have to accept the loss of control over the order in which messages are written.

About me

I am a London-based technical architect who has spent more than twenty years leading development across start-ups, digital agencies, software houses and corporates.
Over the years I have built a lot of stuff including web sites and services, multi-screen applications, systems integrations and middleware.

My current focus is on enabling scalable SaaS delivery and providing architectural leadership in agile environments.
I currently work as Chief Architect for Wolters Kluwer UK leading them to cloud heaven, one service at a time. Opinions are my own and not the views of my employer, etc.

Recent

There does seem to be growing confusion over what Service Fabric is really for. Is it an orchestrator for microservices? A means of lifting and shifting legacy applications into the cloud? An application development framework?

Azure Functions only provides direct support for a narrow range of authentication providers. If you want to use an external token provider or custom solution, you’ll have to create the plumbing yourself.

ArchUnit is a java library that provides a fluent API for creating self-testing architectures via unit tests. A similar library can be written for .Net Standard that acts on compiled assemblies rather than raw code.

There is a growing sense of unease around how larger organisations have implemented agile. In particular, there is a tendency towards centralised control that can be at odds with the agile preference for individuals over process.