Programmers Stack Exchange is a question and answer site for professional programmers interested in conceptual questions about software development. Join them; it only takes a minute:

Sign up
Here's how it works:
  1. Anybody can ask a question
  2. Anybody can answer
  3. The best answers are voted up and rise to the top

In many of the services I work on there are a lot of logging being done. The services are WCF services(mostly) which use the .NET EventLogger class.

I'm in the process of improving these services' performance, and I got to think that logging asynchronously would benefit performance.

I'm unaware to what happens when multiple threads ask to log, and it if creates a bottleneck, but even if it doesn't I still think that it shouldn't interfere with the actual process being executed.

My thoughts are that I should invoke the same log method I call now but do so using a new thread, while continuing with the actual process.

Some questions about that:

Is it ok?

Are there any downsides?

Should it be done in a different way?

Maybe its so fast that it doesn't even worth the effort?

share|improve this question
1  
Have you profiled the runtime(s) to know that logging has a measurable effect on performance? Computers are just too complex to just think that something might be slow, measure twice and cut once is good advice in any profession =) – Patrick Hughes May 20 '12 at 15:10
    
@PatrickHughes - some stats from my tests on one specific request: 61(!!) log messages, 150ms before doing some sort of simple threading, 90ms after. so it is 40% faster. – Mithir May 21 '12 at 10:14
up vote 4 down vote accepted

Separate thread for I\O operation sounds reasonable.

For example, it would be not good to log which buttons user has pressed in the same UI thread. Such UI will hang at random and have slow perceived performance.

The solution is to decouple event from its processing.

Here is a lot of information about Producer-Consumer Problem and Event Queue from game development world

Often there is a code like

///Never do this!!!
public void WriteLog_Like_Bastard(string msg)
{
    lock (_lockBecauseILoveThreadContention)
    {
        File.WriteAllText("c:\\superApp.log", msg);
    }
}

This approach will lead to Thread Contention. All processing threads will be fighting to be able to obtain lock and write to the same file at once.

Some may try to remove locks.

public void Log_Like_Dumbass(string msg)
{
      try 
      {  File.Append("c:\\superApp.log", msg); }
        catch (Exception ex) 
        {
            MessageBox.Show("Log file may be locked by other process...")
        }
      }    
}

It is not possible to predict the result if 2 threads will enter method at the same time.

So eventually developers will disable logging at all...

Is it possible to fix?

Yes.

Lets say we have interface:

 public interface ILogger
 {
    void Debug(string message);
    // ... etc
    void Fatal(string message);
 }

Instead of waiting for lock and performing blocking file operation every time when ILogger is called we will Add new LogMessage to the Penging Messages Queue and return to more important things:

public class AsyncLogger : ILogger
{
    private readonly BlockingCollection<LogMessage> _pendingMessages;
    private readonly Type _loggerFor;
    private readonly IThreadAdapter _threadAdapter;

    public AsyncLogger(BlockingCollection<LogMessage> pendingMessages, Type loggerFor, IThreadAdapter threadAdapter)
    {
        _pendingMessages = pendingMessages;
        _loggerFor = loggerFor;
        _threadAdapter = threadAdapter;
    }

    public void Debug(string message)
    {
        Push(LoggingLevel.Debug, message);
    }

    public void Fatal(string message)
    {
        Push(LoggingLevel.Fatal, message);
    }

    private void Push(LoggingLevel importance, string message)
    {
        // since we do not know when our log entry will be written to disk, remember current time
        var timestamp = DateTime.Now;
        var threadId = _threadAdapter.GetCurrentThreadId();

        // adds message to the queue in lock-free manner and immediately returns control to caller
        _pendingMessages.Add(LogMessage.Create(timestamp, importance, message, _loggerFor, threadId));
    }
}

We have done with this simple Asynchronous Logger.

Next step is to process incoming messages.

For the simplicity, lets start new Thread and wait forever until application exits or Asynchronous Logger will add new message to the Pending Queue.

public class LoggingQueueDispatcher : IQueueDispatcher
{
    private readonly BlockingCollection<LogMessage> _pendingMessages;
    private readonly IEnumerable<ILogListener> _listeners;
    private readonly IThreadAdapter _threadAdapter;
    private readonly ILogger _logger;
    private Thread _dispatcherThread;

