none
How Do I maintain the chronological order in which Asynchronous delegate calls are made? RRS feed

  • Question

  • I have created a basic logging framework for my application that writes log messages to a local text file using an Asynchronous delegate.

    My application has many threads running however, and as a result, the order of the log entries in the text file is not chronological.

    So I have two competing requirements: on one hand, my WriteToLog() method has to return almost immediately so that it doesn't block in-flight code, while at the same time the log file has to be in chronological order.

    Any ideas?  Some of the problems I've encountered are:

    1a.  Trying to use a Queue (with a lock{ } around it) to maintain the order seems to result in deadlocks

    1b.  Even if I use a Queue, at some point the Queue must be written to disk, so it seems like I'd have to frequently have WriteToLog spin off a "WriteToDisk" like method.

    2a.  I've considered instantiating a new thread which polls the Queue from (1a) and writes to disk in a loop, say, every 5 seconds.  I'm leaning more towards this method.

    3.  I've looked into log4net and some other stuff but it just seems like overkill, and I'd really like to have my own framework for this seemingly simple task.

     

    Thanks!

    Tuesday, July 27, 2010 3:01 PM

Answers

  • Hi Matt,

     

    the problems you have have been encountered by others already:

    http://blogs.msdn.com/b/agile/archive/2009/06/19/thoughts-on-improving-performance-of-the-logging-application-block.aspx

    Besides this obvious problems you have a principal one. If your log rate is higher than the disk write performance you will either overflow your queue or you need to block until the queue is emptied before you can continue. Either way you are not getting more speed out of it. If you log rate is very high you should consider a tracing framework like the one used by the ApiChange tool.

    If logging is your goal you should check out the Enterprise Library Logging Application Block.

    Yours,

      Alois Kraus

     

    • Marked as answer by SamAgain Thursday, August 5, 2010 6:18 AM
    Tuesday, July 27, 2010 9:34 PM
  • Thank you all for your suggestions.  I apologize I did not reply earlier (Didn't receive a notification email!  Darn System.Net.Mail (?))

    I will share my solution with you, since it's unlikely I will receive much glory from any customers ("Wow, awesome logging features!").

    1.  The first method simply obtains a "place holder" (the long Order variable) then asynchronously calls a method to write the log file to disk.

        public static void WriteToLog(string Message, LogLevel Severity)
        {
    
          long Order = Interlocked.Increment(ref LogOrder);
    
          // Return immediately if logging is off
          if (!_logEnabled) return;
    
          // Asynchronously call WriteToLogSynchronous
          WriteToLogAsyncDelegate d = new WriteToLogAsyncDelegate(WriteToLogSynchronous);
          d.BeginInvoke(Message, Severity, Order, null, null);
        }
    

     2.  The WriteToLogAsyncDelegate writes a log entry to the text file and looks like this:

    1 Log entry message goes here

    3.  The resultant log file is still out of order, but at least we know the proper order:

    1 Log entry message goes here

    3 Notice that it's not in order though

    2 Because it's being called by different threads

    7 at different times

    4.  I wrote a Windows Forms "Log Viewer" application that parses the log file, adds all entries to a SortedList<Int64, String>

    The program then displays the SortedList in ListView control.

    5.  I also implemented a "Circuit Breaker" feature in the logging that disables logging if it reaches a certain threshold (to accomodate the disk write speed scenario mentioned by Alois)

    6.  Performance tested the logging and it works perfectly for our applications.

     

    Hope this helps someone out there.  Contact me if you'd like more insight or details.

     

    Best

    Matt

    Tuesday, September 28, 2010 4:00 PM

All replies

  • Hi Matt,

     

    the problems you have have been encountered by others already:

    http://blogs.msdn.com/b/agile/archive/2009/06/19/thoughts-on-improving-performance-of-the-logging-application-block.aspx

    Besides this obvious problems you have a principal one. If your log rate is higher than the disk write performance you will either overflow your queue or you need to block until the queue is emptied before you can continue. Either way you are not getting more speed out of it. If you log rate is very high you should consider a tracing framework like the one used by the ApiChange tool.

    If logging is your goal you should check out the Enterprise Library Logging Application Block.

    Yours,

      Alois Kraus

     

    • Marked as answer by SamAgain Thursday, August 5, 2010 6:18 AM
    Tuesday, July 27, 2010 9:34 PM
  • Hi,

       Thanks for your post. I don't think using a queue and lock it could make any difference from just appending to a log file on disk. The log entries in the queue could still not be in chronological order. To make the log entries in chronological order, we have to make the entry writes in chronological order. I am not sure what your in-chronological order log looks like. Could you show some symptoms you are encountering now? Such as the logs you got for now. If the log speed is very high, Alois got the point.

        Following is some test code for mimicing. I am not sure if its logic is similar to yours. Some more info is necessary so we can work it out together.

     

    using System;
    using System.IO;
    using System.Threading;
    
    namespace MultiThread_Write_Log
    {
     class Program
     {
      public delegate void LogDelegate();
      public static Object locker = new Object();
    
      static void Main(string[] args)
      {
       LogDelegate d1 = new LogDelegate(WriteLog);
    
       IAsyncResult r1 = d1.BeginInvoke(null, null);
       IAsyncResult r2 = d2.BeginInvoke(null, null);
    
       Console.ReadLine();   
      }
    
      public static void WriteLog()
      {
       while (true)
       {
        lock (locker)
        {
         String content = String.Format("ID:{0} - {1}", Thread.CurrentThread.ManagedThreadId.ToString(), DateTime.Now.ToString());
         StreamWriter sw = File.AppendText(@"D:\dummies\log.txt");
         sw.WriteLine(content);
         sw.Flush();
         sw.Close();
         Console.WriteLine(content);
        }
        Thread.Sleep(1000);
       }
      }
     }
    }
    

     

     


    Please mark the right answer at right time.
    Thanks,
    Sam
    • Edited by SamAgain Thursday, July 29, 2010 6:24 AM refine
    Thursday, July 29, 2010 5:43 AM
  • Hi,

      I am writing to check the status of the thread. How is your problem going on?


    Please mark the right answer at right time.
    Thanks,
    Sam
    Wednesday, August 4, 2010 10:31 AM
  • We temporarily mark a reply, please remember to click "Mark as Answer" on the post that helps you, and to click "Unmark as Answer" if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread.
    Please mark the right answer at right time.
    Thanks,
    Sam
    Thursday, August 5, 2010 6:18 AM
  • Thank you all for your suggestions.  I apologize I did not reply earlier (Didn't receive a notification email!  Darn System.Net.Mail (?))

    I will share my solution with you, since it's unlikely I will receive much glory from any customers ("Wow, awesome logging features!").

    1.  The first method simply obtains a "place holder" (the long Order variable) then asynchronously calls a method to write the log file to disk.

        public static void WriteToLog(string Message, LogLevel Severity)
        {
    
          long Order = Interlocked.Increment(ref LogOrder);
    
          // Return immediately if logging is off
          if (!_logEnabled) return;
    
          // Asynchronously call WriteToLogSynchronous
          WriteToLogAsyncDelegate d = new WriteToLogAsyncDelegate(WriteToLogSynchronous);
          d.BeginInvoke(Message, Severity, Order, null, null);
        }
    

     2.  The WriteToLogAsyncDelegate writes a log entry to the text file and looks like this:

    1 Log entry message goes here

    3.  The resultant log file is still out of order, but at least we know the proper order:

    1 Log entry message goes here

    3 Notice that it's not in order though

    2 Because it's being called by different threads

    7 at different times

    4.  I wrote a Windows Forms "Log Viewer" application that parses the log file, adds all entries to a SortedList<Int64, String>

    The program then displays the SortedList in ListView control.

    5.  I also implemented a "Circuit Breaker" feature in the logging that disables logging if it reaches a certain threshold (to accomodate the disk write speed scenario mentioned by Alois)

    6.  Performance tested the logging and it works perfectly for our applications.

     

    Hope this helps someone out there.  Contact me if you'd like more insight or details.

     

    Best

    Matt

    Tuesday, September 28, 2010 4:00 PM
  • It would be perhaps much easier to write your strings to a Queue<string> which is guarded by a lock. Then create one writer thread which waits until data to write is present and deques the strings. On the writer side you only need to lock on the queue and Enqueue your log message.

    This way you do not need to complicate the reader and much more important you will be much faster. The overhead to send your log messag to an thread pool thread for every log message (context switching, IAsyncResult allocation, Thread pool queue deque, ...) is much higher than to simply put it into a thread safe queue. \

    This is called producer consumer pattern and it is a very efficient one. You would want to use the Thread Pool Threads BeginInvoke, Endinvoke when you do something more costly like reading a file or something like this. But you need also to take care that not too many calls are pending which will degrade performance as well. The exact number depends on the things you do on your thread pool thread. For CPU bound operations you should not run more than two times the number of cores.

    Wednesday, December 7, 2011 9:39 AM