A Tracing Primer - Part I [Mike Rousos]

One of the changes in Whidbey will be a revamped tracing system. Much is unchanged - tracing messages are sent through switches to listeners where the data is reported in some fashion. One of the main differences is the inclusion of the TraceSource type. This type will function as the main tracing entity, as opposed to the older static Trace type. The familiar Trace type will still exist but now, we expect, most tracing will be done through instantiations of TraceSources.

Introduction

So, what is tracing? Tracing is a diagnostics system by which an application's progression can be tracked. The tracing statements report information, much the way Console.WriteLine might, but they can be turned on or off through a configuration file and can report their information in a plethora of ways using different listeners.

The main components of a tracing system are

• A Trace Source. The trace source is what the developer uses to first send tracing messages. Different systems of an application can use different trace sources as one way to differentiate the tracing messages.
• A Switch. Once a source receives a trace command, it consults its switch to determine whether or not to actually trace this message. In this way, by setting a switch higher or lower in a configuration file, a user can regulate which messages are actually traced. The advantage to turning off some trace messages is twofold. Firstly, performance will benefit by not passing through the various tracing codepaths. Secondly, in some applications with thorough tracing instrumentation, trace output files can become enormous and difficult to make sense of. Often, it is best to only view the most critical tracing messages and then relax the switch to focus in on a potential issue. Switches can be of several kinds or a user can create their own switches, but for this first blog I will only be touching on the SourceSwitch - far and away the most common switch.
• Listeners. Once a switch has verified that a tracing message should, in fact, be traced, the listeners which are attached to the trace source will record the data contained in the message. There are many types of listeners and users can even create their own (although this is a topic best saved for part II of this blog). As with switches, the listeners that are attached to a trace source can be determined through a configuration file, allowing excellent run-time control over tracing.
• Filters. Finally, listeners can each have a filter attached. A filter is like a switch for a listener. It will determine which trace events are actually processed by the listener. In this way, a user can have multiple listeners attached to a trace source and have each listener record different categories of tracing messages. This topic, though, is another that is best left to a later blog entry.

One of the best ways to understand the tracing system is pictorial. Here is an image that diagrams what is described above.

Tracing Step by Step

So, what does it look like to actually use tracing? Well, here's a step by step guide to setting up and using tracing.

Instantiate a TraceSource

The first step to instrumenting an application with tracing is to create a trace source. In large projects with various components, it makes sense to use a separate trace source for each component. This will make it easier to keep the different traces separate. Here is a small application that simply creates a new trace source:

using System;
using System.Diagnostics;

class myClass
{
static void Main()
{
// The single string passed into the constructor here is the name of the trace source
TraceSource mySource = new TraceSource("myTraceSrc");

// Here we have the code to be instrumented with tracing.

mySource.Flush();
mySource.Close();
}
}

This code will create a trace source with the name "myTraceSrc". Another overload for the trace source constructor takes a string (the name) and also a member of the SourceLevels enum to serve as the default SourceSwitch level if none is specified later either in the code or in a config file. Notice that we need to include the System.Diagnostics namespace and we should flush and close the trace source when we are through with it. Not doing this could leave a last message or two unreported.

Another point to note regarding the above example is that while such a setup is sufficient for a simple demonstration like this one (and, in fact, I tried to make that code as simple as possible), a more common architecture for a large application is to have the trace sources be static variables, so that they are easily accessed by all types in a subsystem.

Adding Tracing Events

It might make sense here to talk about switches or attaching listeners, but these steps are not strictly necessary when developing an application because they can also be done through a configuration file. Simply adding and using a trace source is all that needs to happen as of compile time. Methods to trace an event may look like this:

mySource.TraceInformation("Hello World!");
mySource.TraceEvent(TraceEventType.Error, 5, "Hello World!");
mySource.TraceData(TraceEventType.Critical, 11, new object[] {1, 2, 3});
mySource.TraceData(TraceEventType.Information, 11, 11,214,2.3,"Hello", 't');

The first method shown, TraceInformation, is the simplest way to trace to a trace source and takes only a single string, representing the message to be traced. To fully understand this method, though, one must first grasp the latter two methods above. In both the TraceEvent and the TraceData methods, the first parameter is an element of the TraceEventType enumeration. This parameter will determine what sort of trace event this is. In most cases, this just means that it will determine the severity of the event. This information is used by switches and filters to determine if, for a given configuration, this message should actually be traced. Here are the members of TraceEventType and when they should be used:

