How to effectively log asynchronously?

Question

I am using Enterprise Library 4 on one of my projects for logging (and other purposes). I've noticed that there is some cost to the logging that I am doing that I can mitigate by doing the logging on a separate thread.

The way I am doing this now is that I create a LogEntry object and then I call BeginInvoke on a delegate that calls Logger.Write.

new Action<LogEntry>(Logger.Write).BeginInvoke(le, null, null);

What I'd really like to do is add the log message to a queue and then have a single thread pulling LogEntry instances off the queue and performing the log operation. The benefit of this would be that logging is not interfering with the executing operation and not every logging operation results in a job getting thrown on the thread pool.

How can I create a shared queue that supports many writers and one reader in a thread safe way? Some examples of a queue implementation that is designed to support many writers (without causing synchronization/blocking) and a single reader would be really appreciated.

Recommendation regarding alternative approaches would also be appreciated, I am not interested in changing logging frameworks though.

Answer 1

Just an update:

Using enteprise library 5.0 with .NET 4.0 it can easily be done by:

static public void LogMessageAsync(LogEntry logEntry)
{
    Task.Factory.StartNew(() => LogMessage(logEntry)); 
}

See: http://randypaulo.wordpress.com/2011/07/28/c-enterprise-library-asynchronous-logging/

Answer 2

I wanted to say that my previous post was kind of useless. You can simply set AutoFlush to true and you will not have to loop through all the listeners. However, I still had crazy problem with parallel threads trying to flush the logger. I had to create another boolean that was set to true during the copying of the queue and executing the LogEntry writes and then in the flush routine I had to check that boolean to make sure something was not already in the queue and the nothing was getting processed before returning.

Now multiple threads in parallel can hit this thing and when I call flush I know it is really flushed.

     public static void FlushLogs()
    {
        int queueCount;
        bool isProcessingLogs;
        while (true)
        {
            //wait for the current iteration to complete
            m_waitingThreadEvent.WaitOne();

            //check to see if we are currently processing logs
            lock (m_isProcessingLogsSync)
            {
                isProcessingLogs = m_isProcessingLogs;
            }

            //check to see if more events were added while the logger was processing the last batch
            lock (m_loggerQueueSync)
            {
                queueCount = m_loggerQueue.Count;
            }                

            if (queueCount == 0 && !isProcessingLogs)
                break;

            //since something is in the queue, reset the signal so we will not keep looping

            Thread.Sleep(400);
        }
    }

Answer 3

In response to Sam Safrons post, I wanted to call flush and make sure everything was really finished writting. In my case, I am writing to a database in the queue thread and all my log events were getting queued up but sometimes the application stopped before everything was finished writing which is not acceptable in my situation. I changed several chunks of your code but the main thing I wanted to share was the flush:

public static void FlushLogs()
        {   
            bool queueHasValues = true;
            while (queueHasValues)
            {
                //wait for the current iteration to complete
                m_waitingThreadEvent.WaitOne();

                lock (m_loggerQueueSync)
                {
                    queueHasValues = m_loggerQueue.Count > 0;
                }
            }

            //force MEL to flush all its listeners
            foreach (MEL.LogSource logSource in MEL.Logger.Writer.TraceSources.Values)
            {                
                foreach (TraceListener listener in logSource.Listeners)
                {
                    listener.Flush();
                }
            }
        }

I hope that saves someone some frustration. It is especially apparent in parallel processes logging lots of data.

Thanks for sharing your solution, it set me into a good direction!

--Johnny S

Answer 4

I wrote this code a while back, feel free to use it.

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading;

namespace MediaBrowser.Library.Logging {
    public abstract class ThreadedLogger : LoggerBase {

        Queue<Action> queue = new Queue<Action>();
        AutoResetEvent hasNewItems = new AutoResetEvent(false);
        volatile bool waiting = false;

        public ThreadedLogger() : base() {
            Thread loggingThread = new Thread(new ThreadStart(ProcessQueue));
            loggingThread.IsBackground = true;
            loggingThread.Start();
        }


        void ProcessQueue() {
            while (true) {
                waiting = true;
                hasNewItems.WaitOne(10000,true);
                waiting = false;

                Queue<Action> queueCopy;
                lock (queue) {
                    queueCopy = new Queue<Action>(queue);
                    queue.Clear();
                }

                foreach (var log in queueCopy) {
                    log();
                }
            }
        }

        public override void LogMessage(LogRow row) {
            lock (queue) {
                queue.Enqueue(() => AsyncLogMessage(row));
            }
            hasNewItems.Set();
        }

        protected abstract void AsyncLogMessage(LogRow row);


        public override void Flush() {
            while (!waiting) {
                Thread.Sleep(1);
            }
        }
    }
}

Some advantages:

• It keeps the background logger alive, so it does not need to spin up and spin down threads.
• It uses a single thread to service the queue, which means there will never be a situation where 100 threads are servicing the queue.
• It copies the queues to ensure the queue is not blocked while the log operation is performed
• It uses an AutoResetEvent to ensure the bg thread is in a wait state
• It is, IMHO, very easy to follow

Here is a slightly improved version, keep in mind I performed very little testing on it, but it does address a few minor issues.

public abstract class ThreadedLogger : IDisposable {

    Queue<Action> queue = new Queue<Action>();
    ManualResetEvent hasNewItems = new ManualResetEvent(false);
    ManualResetEvent terminate = new ManualResetEvent(false);
    ManualResetEvent waiting = new ManualResetEvent(false);

    Thread loggingThread; 

