0

I have a simple logger with producer consumer pattern based on BlockingCollection (code is below).

public class Logger
{
    public Logger()
    {
        _messages = new BlockingCollection<LogMessage>(int.MaxValue);
        _worker = new Thread(Work) {IsBackground = true};
        _worker.Start();
    }

    ~Logger()
    {   
        _messages.CompleteAdding();
        _worker.Join();                 // Wait for the consumer's thread to finish.
        //Some logic on closing log file
    }

    /// <summary>
    /// This is message consumer thread
    /// </summary>
    private void Work()
    {
        while (!_messages.IsCompleted)
        {
            //Try to get data from queue
            LogMessage message;
            try
            {
                message = _messages.Take();
            }
            catch (ObjectDisposedException) { break; }    //The BlockingCollection(Of T) has been disposed.
            catch(InvalidOperationException){ continue; } //the BlockingCollection(Of T) is empty and the collection has been marked as complete for adding.

            //... some simple logic to write 'message'
        }
    }
}

The problem is that application is not ending instantly with that. It takes 20-40 seconds to end an application and if I pause it with debugger in a middle, I see that:
1. GC.Finalize thread is set on _worker.Join();
2. _worker thread is on _messages.Take().

I would await that _messages.Take() is ended short after _messages.CompleteAdding(); But looks like it is not.

What's wrong with this finalization and how to better finalize worker thread in this situation?

P.S. I could simply drop _worker.Join() but then Work() can write something to closed file. I mean, this is concurrent non determined situation then.

Update
As a proof of concept I've renamed ~Logger() to Close() and call it at some point. It closes logger instantly. So _messages.Take() is ending right after _messages.CompleteAdding() as expected in this case.

The only explanation of the 20-40 seconds delay in ~Logger I see in high priority of the GC thread. Could there be another explanation?

MajesticRa
  • 13,770
  • 12
  • 63
  • 77
  • Yes, the delay you observed was due to the fact that the finalizer was not called for a very long time, because the GC just didn't need to reclaim space. – drwatsoncode Dec 27 '12 at 09:48
  • @ricovox I really appreciate your help! But, please, be more thoughtful with stackoverflow questions. Your comment has nothing to do with the question asked. – MajesticRa Dec 27 '12 at 10:13

1 Answers1

3

In C#, Finalizers (aka destructors) are non-deterministic, which means you cannot predict when they will be called or in what order. For example in your code, it's entirely possible for the finalizer of _worker to be before after the finalizer for Logger. For this reason, you should never access managed objects (such as FileStreams etc) inside a finalizer, because the finalizers of other managed resources could have already completed, making their references invalid. Also the finalizer will not be called until after the GC determines that a collection is necessary (due to the need for additional memory). In your case, the GC probably takes 20-40 seconds before it makes the required collection(s).

What you want to do is get rid of the finalizer and use the IDisposable interface instead (optionally with a Close() method that might provide better readability).

Then you would just call logger.Close() when it is no longer required.

void IDisposable.Dispose()
{   
     Close();
}

void Close() 
{
    _messages.CompleteAdding();
    _worker.Join(); // Wait for the consumer's thread to finish.
    //Some logic on closing log file
}

In general, only use a finalizer when you have unmanaged resources to clean up (for example, if you are using P/Invoke WinAPI function calls etc). If you are using only .Net classes, etc. you probably do not have any reason to use one. IDisposable is almost always the better choice, because it provides deterministic cleanup.

For more information on finalizers vs destructors, take a look here: What is the difference between using IDisposable vs a destructor in C#?

Another change I would make in your code is using TryTake instead of Take. This gets rid of the need for the try/catch because it will not throw an exception when the collection is empty and CompleteAdding is called. It will simply return false.

private void Work()
{
    //Try to get data from queue
    LogMessage message;
    while (_messages.TryTake(out message, Timeout.Infinite))
       //... some simple logic to write 'message'       
}

The two exceptions you catch in your code can still occur for other reasons such as accessing it after it is disposed or modifying the BlockingCollection's underlying collection (see MSDN for more info). But neither of those should occur in your code, because you don't hold a reference to the underlying collection, and you don't dispose of the BlockingCollection before the Work function is complete. If you still wanted to catch those exceptions, just in case, you can place a try/catch block outside of the while loop (because you would NOT want to continue the loop after either exception occurs).

