This time I wanted to write something about the .NET Framework that is solved not optimal of the .NET Framework. My unsuspecting victim is the well known System.Diagnostics.Trace class. Static classes have the big plus that they are easy to use but they can be very hard to maintain if you want to extend it (no derivation) and have a lifetime problem with the objects that are created inside it. The Trace facade is in my opinion a prominent example of how you should not design a reliable static facade class. It’s has many features that are nice but it’s at the same time a fine example of design that has lost its vision. It tries to do too many things at the same time without succeeding in the optimal solution for all the goals it might have. Tracing should be fast, right? The .NET Trace definitely not the fastest solution. Yes it’s flexible and can be very good configured inside your App.config file. But if you have used the Microsoft Logging Application Block of Enterprise Library 2.0 once then you know how much farther design for flexibility can be done. But I must admit that the Entlib TraceListeners does derive from the .NET ones. Below is a +- table about the .NET Trace regarding Performance Reliability and Extensibility.
In the following article I will show you what reliability issues there are and how to solve them.
| Performance | Reliability | Extensibility/ Ease of use |
|---|---|---|
| + TraceSwitches allow to configure at run time what should be traced. – DefaultTraceListener uses OutputDebugString which is by far the slowest method to trace. | – I loose traces if I do not call Trace.Close/Flush from time to time. – Static Trace.Close is a mistake because I cannot really close something that is static. – A Trace.Write after a Trace.Close causes loss of all following traces in case of file based listeners. (+ Some Listeners do reopen itself after being closed. The File Listener can do this if you init it with a file name) | + Dynamic Trace Switch Configuration + Dynamic Trace Listener Configuration -Other (Logging) solutions are far more flexible. – It is nearly impossible to write a program that does capture all traces even during application shutdown. |
The most obvious reliability problem I did find is demonstrated with a very simple Console Application:
class Program
{
static void Main(string[] args)
{
Program pr = new Program(); // Create instance that will be finalized later
TextWriterTraceListener listener =
new TextWriterTraceListener(@"C:\trace.txt");
Trace.Listeners.Clear(); // Remove default trace listener
Trace.Listeners.Add(listener);
Trace.WriteLine("First Trace"); // Generate some trace messages
Trace.WriteLine("Perhaps last Trace.");
}
}This small program does generate a 0 byte trace log file on my hard disk. Why? Because the StreamWriter is not flushed during Application exit. You can set the Trace.AutoFlush property to true for all trace listeners but you will loose about 30-50% throughput by doing this. Tracing should not alter application timing because if your (e.g. multithreading) timing dependant error goes away when you attach a debugger or enabling tracing you are left with the last option to insert printf statements inside your code and try it then again. For this reason we should strive for maximal speed and reliable delivery of our trace messages at the same time to make this worst case scenario happen less often..
Ok if I want performance then I will call Trace.Flush from time to time to ensure that my traces are written. During application exit I have to place the Trace.Close (Trace.Flush produces the same problem) at a strategic place to ensure that my traces are written.
class Program
{
~Program()
{
Trace.Close(); // ensure that all traces are flushed (Trace.Flush has the
// same effect that is shown below)
}
static void Main(string[] args)
{
Program pr = new Program(); // Create instance that will be finalized later
TextWriterTraceListener listener =
new TextWriterTraceListener(@"C:\trace.txt");
Trace.Listeners.Add(listener);
Trace.WriteLine("First Trace"); // Generate some trace messages
Trace.WriteLine("Perhaps last Trace.");
}
}Ok that does look better. We do now ensure that we flush the underlying StreamWriter in our Finalizer. But wait Finalizers are not always called during application shutdown. We can remedy this situation by deriving from CriticalFinalizerObject. Due to our efforts to make it more reliable we are greeted with the following output:
Unhandled Exception: System.ObjectDisposedException: Cannot access a closed file.
at System.IO.__Error.FileNotOpen()
at System.IO.FileStream.Write(Byte[] array, Int32 offset, Int32 count)
at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
at System.IO.StreamWriter.Dispose(Boolean disposing)
at System.IO.StreamWriter.Close()
at System.Diagnostics.TextWriterTraceListener.Close()
at System.Diagnostics.TraceInternal.Close()
at System.Diagnostics.Trace.Close()
at TraceTest.Program.Finalize()
Hey who did invite this exception to our party? To better understand whats going on we have to understand what does happen under the covers of the static Trace facade.
From the functional point of view our simple file trace is exactly the same as the following code snippet:
static void Main(string[] args)
{
FileStream file = new FileStream(@"C:\Trace.txt", FileMode.Create);
StreamWriter writer = new StreamWriter(file);
writer.WriteLine("Our Trace Line");
}Do you see the problem here? Who does close the StreamWriter to flush its cache? If you run this program the result is a 0 byte Trace.txt with nothing inside it. This is exactly what we got when we configured the TextWriterTraceListener into the static Trace facade. Lets have a look into FileStream and StreamWriter.
As you can see from the class diagram a StreamWriter does hold a reference to the underlying file stream which in turn does encapsulate the real file handle via a safe handle. What is interesting in this picture that StreamWriter does NOT implement a finalizer whereas FileStream and SafeHandle do. This was decided by the CLR team as working model for streams to ensure that programmers close the darn StreamWriter before they exit or they will loose (consistently) data (= 0 byte Trace.txt). If StreamWriter did implement a finalizer it could work or not work depending on the order the finalizers are called. We can now imagine why the ObjectDisposedException was thrown.
Our problem here was that during AppDomain shutdown all finalizers are called in an arbitrary order. In our case we did try to flush our unsaved data while the FileStream was already finalized! If the CLR does change its GC implementation the following could also happen:
We are left in the unfortunate situation that an exception can happen or not depending when we call (Trace.) Close. This is certainly a problem if we trace inside our finalizers and try to get the output away before our underlying file stream is finalized.
Static Facade Resource Management
The 10000$ question is if we can manage resources that are acquired by static facades. If we do nothing about this we loose trace messages. The protocol for static facades should be the following:
- Acquire (static) Resources.
- Use static facade
- During application shutdown release resources as late as possible.
- After the resource release we ignore future calls to our static facade.
Sounds rather easy. And the truth it is easy to manage static resources. The new resource handling protocol for static facades goes like this
- Acquire Resources (FileStream, …)
- Create your own static resource holder which does derive from CriticalFinalizerObject
- Prevent finalization of the acquired resources (GC.SuppressFinalize)
- Finalize the resources in our static resource holder in the order which is needed.
Thats really easy to do. Lets have a look at my brand new StaticResourceManager class:
/// <summary>
/// Ensures deterministic StreamWriter Flush, and File close at application exit
/// for
/// static facades. The cleanup is done after all normal finalizers have been
/// called.
/// </summary>
public
class StaticResourceManager : CriticalFinalizerObject
{
List<StreamWriter> writers = new List<StreamWriter>();
public
void AddStream(StreamWriter writer)
{
writers.Add(writer);
FileStream fStream = GetIfFileStream(writer.BaseStream);
if (fStream != null)
{
GC.SuppressFinalize(fStream); // prevent GC on FileStream
// prevent file close at application exit before want to let it happen
GC.SuppressFinalize(fStream.SafeFileHandle);
}
}
static FileStream GetIfFileStream(Stream stream)
{
if (stream is FileStream)
return (FileStream)stream;
else
return null;
}
/// <summary>
/// Deterministic cleanup of StreamWriters
/// 1. StreamWriter Close -> FileStream -> Close -> possible Writes
/// 2. FileHandle Close
/// </summary>
~StaticResourceManager()
{
foreach (StreamWriter writer in writers)
{
FileStream fstream = GetIfFileStream(writer.BaseStream);
SafeFileHandle handle = null;
if (fstream != null)
{
handle = fstream.SafeFileHandle;
}
writer.Close(); // Close StreamWriter first
if (handle != null) // Close file handle now hurray
handle.Close();
}
}
}Now we can finally write a much more reliable TraceListener which does use it internally. To show you that it does really work you can try out my improved Trace Sample:
class Program
{
// Our ResourceManager will ensure proper cleanup at application exit
private static StaticResourceManager myResourceManager = new StaticResourceManager();
Program()
{
FileStream file = new FileStream(@"C:\Trace.txt", FileMode.Create);
StreamWriter writer = new StreamWriter(file);
myResourceManager.AddStream(writer); // ensure flush and close at Application exit
// Use Tracing as usual
TextWriterTraceListener listener = new TextWriterTraceListener(writer);
Trace.Listeners.Add(listener);
Trace.WriteLine("First Trace"); // Generate some trace messages
Trace.WriteLine("Perhaps last Trace.");
}
~Program()
{
Trace.WriteLine("Hello last Trace in finalizer.");
}
static void Main(string[] args)
{
Program p = new Program();
}
}Finally we will see our beloved complete set of trace messages in our Trace.txt
Trace.txt
First Trace
Perhaps last Trace.
Hello last Trace in finalizer.
Please note that this simple fix is still not the complete story since our listener should survive a Close call of the static Trace facade after all.
Conclusions
I have shown that some things do not work as expected by most developers when working with the static trace facade with true resource based Trace Listeners. A Close method in a static facade is a true crime which delegates the responsibility back to the users of the .NET Trace facility. But since Tracing can and should be used by virtually every .NET component that is written we cannot ensure anymore that another component has not called Trace.Close for any reason. Resource management should be handled by the facade itself properly. In fact it can be done quite easy and I have no idea why MS did not implement a solution which does ensure that all finalizers can use tracing with no risk of loosing messages. The trick is that all Critical Finalizers are called by the GC after all normal finalizers have been visited. Finally I do not understand why I am able to programatically remove a trace listener that has been added to the global Listener collection by perhaps a totally different component which does rely on it. I should only be able to remove elements that I have previously added by myself (could be done by a token that is returned by the add operation and must be supplied to the remove operation). That is all for the moment and I hope you did enjoy this little article and have gained a better understanding why you see a 0 byte file when using the .NET Trace right away.
