none
Tracing.WriteLine (Custom Trace Listener): Is this a blocking (synchronous) call? RRS feed

  • Question

  • Background: We are looking into using tracing to abstract the logging functions of a system from the core execution path (Observer pattern). We have created our own custom trace listener and overridden the Write & WriteLine methods of the base class.

    Issue: We ran into what we believe is a problem for us: the Trace.WriteLine call appears to be a blocking (synchronous call).  Instead of handling the trace 'events' as they come in, the customer listener serializes the requests and executes them one after another, in order.

    Questions: Is this the expected behavior of the .NET Tracing model? Is this truly the case or is there an attribute that we can apply to our custom trace listener to have it behave as a fire-and-forget operation (e.g. an event)?

     

     

    Wednesday, May 19, 2010 5:03 PM

Answers

  • Eric is correct -- it's synchronous.

    His other idea would work fine, unless there are other usual (synchronous) trace listeners in the Trace.Listeners collection. I'm guessing Trace dispatches a new message to each of its listeners, before it moves to the next message. Therefore, mixing async and sync listeners ruins all the fun.

    By the way, that's a typical issue which arises when you're building an asynchronous logger (has a typical solution too, minus the Trace class, of course). My advice is to not use the static Trace class and carefully consider the issues async logging brings in. One is you can lose all buffered messages that didn't make it to the log because the process terminated. This can be critical when analyzing what went wrong with a component of a distributed system, post-mortem. Second is more subtle and considers logging when the application is shutting down (gracefully) -- depending on the threading model you use, you can again lose the messages, say because the logging thread was a background thread and didn't have a chance to run before the application shut itself down, or you were using a no-message-no-thread pattern, and the new thread didn't get to the scheduler... I've designed a few async loggers and can rant for hours about that. Andrew, do you really want to get the hands dirty?
    • Marked as answer by eryang Tuesday, June 1, 2010 3:03 AM
    Wednesday, May 26, 2010 8:40 PM

All replies

  •  

    Hi,

    I'm sorry, but as far as I know, .NET Trace use synchronous call, and there is no such attribute for custom trace listener to let listener works asynchronously.

     

    However, since you implements custom trace listener, why not add some logic for asynchronous in your listener, for example, in the WriteLine method, put log message in a queue and return immediately.


    Sincerely,
    Eric
    MSDN Subscriber Support in Forum
    If you have any feedback of our support, please contact msdnmg@microsoft.com.
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    Welcome to the All-In-One Code Framework! If you have any feedback, please tell us.
    • Marked as answer by eryang Tuesday, June 1, 2010 3:03 AM
    • Unmarked as answer by Andrew Corley Tuesday, June 1, 2010 1:58 PM
    • Unmarked as answer by Andrew Corley Tuesday, June 1, 2010 1:58 PM
    Thursday, May 20, 2010 8:03 AM
  •  

    Hi,

    I'm writing to check the issue status, please feel free to let us know if you have any concern.


    Sincerely,
    Eric
    MSDN Subscriber Support in Forum
    If you have any feedback of our support, please contact msdnmg@microsoft.com.
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    Welcome to the All-In-One Code Framework! If you have any feedback, please tell us.
    Monday, May 24, 2010 5:10 AM
  • Eric is correct -- it's synchronous.

    His other idea would work fine, unless there are other usual (synchronous) trace listeners in the Trace.Listeners collection. I'm guessing Trace dispatches a new message to each of its listeners, before it moves to the next message. Therefore, mixing async and sync listeners ruins all the fun.

    By the way, that's a typical issue which arises when you're building an asynchronous logger (has a typical solution too, minus the Trace class, of course). My advice is to not use the static Trace class and carefully consider the issues async logging brings in. One is you can lose all buffered messages that didn't make it to the log because the process terminated. This can be critical when analyzing what went wrong with a component of a distributed system, post-mortem. Second is more subtle and considers logging when the application is shutting down (gracefully) -- depending on the threading model you use, you can again lose the messages, say because the logging thread was a background thread and didn't have a chance to run before the application shut itself down, or you were using a no-message-no-thread pattern, and the new thread didn't get to the scheduler... I've designed a few async loggers and can rant for hours about that. Andrew, do you really want to get the hands dirty?
    • Marked as answer by eryang Tuesday, June 1, 2010 3:03 AM
    Wednesday, May 26, 2010 8:40 PM
  •  

    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.


    Sincerely,
    Eric
    MSDN Subscriber Support in Forum
    If you have any feedback of our support, please contact msdnmg@microsoft.com.
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    Welcome to the All-In-One Code Framework! If you have any feedback, please tell us.
    Tuesday, June 1, 2010 3:03 AM
  • ALL:
      Very good input, thank you. I was hoping that we would have a .NET Framework library that would handle the asynchronous messaging for us. I do think tracing has its place, but not necessarily for the system that we are building.

    Mikhail,
      You are correct in pointing out the issues with asynch logging. We decided to 'roll our own' asynchronous logging paradigm. It seems to be working well for us so far. We are requiring the system to gracefully shutdown so that all of the messages 'in queue'  are flushed to storage.

    Tuesday, June 1, 2010 2:05 PM
  • Andrew,

    Glad to be of help. In case you are interested, for the graceful shutdown scenario I used the GoF "State" pattern: the logger is asynchronous until application shutdown starts. But when the app is shutting down, the async logger is flushed and swapped for a synchronous one (atomically) -- it's transparent for the clients since both loggers implement the same interface.

    This approach can lead to lost messages, too, depending on your threading model: since application shutdown timeout is not forever, and the CLR waits for about 4 seconds for process exit handlers to run, before it rudely terminates the process -- still respecting foreground threads, that is. On the extreme, it's possible for the timeout to not be enough to log the message queue. You could use foreground threads to work around that, but I'm not sure if there is some kind of guarantee that your foreground (flushing) thread will get to the scheduler before the process terminates -- it can be starved for the CPU cores by higher priority threads from the process that is shutting down or other processes (and the Balance Set Manager will not have enough time to kick in). Therefore, on the extreme, there seems to be no possibility for building a 100%-reliable async logging system (one that tries to log every message you had thrown at it) in .Net FW. Correct me if I'm wrong here.

    (This, of course, doesn't handle rude process termination -- only sync loggers provide logs which are consistent with what really had been logged before the crash).

    Gotta run to run them tests. Best of luck with the logger!

    Tuesday, June 1, 2010 6:38 PM