log4net - Some fun with appenders

One of the most frequent logger mechanisms that is used in our days is log4net. This is an open source framework that can be found on different programming language, like Java and C#.

I played a little with log4net in the last period of time to see if log4net can become a bottleneck of an application. What I observed until now is the call duration of the appender is the longest call. Even if C# knows about async calls to IO resources, log4net will make all this calls in a sync way.

Usually if we have around 100 messages per second, the default log4net mechanism will be perfect for us. For these cases, if you want to improve the performance we should use the TraceAppender. Yes, the default appended from .NET. It works great and is pretty fast. This is a pretty good option if you don’t want to use a buffer appender. There are a lot of frameworks that used Trace – don’t be afraid of using it.

Another option is to use buffer appender. This is an appender that will not send messages immediately. We will send the messages only in the moment when there will be a specific number of messages in the buffer. The log4net already has this kind of appender defined (“BufferingForwardingAppender”). You should know that even if we are using the buffer the IO calls are still made sync. This means that in the moment when the buffer will be full and need to flush the content, there will be a sync IO call.  

A nice feature of this appender is the lossy option. Using this option you can set the buffer to flush the content in the case when a specific type of message is wrote into the buffer – for example when an error is logged.

What we observed until now is the way how the IO is used – we have only sync calls to the files. Because of this we could have some bottlenecks at this level. Theoretically we could improve the log4net performance if we would use async calls – when writing to files.

I didn’t have time to implement and measure, but I think that it would be pretty interesting. One solution is to make the calls async at the appender level. We could make the calls that write the buffered content to run on a different thread. This solution could cause problems because creating and working with thread is a pretty expensive thing – from resource perspective.

Another option would be to use async write calls to IO. For example we could use IO completion ports. This would be a pretty clever thing to do, but is a little bit complicated. Playing with IO completion ports is not simple.

The last option that I see valid is to use a thread (maybe a background thread) that writes the content to IO. Using this method, our application will be able to send content to the log4net without the need to wait after log4net to append/persist the content. The real action of writing the content to IO (file for example) will be made by the second thread. The drawback is from the second thread. It will need to run all the time. This thread will be created by appender. It is not important how we will append the content (async/sync) way, because we are already on another thread and the log4net calls will don’t need to wait until the content is written.

Until now I didn’t heard people to have problems with log4net – performance problems. If we configure log4net properly, we should not have any kind of problems. This investigation was only for fun, to see if we could improve the performance of log4net.