    public ThreadedLogger() {
        loggingThread = new Thread(new ThreadStart(ProcessQueue));
        loggingThread.IsBackground = true;
        // this is performed from a bg thread, to ensure the queue is serviced from a single thread
        loggingThread.Start();
    }


    void ProcessQueue() {
        while (true) {
            waiting.Set();
            int i = ManualResetEvent.WaitAny(new WaitHandle[] { hasNewItems, terminate });
            // terminate was signaled 
            if (i == 1) return; 
            hasNewItems.Reset();
            waiting.Reset();

            Queue<Action> queueCopy;
            lock (queue) {
                queueCopy = new Queue<Action>(queue);
                queue.Clear();
            }

            foreach (var log in queueCopy) {
                log();
            }    
        }
    }

    public void LogMessage(LogRow row) {
        lock (queue) {
            queue.Enqueue(() => AsyncLogMessage(row));
        }
        hasNewItems.Set();
    }

    protected abstract void AsyncLogMessage(LogRow row);


    public void Flush() {
        waiting.WaitOne();
    }


    public void Dispose() {
        terminate.Set();
        loggingThread.Join();
    }
}

Advantages over the original:

• It's disposable, so you can get rid of the async logger
• The flush semantics are improved
• It will respond slightly better to a burst followed by silence

Answer 5

Here is what I came up with... also see Sam Saffron's answer. This answer is community wiki in case there are any problems that people see in the code and want to update.

/// <summary>
/// A singleton queue that manages writing log entries to the different logging sources (Enterprise Library Logging) off the executing thread.
/// This queue ensures that log entries are written in the order that they were executed and that logging is only utilizing one thread (backgroundworker) at any given time.
/// </summary>
public class AsyncLoggerQueue
{
    //create singleton instance of logger queue
    public static AsyncLoggerQueue Current = new AsyncLoggerQueue();

    private static readonly object logEntryQueueLock = new object();

    private Queue<LogEntry> _LogEntryQueue = new Queue<LogEntry>();
    private BackgroundWorker _Logger = new BackgroundWorker();

    private AsyncLoggerQueue()
    {
        //configure background worker
        _Logger.WorkerSupportsCancellation = false;
        _Logger.DoWork += new DoWorkEventHandler(_Logger_DoWork);
    }

    public void Enqueue(LogEntry le)
    {
        //lock during write
        lock (logEntryQueueLock)
        {
            _LogEntryQueue.Enqueue(le);

            //while locked check to see if the BW is running, if not start it
            if (!_Logger.IsBusy)
                _Logger.RunWorkerAsync();
        }
    }

    private void _Logger_DoWork(object sender, DoWorkEventArgs e)
    {
        while (true)
        {
            LogEntry le = null;

            bool skipEmptyCheck = false;
            lock (logEntryQueueLock)
            {
                if (_LogEntryQueue.Count <= 0) //if queue is empty than BW is done
                    return;
                else if (_LogEntryQueue.Count > 1) //if greater than 1 we can skip checking to see if anything has been enqueued during the logging operation
                    skipEmptyCheck = true;

                //dequeue the LogEntry that will be written to the log
                le = _LogEntryQueue.Dequeue();
            }

            //pass LogEntry to Enterprise Library
            Logger.Write(le);

            if (skipEmptyCheck) //if LogEntryQueue.Count was > 1 before we wrote the last LogEntry we know to continue without double checking
            {
                lock (logEntryQueueLock)
                {
                    if (_LogEntryQueue.Count <= 0) //if queue is still empty than BW is done
                        return;
                }
            }
        }
    }
}

Answer 6

I suggest to start with measuring actual performance impact of logging on the overall system (i.e. by running profiler) and optionally switching to something faster like log4net (I've personally migrated to it from EntLib logging a long time ago).

If this does not work, you can try using this simple method from .NET Framework:

ThreadPool.QueueUserWorkItem

Queues a method for execution. The method executes when a thread pool thread becomes available.

MSDN Details

If this does not work either then you can resort to something like John Skeet has offered and actually code the async logging framework yourself.

Answer 7

If what you have in mind is a SHARED queue, then I think you are going to have to synchronize the writes to it, the pushes and the pops.

But, I still think it's worth aiming at the shared queue design. In comparison to the IO of logging and probably in comparison to the other work your app is doing, the brief amount of blocking for the pushes and the pops will probably not be significant.

Answer 8

Yes, you need a producer/consumer queue. I have one example of this in my threading tutorial - if you look my "deadlocks / monitor methods" page you'll find the code in the second half.

There are plenty of other examples online, of course - and .NET 4.0 will ship with one in the framework too (rather more fully featured than mine!). In .NET 4.0 you'd probably wrap a ConcurrentQueue<T> in a BlockingCollection<T>.

The version on that page is non-generic (it was written a long time ago) but you'd probably want to make it generic - it would be trivial to do.

You would call Produce from each "normal" thread, and Consume from one thread, just looping round and logging whatever it consumes. It's probably easiest just to make the consumer thread a background thread, so you don't need to worry about "stopping" the queue when your app exits. That does mean there's a remote possibility of missing the final log entry though (if it's half way through writing it when the app exits) - or even more if you're producing faster than it can consume/log.

Answer 9

If you log something on a separate thread, the message may not be written if the application crashes, which makes it rather useless.

The reason goes why you should always flush after every written entry.

Answer 10

An extra level of indirection may help here.

Your first async method call can put messages onto a synchonized Queue and set an event -- so the locks are happening in the thread-pool, not on your worker threads -- and then have yet another thread pulling messages off the queue when the event is raised.