Logging frameworks and multithread compatibility

Note that I have seen these questions here on SO (which discuss the thread safety of log4net) and I suspect that they answer my question, but I am going to ask anyway:

Multithread safe logging

Log4Net FileAppender not thread safe?

Recently I have written a WCF service for logging. The idea is very similar to Clog (or look for Clog under Calcium). Basically, I have implemented a logging API for use in a Silverlight client (a Silverlight class library). The logging API is, more or less, a clone of the Common.Logging for .NET API which we are using elsewhere in our application. The implementation of the API forwards all logging messages to a WCF logging service that, itself, is implemented in terms of Common.Logging.

While looking at Clog I found the following code in the Log4NetStrategy class that struck me as a little bit odd:

/// <summary> 
/// All Write log calls are done asynchronously because the DanielVaughan.Logging.Log 
/// uses the AppPool to dispatch calls to this method. Therefore we need to ensure 
/// that the call to Log is threadsafe. That is, if an appender such as FileAppender is used, 
/// then we need to ensure it is called from no more than one thread at a time. 
/// </summary>
/// <param name="logger">The logger.</param>
/// <param name="loggingEvent">The logging event.</param>
[MethodImpl(MethodImplOptions.Synchronized)]
static void WriteThreadSafe(ILogger logger, LoggingEvent loggingEvent)
{
  logger.Log(loggingEvent);
}

Log4NetStrategy (and the strategies for NLog and EnterpriseLibrary as well) implements an interface that has a method like Write(ILogEntry logEntry). ILogEntry is essentially the DTO that the Clog logging service received from the client. The information from the logEntry is extracted and used to create a log4net LoggingEvent. The appropriate log4net logger is also retrieved based on the logger name in the ILogEntry DTO. After the log4net LoggingEvent is created, it and the logger are sent to the WriteThreadSafe method above and logged via log4net. The NLog and EnterpriesLibrary implementations are similar.

In pseudocode, the "Write" method on the Clog logging service looks something like this:

// Write on the logging service
// Send the input log entry to each configured strategy.
public void Write(ILogEntry logEntry)
{
  foreach (ILoggingStrategy ls in loggingStrategies)
  {
    ls.Write(logEntry);
  }
}

// Write on the Log4NetStrategy
// Convert the logEntry to log4net form and log with log4net
public void Write(ILogEntry logEntry)
{
  log4net.LoggingEvent le = ConvertToLoggingEvent(logEntry);
  ILog logger = log4net.GetLogger(logEntry.Logger);
  WriteThreadSafe(logger, le);
}

So here is my question开发者_运维百科... Generally log4net (and NLog and, I assume, EnterpriseLibrary) are considered to be multithread compatible. That is, the user of the public API can simply call log.Info, log.Log, etc and not be concerned about running in a multithreaded environment. The logging framework should take care of ensuring that the logging calls (and any processing within the logging calls) are threadsafe.

If the logging frameworks are multithread compatible, then is the use of the

[MethodImpl(MethodImplOptions.Synchronized]

attribute really needed? It seems like this would (or could) just cause a bottleneck by forcing all logging messages to be handled synchronously, even though the underlying logging framework should be able to handle logging in a multhithreaded environment.

In the case of my logging service (which could be multithreaded), it doesn't seem like it would be necessary to synchronize the calls like this. It seems like I should be able to take my logging input from the service call, construct the appropriate logging structure (based on the underlying logging framework), and just log it. If my logging service is multithreaded, it should "just work" because the underlying logging framework should support it (multithreading).

Does this make sense? Is the explicit synchronization of logging calls (at least for log4net and NLog) really necessary?

Why The Locks?

As far as I remember in Enterprise Library uses the .NET Tracelistener class which has a property IsThreadSafe. If the listener is thread safe no synchronization is performed. For a file as output device there is no reason to synchronize access from several threads unless your StreamWriter which internally holds the write buffer could become corrupted by unsynchronized writes. This is the reason why you need to get a synchronized StreamWriter to write to a file from different threads.

But at any rate this is more of academic interest. When you allow only one thread to write at a time you still can generate several hundred MB of output which brings even the fastest hard disc down. You are IO bound when you write to file. The slowest thing in the whole chain is the hard disc and not your synchronized write to a file. But sometimes it is nice to have the output of several processes in one file. Log4Net for example cannot do it.

... How do I get multiple process to log to the same file?

The FileAppender holds a write lock on the log file while it is logging. This prevents other processes from writing to the file, therefore it is not possible to have multiple processes log directly to the same log file, even if they are on the same machine. ...

Formatting Performance

Even if you think that the lock is costing you performance there are often other costs overlooked. The configurable output format is very nice but at least the formatting in Enterprise Library until 4.0 was very slow. I have made it over 13 times faster which resulted in a net file throughput increase of a factor 2.

Concurrent Writes To File

With a little Win32 magic it is possible to write reliable from different processes into the same file concurrently. But to come back to your question if synchronization is needed: It may be needed depending on the output device.

Scalabilty

If your concern is scalability then you need to have a per thread buffer which is merged at a defined point in time to allow fast data gathering. Then you can implement a global ring buffer which gets from all threads the formatted data where the oldest data is overwritten. When something interesting happens you can dump the whole ring buffer to disc. This design is ~10-20 times faster than any file appender. Windows Event Tracing does employ the ring buffer trick which is blazingly fast.

Since you asked about locking I do think that speed is your main concern. If that assumption is correct you should have a look at a tracing framework like the one the ApiChange tool uses. It has some innovative approaches like automatic exception tracing when your method is left with an exception or fault injection to unit test the error path without the need to modify your product code.

To be scalable you should differentiate between logging and tracing as I have explained here: Logging is not Tracing..

Lock Free

If you want to create a scalable tracing framework you need to pass all your data for one trace call as immutable data, format the data into a string and pass it on to your output device. It can be as simple as (C# Pseudo Code)

1. Trace.Info("blahh {0}", data);
2. traceString = Format(formatString, args, CurrentTime);
3. Write(traceString);

When the data is not stored in a class or the class members do not change after it has been initialized you will never need a lock. You have to be careful that you do share e.g. the formatting buffer between threads. To be scalable you need to set your design priorities for thread safety in the following order.

1. Isolation This is by far the best solution. If the problem can be sliced in a way that several threads can operate independently you never need to think about locking or shared data.
2. Immutability The second best solution is to share data but once more than one thread can "see" it it must never change. This can be achieved e.g. with objects which do have only getters and all data is passed via the ctor.
3. Locking If you use lock free or some locking strategy does not matter much. You are in the world of pain where you must pay attention to processor caches, false sharing and if you are brave you even try some lock free method only to find out that it at best gets twice as fast as a normal lock. In some cases lock free code can be slower.

If you want to read more about threading details I recommend Joe Duffys blog.

Tracing Strategy

To write maintainable software you need to be able to follow your application and data flow. Only then you can diagnose problems which happen only at your customer site. It does pay off to "clutter" your code with traces which do give you enough information to diagnos a problem quickly. You can trace too much or too less or not relevant data. One good trace line which does correlate e.g. your XPath query string with the file it operates on is much better as scattered pieces of information in your log file.

Yours, Alois Kraus