Writing to a log4net FileAppender with multiple threads performance problems

Question

TickZoom is a very high performance app which uses it's own parallelization library and multiple O/S threads for smooth utilization of multi-core computers.

The app hits a bottleneck where users need to write information to a LogAppender from separate O/S threads.

The FileAppender uses the MinimalLock feature so that each thread can lock and write to the file and then release it for the next thread to write.

If MinimalLock gets disabled, log4net reports errors about the file being already locked by another process (thread).

A better way for log4net to do this would be to have a single thread that takes care of writing to the FileAppender and any other threads simply add their messages to a queue.

In that way, MinimalLock could be disabled to greatly improve performance of logging.

Additionally, the application does a lot of CPU intensive work so it will also improve performance to use a separate thread for writing to the file so the CPU never waits on the I/O to complete.

So the question is, does log4net already offer this feature? If so, how do you do enable threaded writing to a file? Is there another, more advanced appender, perhaps?

If not, then since log4net is already wrapped in the platform, that makes it possible to implement a separate thread and queue for this purpose in the TickZoom code.

Sincerely, Wayne

EDIT:

Thanks it seems the answers point to developing our own solution as perhaps an extension to log4net in some way. And they clearly show log4net doesn't do this type of thing.

Furthermore, we just realized that we might be "abusing" the logging system which is mainly meant for human readable messages for notifying of important events or debugging information. This particular part of the software output is only really used for automated tools that verify the accuracy of the system.

Of course, we also use log4net in the "normal" ways for debugging, warnings, and such.

But these are more like "transaction logs" than debug or user notification logs. More specifically, it's unnecessary for these logs to be directly human readable. If necessary a "viewer" of some sort can show the contents in ASCII form.

So we will plan on making these transaction-type log get written to a high speed binary storage.

Thanks it seems both of the answers below were great nudges toward developing our own solution.

Chemosmosis

Answer 1

Log4net doesn't support the exact scenario you describe. It does however offer other appenders that don't lock, like the database appender, or the UDP appender. Here are a couple of ideas:

1. Log your messages to a message queue, and then have a reader (or several readers) read messages off the queue and write them to a log. This provides a reliable mechanism to send/write messages. To be honest I don't know if there's already a MSMQ appender, but writing it yourself wouldn't be too hard.

2. Use the UDP appender to send messages and then write your own service that listens to these messages and writes them to a file.

I think you can detect a theme here... basically use one of the non blocking appenders (or write your own) and implement your own service that receives the messages from the appenders and writes them to a file.

Department

Thanks for clarifying it's not possible in log4net and giving the nudge toward an in-house solution. – Chemosmosis

Answer 2

Check out The Object Guy's logger for a high performance, multi-thread safe logger with ability for async logging as well as many other features - quite nice I think - http://www.theobjectguy.com/DotNetLog/. See the Multi-threaded video on this page.

Chick

Answer 3

It is quite desirable to avoid adding any I/O to your targets threads, so sending a message to the logging collector thread is a good idea. I also sometimes use System::Diagnostics::Debug::WriteLine from the target thread to dump out its output, but there's bound to be a little locking inside there anyways.

Of course adding any extra logging is going to lead to "Heisenberg" effects, so you have to somehow know when these effects are negligible and when they're not, in order to have useful logging of your high performance threads.

If you want to get a little fancier, you can have each thread save its own message list, then dump it out somewhere after so many iterations. So the data would only useful in the period of time before any thread does its logging I/O, but maybe you could capture enough info for your debugging. Also, you get the fun task of collating the individual thread logs into a single log for analysis.

Autostability