    public LoggingQueueDispatcher(BlockingCollection<LogMessage> pendingMessages, IEnumerable<ILogListener> listeners, IThreadAdapter threadAdapter, ILogger logger)
    {
        _pendingMessages = pendingMessages;
        _listeners = listeners;
        _threadAdapter = threadAdapter;
        _logger = logger;
    }

    public void Start()
    {
        //  Here I use 'new' operator, only to simplify example. Should be using interface  '_threadAdapter.CreateBackgroundThread' to allow unit testing
        Thread thread = new Thread(MessageLoop);
        thread.Name = "LoggingQueueDispatcher Thread";
        thread.IsBackground = true;

        thread.Start();
        _logger.Debug("Asked to start log message Dispatcher ");

        _dispatcherThread = thread;
    }

    public bool WaitForCompletion(TimeSpan timeout)
    {
        return _dispatcherThread.Join(timeout);
    }

    private void MessageLoop()
    {
        _logger.Debug("Entering dispatcher message loop...");
        var cancellationToken = new CancellationTokenSource();
        LogMessage message;

        while (_pendingMessages.TryTake(out message, Timeout.Infinite, cancellationToken.Token))
        {
            // !!!!! Now it is safe to use File.AppendAllText("c:\\my.log") without ever using lock or forcing important threads to wait.
            // this is example, do not use in production
            foreach (var listener in _listeners)
            {
                listener.Log(message);
            }
        }

    }
}

I'm passing chain of custom listeners. You may probably want to just send call logging framework (log4net, etc...)

Here is the rest of code:

public enum LoggingLevel
{
    Debug,
    // ... etc
    Fatal,
}


public class LogMessage
{
    public DateTime Timestamp { get; private set; }
    public LoggingLevel Importance { get; private set; }
    public string Message { get; private set; }
    public Type Source { get; private set; }
    public int ThreadId { get; private set; }

    private LogMessage(DateTime timestamp, LoggingLevel importance, string message, Type source, int threadId)
    {
        Timestamp = timestamp;
        Message = message;
        Source = source;
        ThreadId = threadId;
        Importance = importance;
    }

    public static LogMessage Create(DateTime timestamp, LoggingLevel importance, string message, Type source, int threadId)
    {
        return  new LogMessage(timestamp, importance, message, source, threadId);
    }

    public override string ToString()
    {
        return string.Format("{0}  [TID:{4}] {1:h:mm:ss} ({2})\t{3}", Importance, Timestamp, Source, Message, ThreadId);
    }
}

public class LoggerFactory : ILoggerFactory
{
    private readonly BlockingCollection<LogMessage> _pendingMessages;
    private readonly IThreadAdapter _threadAdapter;

    private readonly ConcurrentDictionary<Type, ILogger> _loggersCache = new ConcurrentDictionary<Type, ILogger>();


    public LoggerFactory(BlockingCollection<LogMessage> pendingMessages, IThreadAdapter threadAdapter)
    {
        _pendingMessages = pendingMessages;
        _threadAdapter = threadAdapter;
    }

    public ILogger For(Type loggerFor)
    {
        return _loggersCache.GetOrAdd(loggerFor, new AsyncLogger(_pendingMessages, loggerFor, _threadAdapter));
    }
}

public class ThreadAdapter : IThreadAdapter
{
    public int GetCurrentThreadId()
    {
        return Thread.CurrentThread.ManagedThreadId;
    }
}

public class ConsoleLogListener : ILogListener
{
    public void Log(LogMessage message)
    {
        Console.WriteLine(message.ToString());
        Debug.WriteLine(message.ToString());
    }
}

public class SimpleTextFileLogger : ILogListener
{
    private readonly IFileSystem _fileSystem;
    private readonly string _userRoamingPath;
    private readonly string _logFileName;
    private FileStream _fileStream;

    public SimpleTextFileLogger(IFileSystem fileSystem, string userRoamingPath, string logFileName)
    {
        _fileSystem = fileSystem;
        _userRoamingPath = userRoamingPath;
        _logFileName = logFileName;
    }

    public void Start()
    {
        _fileStream = new FileStream(_fileSystem.Path.Combine(_userRoamingPath, _logFileName), FileMode.Append);
    }

    public void Stop()
    {
        if (_fileStream != null)
        {
            _fileStream.Dispose();
        }
    }

    public void Log(LogMessage message)
    {
        var bytes = Encoding.UTF8.GetBytes(message.ToString() + Environment.NewLine);
        _fileStream.Write(bytes, 0, bytes.Length);
    }
}

