Most programs need a way to collect errors, exceptions and other information, like what happened before an exception occurred. Collecting this information is called tracing. DotNet has some tracing functionality, but it is much too slow. Having tracing active should not slow down the application, which can be achieved by writing the tracing information first in RAM and process it later on a different thread.
Content
Introduction
In every .NET project, regardless of the technology used, some basic functionality is needed right from the start:
Tracing and how to handle exceptions.
Of course, .NET and Visual Studio provides some tracing functionality, but:
- Unnecessarily difficult to use (
Trace, Debug, TraceSource, TraceListener, TraceSource, TraceSwitch, ...) - Visual Studio tracing is much too slow and blocking, making it useless for multithreaded applications
- Trace processing is run on the calling thread, tracing exceptions give problems to caller
Requirements for Tracing and Error Handling
- Available from the very first line of code (no initial setup necessary)
- Take very little time (around a microsecond)
- Trace processing executed on its own thread
- Tracing running continuously, without causing any storage problems
- Trace message filtering and processing accordingly
- Easy extendable (storing trace in db, send email for certain problems, show some messages in GUI, etc.)
BaseLib.Tracer writes trace message in a fast buffer. Another thread empties the buffer, processes the trace and finally stores the message in a ring buffer, where the oldest trace messages get overwritten. For debugging and exception investigations, it is usually enough to have just the latest trace messages.
It's configurable to write some trace messages for permanent storage to files and/or to use any custom implemented trace processing.
Typical Use Cases
- Application writes from the very first line of code into the trace what is happening, like which files it tries to open or other resources it tries to access. If the application fails to start, the trace information shows what could be completed successfully and which functionality made the start to fail. This information is very useful if the application runs on a remote machine, where it is difficult to observe, what is going on.
- When an exception occurs, the trace information gets included in the Exception message, showing what happened just before (!) the exception occurred.
- Exception and warning messages get stored in a log file. If the file reaches a certain size, a new log file gets created. If there are too many log files, the oldest gets deleted.
- Exceptions could get emailed to the developers, including the trace.
The idea of tracing is to write (debugging) messages to a trace. The trace can then be used to investigate why a certain problem happened, or, more precisely, what the application did just before the problem happened. Tracer differentiates four kinds of tracing messages, depending on which tracing method is called:
Tracer.Trace()Tracer.TraceWarning()Tracer.TraceError()Tracer.TraceException()
It is up to the application what the difference between just a trace, warning or error is. Tracer writes them all in the same way into the trace, marking them accordingly. Additionally, the application can for example configure that all messages get stored in RAM, only warning and errors written to a trace file and errors emailed to a development account.
Tracer.TraceWithFilter() takes additionally to the trace message a text, which later can be used for filtering.
Tracer.TraceException() should be used whenever an exception got caught. They are treated by Tracer like any other messages, although all exception details get shown in the trace and if a debugger is attached, it might execute a Break().
Tracing Startup of Application
To use full tracing functionality from the very first line of code executed, Tracer is made a static class.
It might be useful to trace the starting of the application like this:
Tracer.Trace("Application started");
Configuration configuration;
Tracer.Trace("Read Configuration started");
try {
configuration = ReadConfiguration();
} catch (Exception ex) {
Tracer.TraceException(ex, "Read Configuration failed, used default configuration");
configuration = Configuration .Default;
}
Tracer.Trace(configuration.ToString());
Tracer.Trace("Read Configuration completed");
Tracer.Trace("Start Connect DB");
try {
ConnectDB();
Tracer.Trace("DB connected");
} catch (Exception ex) {
Tracer.TraceException(ex, "Connect DB failed");
}
Comments
- Very first line writes to trace. Among other things, this is useful to show in the trace when exactly the trace has started.
- For every step needed to setup the application, use its own
_try_ statement. If there is an exception, do something else so that the application still can start and display some (error) information.
The application can configure some tracing functionality:
Tracer.IsTracing = true;
Tracer.IsWarningTracing = true;
Tracer.IsErrorTracing = true;
Tracer.IsExceptionTracing = true;
Tracer.IsBreakOnWarning = false;
Tracer.IsBreakOnError = true;
Tracer.IsBreakOnException = true;
TraceLogFileWriter =new TraceLogFileWriter(
directoryPath: Environment.CurrentDirectory + @"\LogFiles",
fileName: "FinanceLog",
fileExtension: "log"
maxFileByteCount: 10*1000*1000,
maxFileCount: 5,
logFileWriterTimerInitialDelay: 1000,
logFileWriterTimerInterval: 10*1000
newFileCreated,
filter);
This code does not need to be right at the beginning of the application, since Tracer can work with its default settings without losing any messages. It's possible to read some (tracing) configuration and trace if there goes anything wrong, even Tracer has not been set up already and then setting up Tracer with the read configuration data.
The IsXxxTracing flags control if a normal message, Warning, Error or Exception gets written in the Tracer RAM buffer or immediately discarded.
The IsBreakOnXxx controls if the debugger should break in an attached debugger if a Xxx type of message gets traced. The developer can change the values of these flags using the debugger, allowing him to control easily how often the debugger will break during debugging.
The constructor of TraceLogFileWriter automatically registers with Tracer.MessagesTraced event. Even the already traced messages will be written to the indicated log file. Once the log file size is bigger than maxFileByteCount, a new file gets created. If more than maxFileCount exists, the oldest files get deleted, to prevent tracing using up all disk space. Setting one of these parameters to 0 will prevent that the corresponding max value gets checked. newFileCreated is a method that gets called when a new log file gets created. filter is a method that gets called whenever a message should get written to the log file. If it returns true, that particular message will not get written to the log file.
To get all stored trace messages, just call Tracer.GetTrace(). It returns an array of TraceMessage, sorted by their creation time. During the execution of GetTrace(), no new trace messages get added to guarantee a consistent result. However, they will not get lost, only written after GetTrace() has finished.
Use TraceMessage.ToString() for a simple way to display the trace messages.
Throwing Exceptions
Normally, the debugger breaks after an exception is thrown and stops where the catch statement is. By that time, the local data is lost where the exception was thrown. Use Tracer.Exception() to address this:
throw Tracer.Exception(new MyException("Some info"));
Tracer.Exception() will break in the debugger and the data causing the exception to be thrown is still available. The developer can then let the degugger continue to run and the exception gets thrown. The developer can control during runtime with IsBreakOnException if the break should happen or not.
Catching Exceptions
Some exceptions might be expected to occur sometimes. If the program should react to the exception by doing something else, the exception should be caught in a try catch statement. The rest of the exceptions should be caught in a central place which is done differently in different .NET technologies:
| Technology |
| Console Application | try catch statement |
| Windows Form Application | Application.ThreadException |
| WPF Application | Application.DispatcherUnhandledException |
| ASP.NET | Global.asax: Application_Error |
| multi threading | each thread needs its own try catch statement |
Whether an exception is caught locally or globally, it is in both cases a good idea to trace it with Tracer.TraceException(exception). This writes the exception with all the exception details to the trace. If a debugger is attached and IsBreakOnException is true, the details also get displayed in the debugger output window.
Often, it would be interesting to know what the user did before the exception was thrown. Storing all major user interactions with the application would generate too much information. But when using Tracer, the information gets only written into RAM and overwritten after some time. If an exception gets thrown, it is possible to get the messages traced before the exception and add them to the exception, which then might get written to a log file.
Often, an application needs further processing of trace messages, like displaying warnings, errors and exceptions to the user (GUI), collecting all errors and exceptions in a central database or emailing exceptions to developers. This can be easily done by registering to the event Tracer.MessagesTraced.
Applications with a user interface could provide the following functionality:
- Display and editing of
Tracer settings - Displaying of errors and exceptions to the user. It should be easy to copy the trace information so that it can be sent to support.
- Display of presently stored trace
Version 1.1: Adding Flushing, i.e., Moving Trace Message from Temporary to Final Buffer on Demand
Every trace message gets temporarily stored in a ringbuffer, so that the thread doing the trace gets hardly delayed (about 1 microsecond). A timer is run on another thread, copying the trace messages every 100 milliseconds to the final trace ringbuffer and calling any listeners of MessagesTraced event for further processing, which can be slow, like writing to a file.
This caused some problems, when for example, the application made a trace and closed immediately. The 100 millisecond timer did not run and no event listener got called. It seemed like the Tracing was not working. A similar problem happened when the trace got inspected after an exception with GetTrace(), because again, the timer did not run yet. For these cases, a Flush() method got added, which forced the timer to run immediately, to move all message from temporary to permanent ring buffer, to call the event listeners and only then to return.
LogFileWriter got a Dispose() method and destructor, which guarantee that when the application gets closed, all trace message get written to the trace file up to the call of these methods. Before, the trace messages of between 0 and 100 milliseconds were missing.
The DotNet framework version got lowered to 4.0.
Breaking Change
TraceMessage[] GetTrace(Action<TraceMessage[]> MessagesTracedHandler) got renamed to TraceMessage[] AddMessagesTracedListener(Action<TraceMessage[]> MessagesTracedHandler) to better reflect the real purpose of the method.
Moving ACoreLib from CodePlex to BaseLib on Github
The original article was written for ACoreLib which I shared on CodePlex.com. Unfortunately, Microsoft shut this website down and I don't have the source code for ACoreLib anymore, because I kept adding new code and renamed the library BaseLib, which I share on GitHub.com. The functionality is still the same, but some names have changed. I updated the article using the new names.
The code for this article is in BaseLib/Tracer.cs.
If you are interested in even faster, non blocking tracing, which is helpful in debugging race conditions, read this article:
