3. Tracing Code

You are familiar with the situation: you have carefully designed your algorithm and coded it diligently, but when you run the code the result is wrong. What do you do next? Well, one obvious option is to place a breakpoint at the start of the algorithm, run the code, and then single step through the code. This allows you to check that the input data is correct and it allows you to view intermediate results. The problem occurs when you have a complicated algorithm, or if there is a loop and the error occurs after many iterations. The Visual Studio debugger allows you to provide a condition for a breakpoint and you can use this on a loop counter to break after the appropriate number of iterations. However, such conditional breakpoints degrade the performance of your code considerably and it could make the difference between going for a cup of coffee while the code runs to the break point and going home and returning the following day!

Tracing allows you to print information about what part of the code is running, what input values are used, the results of condition statements so that you can determine code flow, and it also allows you to print intermediate results. Often, the problem with tracing is how to restrict the amount of data that is printed. I am using the term 'printed' rather loosely, the .NET framework gives you various options about how tracing messages are handled: a file, the event log, the console, and the output debug stream are all possible locations for trace messages, and the framework even allows you to write your own code to handle trace messages.

There are two trace mechanisms in .NET: static trace sources and instance trace sources. Static trace sources were introduced in the first version of .NET and are still available. As the name suggests you have just one instance for the entire application. This means that categorization of the messages has to be done when generating the message, which complicates the code. Furthermore, since there is just one instance of the trace source, any configuration will effect just that instance. .NET 2.0 (and hence 3.0) introduced instance trace sources which means that you can create multiple instances in your application, each one configured to behave in a different way. Trace sources create the message and these are then passed to trace listeners which is responsible for the actual display or storage of the message.

This page will cover tracing messages through the static trace sources; instance trace sources will be covered on a later page.

The framework provides two classes, Debug and Trace, which have methods that you call to generate a trace message. The methods merely generate the message that will be traced, they do not say where the trace message is sent. Both of these classes give access to the same static array of trace listeners. It is a trace listener that handles the trace message and logs it in the appropriate file, event log or whatever. When you log the message the tracing class (Debug and Trace) iterates the trace listener collection in a serial fashion and passes the trace message to each one. This means that if one trace listener takes a long time to handle the message then it will slow down all tracing. Thus, if you have tracing enabled in your application, then the implementation of trace listeners is vital to the well being of your application. As you'll see later, there are threading and inter-process issues with the default classes provided by the framework.

The two classes Debug and Trace are essentially the same, (Trace has three methods and two properties that Debug does not have and Debug has one method that Trace does not have.) The main difference between the two is that the Trace methods are marked with [Conditional("TRACE")] and Debug methods are marked with [Conditional("DEBUG")]. That is, only code that has been compiled with the TRACE symbol defined will call the Trace methods and only code that has been compiled with the DEBUG symbol defined will call the Debug methods. As I mentioned earlier, these symbols will be defined with the /d command line switch; if you compile a debug build with /debug you should be aware that the DEBUG symbol is not automatically defined.

The Visual Studio project wizards will define these symbols for you. For a debug build it will define both DEBUG and TRACE. However, for release builds it defines TRACE. You have to be very wary of this action: for two main reasons. Trace has an Assert method which means that there is a possibility that an assert can be generated in release mode. An assert indicates that not only is there a bug in your code, but you guessed that there might be one but had not got round to fixing it. Clearly, it shows that you have not finished debugging your code, so how professional does it make your code look? The other main reason (which will be expanded on this page) is that trace listeners can couple your process to another process so that the performance of your process will depend on the performance of a process that you neither know about nor can control. Do you want to submit yourself to that? I suspect not.

I will mention later how to make tracing in release mode less odious, if you really insist on doing it, but I stick by the statement above.

The simplest way to generate a trace message is to pass a string to the overloaded Debug.WriteLine method. The whole line is passed to the trace listener, with a newline. Note that trace listeners are allowed to process trace messages in whatever way they like so it is usually best to log whole lines. The Debug class also has Write methods with corresponding parameters to the WriteLine methods, but since these methods are static and they maintain no concept of threading context you may find that the component parts you write with Write may get mixed between messages from other threads. If you want to build up a trace message it is better to construct each line using String.Format and then pass the entire message to WriteLine. However, this has the disadvantage that you'll have to bracket this formatting code with conditional compilation directives so that the formatting code does not appear in builds that do not define the DEBUG symbol. This will make your code less readable. If the formatting is similar for most messages then you can define a [Conditional] method that will format the message and call Debug.WriteLine. There is another solution in .NET 3.0/2.0, the Print method, which will be covered in a moment.

WriteLine has four overloads, the two simplest are the aforementioned method that takes a string, and a method that takes an object, on which ToString will be called. Note that for most of the framework classes ToString will merely print the name of the class, thus you should only call this method for your own classes which you have defined a ToString method that actually prints its state. The other two overloads take two parameters; the first parameter is either a string or an object with the same meaning as for the other two overloads, and the second parameter a category string. This will generate a message in this format:

where message is the string (or object contents) that you pass to the first parameter and category is the string you pass as the second parameter. That is all that these methods do for the trace listeners in the framework. If you implement your own trace listener you may decide to use the category to determine how the message is logged, but .NET 3.0/2.0 has a more elegant solution with trace sources.

.NET 3.0/2.0 added a new method called Print to the Debug class (but not to the Trace class). This has two overloads, the first takes a single string and is essentially a call to WriteLine that has a single string. The other overload takes a format string and a params array of objects, the two parameters are passed to String.Format and the resultant string is passed to Debug.WriteLine. Using a format string like this means that the Print method behaves like the Console.WriteLine method.