public interface ILoggerFactory
{
    ILogger For(Type loggerFor);
}

public interface ILogListener
{
    void Log(LogMessage message);
}

public interface IThreadAdapter
{
    int GetCurrentThreadId();
}

public interface IQueueDispatcher
{
    void Start();
}

Entry point:

public static class Program
{
    public static void Main()
    {
        Debug.WriteLine("[Program] Entering Main ...");

        var pendingLogQueue = new BlockingCollection<LogMessage>();


        var threadAdapter = new ThreadAdapter();
        var loggerFactory = new LoggerFactory(pendingLogQueue, threadAdapter);


        var fileSystem = new FileSystem();
        var userRoamingPath = GetUserDataDirectory(fileSystem);

        var simpleTextFileLogger = new SimpleTextFileLogger(fileSystem, userRoamingPath, "log.txt");
        simpleTextFileLogger.Start();
        ILogListener consoleListener = new ConsoleLogListener();
        ILogListener[] listeners = new [] { simpleTextFileLogger , consoleListener};

        var loggingQueueDispatcher = new LoggingQueueDispatcher(pendingLogQueue, listeners, threadAdapter, loggerFactory.For(typeof(LoggingQueueDispatcher)));
        loggingQueueDispatcher.Start();

        var logger = loggerFactory.For(typeof(Console));

        string line;
        while ((line = Console.ReadLine()) != "exit")
        {
            logger.Debug("you have entered: " + line);
        }

        logger.Fatal("Exiting...");

        Debug.WriteLine("[Program] pending LogQueue will be stopped now...");
        pendingLogQueue.CompleteAdding();
        var logQueueCompleted = loggingQueueDispatcher.WaitForCompletion(TimeSpan.FromSeconds(5));

        simpleTextFileLogger.Stop();
        Debug.WriteLine("[Program] Exiting... logQueueCompleted: " + logQueueCompleted);

    }



    private static string GetUserDataDirectory(FileSystem fileSystem)
    {
        var roamingDirectory = Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData);
        var userDataDirectory = fileSystem.Path.Combine(roamingDirectory, "Async Logging Sample");
        if (!fileSystem.Directory.Exists(userDataDirectory))
            fileSystem.Directory.CreateDirectory(userDataDirectory);
        return userDataDirectory;
    }
}
share|improve this answer

Key factors to consider are your need for reliability in the logfiles and the need for performance. Refer downsides. I think this is a great strategy for high performance situations.

Is it ok - yes

Are there any downsides - yes - depending on the criticality of your logging and your implementation any of the following could occur - logs written out of sequence, log thread actions not complete before event actions complete. (Imagine a scenario where you log "starting to connect to DB" and you then crash the server, log event may never get written even though the event has occurred (!))

Should it be done in a different way - you might want to look at Disruptor model as it's almost ideal for this scenario

Maybe its so fast that it deosn't even worth the effort - disagree. If yours is an "application" logic, and the only thing you do is write logs of the activity - then you will be orders of magnitude lower latency by offloading logging. If however you rely on a 5sec DB SQL call to return before logging 1-2 statements, the benefits are mixed.

share|improve this answer

I think logging is generally a synchronous operation by it's nature. You want to log things if they happen or if they don't depending on your logic, so in order to log something, that thing needs to be evaluated first.

Having said that, you can improve your application's performance by caching logs and then creating a thread and saving them to files when you have a CPU bound operation.

You need to identify your checkpoints cleverly so you don't lose your important logging information during that cache period.

If you want to have a performance boost in your threads you need to balance IO operations and CPU operations.

If you create 10 threads that all do IO, then you won't get a performance boost.

share|improve this answer
    
How would you suggest caching logs? there are request-specific items in most log messages in order to identify them, in my service exact same requests rarely occur. – Mithir May 22 '12 at 5:20

Logging asynchronously is the only way to go if you need low-latency in the logging threads. The way this is done for maximum performance is through the disruptor pattern for lock-free and garbage-free thread communication. Now if you want to allow multiple threads to log concurrently to the same file you must either synchronize the log calls and pay the price in lock contention OR use a lock-free multiplexor. For example, CoralQueue provides a simple multiplexing queue as described below:

enter image description here

You can take a look on CoralLog which uses these strategies for asynchronous logging.

Disclaimer: I am one of the developers of CoralQueue and CoralLog.

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.