Finally, why do you specify int.MaxValue as the collection's capacity? You shouldn't do this unless you expect to routinely add close to that many messages to the collection.

So altogether, I would re-write your code as follows:

public class Logger : IDisposable
{
    private BlockingCollection<LogMessage> _messages = null;
    private Thread _worker = null;
    private bool _started = false;

    public void Start() 
    {
        if (_started) return;
        //Some logic to open log file
        OpenLogFile();      
        _messages = new BlockingCollection<LogMessage>();  //int.MaxValue is the default upper-bound
        _worker = new Thread(Work) { IsBackground = true };
        _worker.Start();
        _started = true;
    }

    public void Stop()
    {   
        if (!_started) return;

        // prohibit adding new messages to the queue, 
        // and cause TryTake to return false when the queue becomes empty.
        _messages.CompleteAdding();

        // Wait for the consumer's thread to finish.
        _worker.Join();  

        //Dispose managed resources
        _worker.Dispose();
        _messages.Dispose();

        //Some logic to close log file
        CloseLogFile(); 

        _started = false;
    }

    /// <summary>
    /// Implements IDiposable 
    /// In this case, it is simply an alias for Stop()
    /// </summary>
    void IDisposable.Dispose() 
    {
        Stop();
    }

    /// <summary>
    /// This is message consumer thread
    /// </summary>
    private void Work()
    {
        LogMessage message;
        //Try to get data from queue
        while(_messages.TryTake(out message, Timeout.Infinite))
            WriteLogMessage(message); //... some simple logic to write 'message'
    }
}

As you can see, I added Start() and Stop() methods to enable/disable queue processing. If you want, you can call Start() from your constructor, but in general, you probably don't want expensive operations (such as thread creation) in a constructor. I used Start/Stop instead of Open/Close, because it seemed to make more sense for a logger, but that's just a personal preference, and either pair would work fine. As I mentioned before, you don't even have to use a Stop or Close method. Simply adding Dispose() is enough, but some classes (like Streams etc) use Close or Stop as an alias for Dispose just to make the code more readable.

Community
  • 1
  • 1
drwatsoncode
  • 4,721
  • 1
  • 31
  • 45
  • Thank you for the answer! I updated the post, so you can see the effect of calling Close() method directly. But the question is a bit more tricky here. I'm not trying to predict at what point of time what finalizer is hit. The code is straight and it works the same as using a debugger proves. The only difference is that calling the same code from GC thread takes 20-40 seconds to execute. The problem implementing of IDisposable is that this logger is used through some ServiceLocator and... Should service locators decide at what point to dispose their items? - It is another question, probably. – MajesticRa Dec 27 '12 at 09:27
  • I'll take a look at `ServiceLocator` and see if I can make this comment more detailed, but without knowing too much about the full scope of this Logger class in your application, I can't really say too much except that Logger should be disposed once you are completely done using it. If that is when the application closes, it's just fine. You can call it at the very end of your `Main()` function or in Application events such as Exit or the AppDomain ProcessExit event if necessary. – drwatsoncode Dec 27 '12 at 09:52
  • Hi! Thank you for updating. 1. I have read about Finalizer vs IDisposable. I know trade off. 2. TryTake instead of Take - no way. Take - waits. TryTake in while will waste CPU. Try it. Read docs. 3. Start() and Stop() is a bad idea in this case. Since they are starting a new thread it is possible that messages are still being written while Stop() and new Start() is called. _started should be fenced. Read about it. So it adds huge complexities if one would like to implement it safely. 4.Two exceptions I catch OCCURE from time to time. And logger is not the only producer consumer. – MajesticRa Dec 27 '12 at 09:59
  • In response to #2: Thanks for pointing out my mistake with TryTake. I should have specified Timeout.Infinite (-1) as the second parameter. This will cause the function to block as expected, but will still avoid the exception. – drwatsoncode Dec 27 '12 at 10:49
  • let us [continue this discussion in chat](http://chat.stackoverflow.com/rooms/21764/discussion-between-majesticra-and-ricovox) – MajesticRa Dec 27 '12 at 12:13