• Critical. This is the most severe member of the enum. It should be used sparingly, only for very serious and irrecoverable errors.
• Error. This enum member has a slightly lower priority than Critical, but it still indicates something wrong in the application. It should typically be used to flag a problem that has been handled or recovered from.
• Warning. This value indicates something unusual has occurred that may be worth investigating further; although it does not necessarily indicate an error.
• Information: This value indicates that the process is executing correctly, but there is some interesting information to include in the tracing output file. It may be information that a user has logged onto a system or that a new form in the application is opening.
• Verbose: This is the loosest of all the severity related values in the enum. It should be used for information that is not indicating anything wrong with the application and is likely to appear in vast quantities. For example, when instrumenting all methods in a type to trace their beginning and ending, it is typical to use the verbose event type.
• Stop, Start, Suspend, Resume, Transfer: These event types are not indications of severity, but mark the trace event as relating to the logical flow of the application. They are known as activity event types and mark a logical operation’s starting or stopping, or transferring control to another logical operation. They are very useful event types but fall outside the scope of this already long blog. They will be discussed in more detailing in a future post.

The second parameter in the trace methods is the event ID number. This integer identifies the nature of the tracing message. It is typical for an application to designate different event ids to mean different things. For example, the number 1 may mean that this trace event marks the beginning of a method and the number 2 may indicate that the event marks the end of a method. The event ID is just another way to differentiate tracing messages.

In TraceEvent, the most common tracing method, the third parameter (which is optional) is a string which contains the message to actually be traced. The string contains the information the trace event is meant to convey. If no message is specified, an empty string will be used. In the TraceData method, the string is replaced with an object[]. This allows the developer to pass a collection of items that are of interest at some particular point in the program's execution.

As mentioned above, there is also a TraceInformation method which takes a string as its only parameter. This method will simply call TraceEvent with an event type of information and an event ID of 0. It's a shorthand way of tracing information - something that is done a lot when instrumenting an application with tracing.

Compiling the Application

This is a short but important section. In order to enable tracing, the /d:TRACE flag must be passed into the C# compiler or the /d:TRACE=True flag must be passed into the VB compiler. These flags can be removed to ship a retail version of the project and no tracing methods will be compiled.

Alternatively, #define TRACE can be added to the top of a file to enable tracing.

Using the Configuration File

So, now you have some trace sources and you have added lots of trace events to your code. How do you see this output? How do you determine which of those events are actually traced? One way is to programmatically add switches and listeners, but it lacks the flexibility of doing the same thing with a configuration file. Therefore, I will discuss the configuration file first. Afterwards, I will briefly touch on how to accomplish these things programmatically (which will override any diagnostics configuration settings, by the way).

Everything tracing related goes under the <system.diagnostics> tag in the config file. A user needs to define sources whose names match the names used in the application for the trace sources. This is important. The names are case sensitive and must match exactly. If the application has TraceSource mySrc = new TraceSource("myTS");, then the configruation file needs to have <source name="myTS"> to work with that source. First, I will show an example configuration file and then talk through what the various sections do.

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<sources>
<source name="myTraceSrc" switchName="switch1">
<listeners>
<add initializeData="output.txt" type="System.Diagnostics.TextWriterTraceListener"
name="myLocalListener" />
<add name="consoleListener" />
</listeners>
</source>
<source name="myTraceSrc2" switchValue="Warning">
<listeners>
<add name="xmlListener" />
<add name="consoleListener" />
</listeners>
</source>
</sources>
<sharedListeners>
<add initializeData="output.xml" type="System.Diagnostics.XmlWriterTraceListener"
name="xmlListener" traceOutputOptions="None" />
<add type="System.Diagnostics.ConsoleTraceListener" name="consoleListener"
traceOutputOptions="None" />
</sharedListeners>
<switches>
<add name="switch1" value="Critical" />
</switches>
</system.diagnostics>
</configuration>

Ok, that's a bit on the long side, but it includes an example of everything I intend to explain about the config file in this post. First, notice the <sources> section. This is where the sources that are used are defined. The name must match the name of a trace source in the application precisely.

Also, all trace sources should have a switch defined here. There are two ways to define a swtich (as demonstrated above). First, you can specify a switchValue (as in the second trace source above). This value should equal one of the members of the SourceLevels enum. This is what's known as defining a local switch because the switch value will only have an effect on that particular source. The other method is to specify a switchName. The switchName should refer to one of the members of the switches section (at the bottom of the config file in my example). This is known as referencing a shared switch because these switches can be used by multiple sources and changing a value in the switches section can change the behavior of many sources (any that use that switch).

Next, notice the sources' <listeners> sections. The listeners section is much like the switches section in that you can reference either local or shared listeners. In either case, the listener must have a name specified. If it's a shared listener, that's all that's required because the rest of the listener definition is taken care of in the shared listeners section. If the listener is a local listener, then the rest of the definition needs to go here. All local listeners must have their type specified along with their name. Also, if the listener outputs to a file (as the text writer and xml writer listeners do), an output file must be specified. This is done with the intializeData attribute. Again, a local listener will be used only for that particular source; a shared listener can be used across multiple sources.