The Debug and Trace classes also give you some rudimentary formatting through indents. Indents are configuraed through two static properties. IndentSize determines how many spaces are used in the indent and IndentLevel gives the number of indents that will be used when printing the next message. You can also use the static Indent and Unindent methods to increment and decrement this value. Since the level is static it means that all calls to trace messages are subject to this value, and if you have a multi threaded application this can result in confusing indents. Indentation is the responsibility of the individual trace listener class who will have access to the indent level and indent size but is under no compulsion to actually use those values. Again, trace sources have a much better solution to formatting messages, not least because they are instance objects and can be thread specific.

Some trace listeners are based on buffered streams, and it is possible that your application could finish before the stream has flushed all of its buffer to the underlying store. To help here, the Trace and Debug classes provide a mechanism to flush the trace listeners. Both classes have a property, AutoFlush, that determines if the trace listener should flush its stream whenever any writes are made to the trace listener (that is, both WriteLine and Write). Trace also has a static property called UseGlobalLock that affects how automatic flush works. However, although this property is on Trace, it sets a global value that is used by the tracing code that is used by both Trace and Debug. This is a daft arrangement because if you only have DEBUG defined you cannot alter this global property through the  Trace class, furthermore, if you use a configuration file to provide settings for tracing then even if you do not use the Trace class in your application you still have to provide configuration settings for it.

The documentation says: the global lock is always used if the trace listener is not thread safe, regardless of GlobalLock. However, if you take a look at TraceIntenal.WriteLine using ILDASM or Reflector you'll see that this is not the case. The implementation is the following (using pseudo-code):

That is, if the trace listener is not thread safe, some locking mechanism will be used, but the lock will only be a lock (that is, the Monitor class) if the UseGlobalLock property is set. What this means is that if UseGlobalLock is set then tracing by multiple threads will be serialized, that is, only one trace message can be performed at any one time. If UseGlobalLock is not set then access to trace listeners that are not thread safe are serialised, and with this setting any thread can access any trace listener that is thread safe at any time.

Every version of Write and WriteLine has a companion method called WriteIf and WriteLineIf that differ only by the addition of a Boolean parameter. The message is only passed to the trace listener if the Boolean is true. This can be useful if you define switches in your application, for example, this pseudo-code:

This allows you to use the configuration file to determine the types of messages that you trace. For example, if you have a GUI application that makes calls via a socket you could define one 'level' to be GUI messages and another 'level' to be socket calls. Or you may decide that your levels are levels of importance: information, warning and error, and use the configuration file as a way of filtering the messages that will be generated.

Using the If versions of the tracing methods gives you more control about how much data is traced, and hence reduce the performance cost of tracing, but be aware that there is still a condition test for every call to an If method. The instance trace sources give a better mechanism of filtering.

It is worth pointing out that the Trace class has three methods that are not available on Debug: TraceInformation, TraceWarning and TraceError. These are used to trace events and will be covered on a later page.

Microsoft makes quite a fuss about internationalization. Quite right to, but sometimes I think that they have not thought it through completely. If you are tracing as a debugging aid (which I insist is the main reason) then you will want to trace a message in your own language. After all, if you are going to read the messages then you will want to generate them in a language that you can understand. if you are tempted to put in trace messages in your release mode code 'just in case there is a problem after deployment' then bear in mind that your customers (who you are using as paying beta testers) may not understand the same language as you. This means that you will have to internationalize the messages. If you use tracing as a log mechanism (which is a valid thing to do, when done sparingly) then you will also have to internationalize your messages.

In .NET internationalization is performed at write time using satellite assemblies. The mechanism works like this. Your application stores all the strings that the user will see as .NET resources. Your assembly will contain the culture neutral strings that will be used if a suitable localised resource cannot be found. Your application then has one or more resource-only library assemblies, one for each locale that you support. Each satellite contains the resources for a locale and its name includes this in the Culture part of its long name. At runtime your code creates an instance of ResourceManager and calls GetString passing some identifier unique for the string that you require. The ResourceManager object will read the culture of the current thread and then search for assembly an assembly for that specific culture (for example en-GB for UK English). If such an assembly cannot be found, the resource manager uses 'fallback'. First it will look for an assembly which is just language specific (for example, en for English) and if that assembly cannot be found the current assembly is searched for the culture neutral resource.

The complete steps that you have to perform are given in detail in my Fusion Workshop.

This means that if you intend to log data you will have to ensure that you have a ResourceManager object available to all logging code (possibly as a static property), you'll have to maintain the resource strings and you'll have to provide code that obtains the correct resource string. Since Trace is conditional, it makes sense to make this resource code conditional too, and the code is far more readable if you use a conditional method:

Here, you can see that there is a static object to give access to resources. The AccessAccount method logs the message that the account has been opened. The actual log message will look something like this: Opened Account # 12345 in English. So the localised string in the English resource will be Opened Account #{0} and this string is identified by the identifier OPEN_ACCOUNT_STRING. Each satellite will have a string with this identifier. LogMessage calls GetString to get the string localised to the culture of the current thread, inserts any parameters into the string and then logs the message with Trace.WriteLine.

The problem with this mechanism is that the reader of the log is assumed to be in the same culture as the generator of the log. This problem is compounded if the event log is used to store the log messages because this service assumes that the reader of the log is responsible for providing the localised format strings.

Errata

If you see an error on this page, please contact me and I will fix the problem.

Page Four