Using asynchronous log4net appenders for high performance logging

16 March 2013

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:

ThreadPool.QueueUserWorkItem(task => logger.Debug("This is a log entry"));

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:

for (int n = 1; n <= 5; n++)
{
    logger.DebugFormat("Log entry {0}", n);
}

The output will be something like this:

DEBUG Log entry 1
DEBUG Log entry 2
DEBUG Log entry 3
DEBUG Log entry 4
DEBUG Log entry 5

If you encapsulated the same code within a parallel task as shown below it will run a lot faster as execution continues immediately after the final task has been queued on the thread pool:

for (int n = 1; n <= 5; n++)
{
    Task.Run(() => logger.DebugFormat("Log entry {0}", n));
}

However, the results won’t be quite what you expected as every line will report the line number as it was when the loop finished executing:

DEBUG Log entry 6
DEBUG Log entry 6
DEBUG Log entry 6
DEBUG Log entry 6
DEBUG Log entry 6

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.

public void Debug(string message)
{
    ThreadPool.QueueUserWorkItem(task => logger.Debug(message));
}

This would at least guarantee that any logged state information will be accurate, though the ordering of entries will not be corrected as shown by the results below:

DEBUG Log entry 1
DEBUG Log entry 5
DEBUG Log entry 2
DEBUG Log entry 3
DEBUG Log entry 4

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.

public class AsyncFileAppender : AppenderSkeleton
{
    private StreamWriter writer;
    private TextWriter wrapper;

    public AsyncFileAppender() 
    {
        writer = new StreamWriter("C:\\async-log.txt");
        wrapper = TextWriter.Synchronized(writer);
    }

    protected override void Append(LoggingEvent loggingEvent)
    {
        Task.Run(() => wrapper.WriteLine(loggingEvent.RenderedMessage));
    }

    protected override void OnClose()
    {
        wrapper.Dispose();
        writer.Dispose();
        base.OnClose();
    }
}

Filed under Architecture.