After the sources section, there are the <sharedListeners> and the <switches>sections. These define shared listeners and switches that the sources may reference. Switches and listeners are defined here in the same way that their local counterparts are defined in the sources section.

Configuring the Sources Programmatically

Of course, a developer can specify these same things programmatically and not need to depend on a config file.

Switches from the config file are SourceSwitches (unless otherwise specified, which we will discuss in a later blog). So, to use them programmatically, instantiate a SourceSwitch. A trace source's switch property can be set to an instance of a SourceSwitch. Alternatively, a trace source's switch level can be set directly.

Listeners can be instantiated just like any other type and can be added to a trace source's listeners collection.

Below is an example of how to programmatically configure the same sort of setup that is used in the configuration file above.

using System;
using System.Diagnostics;

class myClass
{
static void Main()
{
TraceSource mySource = new TraceSource("myTraceSrc");
TraceSource mySource2 = new TraceSource("myTraceSrc2");

  SourceSwitch switch1 = new SourceSwitch("switch1", "Critical");
mySource.Switch = switch1;

  mySource2.Switch.Level = SourceLevels.Warning;

ConsoleTraceListener consoleListener = new ConsoleTraceListener();
XmlWriterTraceListener xmlListener = new XmlWriterTraceListener("output.xml");

  mySource.Listeners.Add(new TextWriterTraceListener("output.txt"));
mySource.Listeners.Add(consoleListener);

  mySource2.Listeners.Add(xmlListener);
mySource2.Listeners.Add(consoleListener);

  mySource.Flush();
mySource.Close();
mySource2.Flush();
mySource2.Close();
}
}

Trace Listeners

Finally, I will give a rundown of the trace listeners that will ship with Whidbey. Custom listeners can also be created, but this will be detailed in a later blog entry.

• ConsoleTraceListener - This listener writes the trace events to the console with this format: SourceName EventType: ID: Message
• TextWriterTraceListener - As the ConsoleTraceListener, except it outputs to a file rather than the console.
• XMLWriterTraceListener - This listener outputs the tracing information into an XML file which follows a schema I will detail in a future blog.
• DelimitedListTraceListener - This listener outputs to a file, like the TextWriterTraceListener, but it delimits the information with a string the user can specify (the default is a semicolon).
• DefaultTraceListener - This listener is like the ConsoleTraceListener, but instead of writing to the console, it sends its information to the debug stream. This means that Visual Studio's output window will display the tracing information when an application is debugged. Also, it should be noted that all trace sources will have a default trace listener named 'Default' in their listener collection automatically. If a user doesn't want this listener present, it needs to be removed manually.

Closing

I hope that his helps explain the basics of tracing. I would very much appreciate any feedback or questions. And remember that one of the best parts of this tracing system is that it is so configurable. It can be used in a myriad of ways to cover a whole slew of tracing needs. What I outlined in the section on the usage of the event types and the event IDs was an example of what may be a good method of using our tracing APIs. I would be very interested, though, to hear how our customers use these APIs in their own scenarios. This sort of feedback will be very helpful as we consider what to do with our tracing system moving forward.

• Anonymous
  March 15, 2005
  Very cool that you posted this. It's one of the biggest sleepers in 2005.
  
  For anyone who's going to be at DevConnections next week, this is a large part of my Preparing Code for Easier Debugging talk. Or if you're in an INETA user group I can talk about why the new tracing approach changes everything (meaning, you'll actualy start using tracing techniques). I don't mean to sound like a commercial here, it's just that this aspect of 2005 is so very, very cool and almost no one has been talking about it.

• Anonymous
  March 16, 2005
  One thing I find lacking in the current (1.1) Trace listeners, and apparently the new listeners, is the ability to include a timestamp with every message. I always end up creating a static Utility class with this method:
  
  public static void Trace(string message){
  System.Diagnostics.Trace.WriteLine(DateTime.Now.ToString("s") +" "+ message);
  }
  
  I'm surprised this isn't a more commonly requested feature. Am I using Tracing incorrectly because I want time information?

• Anonymous
  March 16, 2005
  Joshua,
  This is supported in Whidbey! I was waiting to introduce the trace output options property on listeners until my next post because this post was already pretty long, but you can specify options on a listener that will change what gets recorded. One of the options is timestamp. When this is selected, a timestamp will show up in every trace. The complete list of options are:
  - Timestamp
  - Date/Time
  - Callstack
  - Logical Operations Stack
  - Process ID
  - Thread ID

• Anonymous
  March 16, 2005
  Mike,
  Thanks for the info - this is an area of Whidbey where documentation has been sorely lacking. Here's a couple of follow up questions:
  
  1) Is there any way to specify the format in which trace messages are logged (if you're familiar with Log4Net, the equivalent is the Layout concept)?
  
  2) Is trace configuration updated dynamically when the config file changes, without application restart? This is critically important for server applications.
  

• Anonymous
  March 16, 2005
  Kevin,
  
  Thanks for the questions.
  1) Unfortunately, I'mnot familiar with Log4Net. There really isn't anyway to format the existing listners, though. The TextWriterTraceListener will always output things in this format - Source EvetnType: ID: Message OutputOptions.
  
  That said, a user can implement their own custom listener and have complete control over the output. It's really a pretty easy exercise to do this. I'll be sure to post a blog entry about it sometime in the next week or two.
  
  2) Changing a config file does not automatically update the tracing setup. However, there is a static method - Trace.Refresh() that will do this. It reloads the config file and updates the tracing setup. Two ways of using this would be to include a command an admin can call on the app to invoke this method or to use a File System Watcher to watch for changes to the config file (I've used this method before). Then, if the config file changes, we fire Trace.Refresh() so that we can update the tracing configuration without restarting the app.

• Anonymous
  March 17, 2005
  The comment has been removed

• Anonymous
  March 17, 2005
  Tips

• Anonymous
  March 17, 2005
  Just great!!
  I needed to understand the following:
  <system.diagnostics>
  <switches>
  <add name="MySource" value="Verbose"/>
  </switches>
  
  <sources>
  <source name="MySource">
  <listeners>
  <add name="examplelog" type="System.Diagnostics.TextWriterTraceListener" initializeData="example.log"/>
  <add name="allfile" type="System.Diagnostics.TextWriterTraceListener" initializeData="all.log" TraceOutputOptions="Timestamp, CorrelationId" />
  </listeners>
  </source>
  </sources>
  
  </system.diagnostics>
  
  which obviously coms from an app.config file.
  I am running this on Whidbey, and this program basically writes all activity of a game called Space Invaders :o)
  Before this, I have logged info and errors in your typical Event Log.
  
  Thank you again,
  
  Tonchi.
  "What you think doesn't matter. What matters is evidence!"

• Anonymous
  March 21, 2005
  Tips

• Anonymous
  March 29, 2005
  The comment has been removed

• Anonymous
  July 11, 2006
  The comment has been removed

• Anonymous
  August 31, 2006
  &#191;Sigues escribiendo Trace.WriteLine(&quot;...&quot;) en tu c&#243;digo de .NET 2.0? &#191;Sigues escribiendo cosas como esta...

• Anonymous
  September 14, 2006
  WPF (Avalon) uses the .Net tracing system to provide some diagnostics about what’s going on inside your WPF application.  It’s not at all an exhaustive set of traces, and in fact it’s still pretty rudimentary.  But frequently it’s enough to help out when

• Anonymous
  September 15, 2006
  WPF (Avalon) uses the .Net tracing system to provide some diagnostics about what’s going on inside your WPF application.  It’s not at all an exhaustive set of traces, and in fact it’s still pretty rudimentary.  But frequently it’s enough to help out when

• Anonymous
  February 28, 2007
  PingBack from http://softwarearquitecto.com/blog/?p=6

• Anonymous
  March 15, 2007
  We have an applciation (Bought from another company) that has a very good logging system, and during

• Anonymous
  August 29, 2007
  PingBack from http://dstelow.wordpress.com/2007/08/29/links-for-2007-08-29/

• Anonymous
  January 31, 2008
  Pokud se sháníte po jednoduchém mechanizmu, jak ve Vašich aplikacích logovat výjimky, pak zřejmě v .NET

• Anonymous
  January 31, 2008
  Pokud se sháníte po jednoduchém mechanizmu, jak ve Vašich aplikacích logovat výjimky, pak zřejmě v .NET

• Anonymous
  March 10, 2008
  PingBack from http://www.it-farmer.com/how-to-use-net-trace-api.html

• Anonymous
  September 28, 2008
  PingBack from http://www.rividian.com/blog/2008/09/28/turning-on-tracing-and-debugging-in-net-web-app/

• Anonymous
  January 21, 2009
  PingBack from http://www.keyongtech.com/2390820-writing-to-the-debug-window

• Anonymous
  June 08, 2009
  PingBack from http://quickdietsite.info/story.php?id=3668

• Anonymous
  June 09, 2009
  PingBack from http://insomniacuresite.info/story.php?id=4620

• Anonymous
  June 16, 2009
  PingBack from http://topalternativedating.info/story.php?id=11492