RSS Feed
Download our iPhone app
Browse DevX
Sign up for e-mail newsletters from DevX


Exploring Secrets of .NET Diagnostics : Page 2

Instrumenting an application with tracing has become increasingly sophisticated as the .NET framework has matured. Find out how to use tracing in your applications, how to fine-tune tracing to your needs with custom listeners, and how to gain field-level and robust formatting control over the output.

A Walk Through the Code
The TraceSourceDemoApp.cs file contains a static constructor, an instance constructor, three event handlers, and three support methods. First, you need a TraceSource as a handle into diagnostics. A TraceSource is the standard top-level, tracing .NET component that connects to the named section of your app.config file via the specified name. This demo uses a customized StructuredTraceSource, which adds some features to the standard TraceSource, providing a better quality of output, as you will see later. The first argument to the constructor is a reference to a TraceSource defined in your application's app.config file. The second (optional) argument is an options value—a bitwise combination of TraceOptions flags to be used in logging.

The class (or static) constructor selects options for the single TraceListener used in this application. It then instantiates the StructuredTraceSource with some standard options at the TraceSource level, which find their way internally to the TraceListener attached to the TraceSource. The order of these is important. The act of instantiating a StructuredTraceSource will itself write some diagnostic output. Therefore, you must adjust any TraceListener options before you create the StructuredTraceSource.

A static constructor is a handy tool for your coding toolkit if you are not familiar with it. Less well known than a "regular" or instance constructor, a static constructor runs once and only once—upon your first access to the class—no matter how many instances of the class you create. One common use is to set up class properties or variables before any objects are instantiated. The StructuredTraceSource named tracer in the following code is such a class (or static) variable. So if you were to define a class containing a static StructuredTraceSource then instantiate multiple copies of your class, all will share the same StructuredTraceSource—and they should—for efficiency. Instantiating the StructuredTraceSource within this static constructor guarantees it will be available when any instances of the class (in this case, TraceSourceDemoForm) are instantiated.

Here is the static constructor for the demo application:

   static TraceSourceDemoForm()
      AlignedTextWriterTraceListener.EventTypeLength = 0;
      tracer = new StructuredTraceSource("DemoMain",
         (TraceOptions.DateTime | 
         TraceOptions.ProcessId | TraceOptions.ThreadId));
The instance constructor (shown next) begins with the standard InitializeComponent call common to GUI applications. The second line is optional; it serves to let you see what all the TraceSource settings are before the tracing actually gets started, dumping that info into the TextBox on the form.

All methods that send output to your collection of Listeners have the "Trace" prefix. The standard TraceSource class includes TraceEvent, TraceInformation, and TraceData. The StructuredTraceSource class inherits those and adds TraceEnter, TraceLeave, and others discussed later in this article (see Table 1):

   public TraceSourceDemoForm()
The form Load event handler invokes the StructuredTraceSource's TraceEnter and TraceLeave methods; these trace execution entering or leaving the event handler. These, in fact, led to the naming of the class; "structured" is intended to invoke the image of successive levels of hierarchy shown by indentation in the diagnostic log. The StructuredTraceSource is optimized for recording the flow of an application and these two methods are key. They write Enter and Leave events in the output as well as automatically indenting (on an Enter) and exdenting (on a Leave):

   private void Form1_Load(object sender, EventArgs e)
      tracer.TraceInformation("constructor processing here...");
      // Not needed since StructuredTraceSource sets Trace.AutoFlush.
      // tracer.Flush();
Note the final comment in the method as well. To ensure that trace output reaches your trace file, you need to periodically flush, or ultimately, close the TraceSource. The StructuredTraceSource sets the static Trace.AutoFlush property which causes every trace event call to be flushed immediately. Whether you use a regular TraceSource or a StructuredTraceSource, be sure to consider how you wish to handle the issue (e.g. you could turn it off).

Author's Note: The MSDN documentation indicates you are also supposed to be able to set AutoFlush from the configuration file, but that setting does not seem to work when tracing with TraceSource objects. I suspect it works only with old-style Trace.WriteXxx calls, because elements must be children of <trace> in the configuration file—and TraceSource elements are not.

You are not required to mark any particular event (Enter, Leave, etc.) in any particular methods of your code. In fact, if you use TraceEnter and TraceLeave in every method, you may get more verbose output than you need. If you do use them, however, the call to TraceEnter, by convention, should be the very first line of your method and TraceLeave should be the last line (or the penultimate line when the method has a return statement). Between the TraceEnter and TraceLeave methods you'd typically have one or more calls to the TraceInformation method (this is the same method available from a regular TraceSource object because StructuredTraceSource derives from TraceSource). Table 1 lists the methods available to emit diagnostic information from a TraceSource or a StructuredTraceSource.

TraceEvent is the main workhorse method for diagnostics. You specify a TraceEventType (see Table 2), an event ID, and a message to log. An event ID is completely arbitrary unless you care to output diagnostics to your system event log, viewable with the standard Event Viewer tool. There event IDs have significance; for example, 6005 is the event ID of a boot, and 6006 is the event ID of a clean shutdown (see Event Log Entries). Your events will be comingled with other application events in the application log, so you may want to give some thought to what you assign. Note that TraceInformation is just shorthand for one type of TraceEvent call, which always uses a TraceEventType of Information and an event ID of 0.

Author's Note: The API page for TraceInformation is wrong on one point—it claims to call the three-argument form of TraceEvent, but it actually calls the four-argument form. This bit of trivia is important only if you wish to create a custom class that inherits from TraceSource.

The methods added by StructuredTraceSource are also shorthand for calls to TraceEvent. Each of these uses a TraceEventType of Information but the event ID is unique to each (shown in Table 1). Using properties, you may change these event IDs to any value you choose (such as 0 to be consistent with TraceInformation calls).

Table 1: TraceSource Tracing Methods: Use these methods in your application to emit diagnostic information. All methods are available with a StructuredTraceSource object; only the unshaded rows are available for a standard TraceSource object.
Method Event Id Description
TraceData   Writes trace data.
TraceEvent   Writes a trace event message.
TraceInformation 0 Writes an informational message, which is just a convenience method for one type of TraceEvent call.
TraceTransfer   Writes a trace transfer message.
TraceEnter 5901 Writes an informational message indicating entering a method.
TraceLeave 5902 Writes an informational message indicating leaving a method.
TraceEnterEventHandler 5903 Writes an informational message indicating entering an event handler method.
TraceLeaveEventHandler 5904 Writes an informational message indicating leaving an event handler method.

If you have multiple return statements in a method, you should place a TraceLeave call just before each of them, so no matter which exit route is taken the initial TraceEnter will always be balanced with a terminating TraceLeave. That is vital for keeping the indentation of the log correct. If possible, consider writing each method with just a single exit point, at the bottom of the method. Sometimes it is not convenient to do so, but often code can be rearranged easily to do this. Then you only need use a single TraceLeave call just before the return at the bottom.

A note on nomenclature about events: There are conventional events that you, as a .NET developer probably think of first, i.e. those that are processed by event handlers, as in a form load event or a button click event. Then there are trace events—events signifying something "newsworthy" enough that you want to log them. Each such trace event has a TraceEventType (see Table 2).

Table 2: Trace Event Types: The shaded types are the more common ones and have a natural hierarchical ordering, as detailed in Table 4 (adapted from TraceEventType Enumeration).
TraceEventType Description
Critical Fatal error or application crash.
Error Recoverable error.
Warning Noncritical problem.
Information Informational message.
Verbose Debugging trace.
Start Starting of a logical operation.
Stop Stopping of a logical operation.
Suspend Suspension of a logical operation.
Resume Resumption of a logical operation.
Transfer Changing of correlation identity.

The StructuredTraceSource adds methods that generate output with the TraceEventType of Information, subdividing this single event type into sub-event types (see Table 3).

Table 3: Trace Event Sub-Types: StructuredTraceSource introduces these trace event sub-types.
TraceEventType Sub-Event Type Event Id Description
Information Enter 5901 Indicates entering most methods
Information Leave 5902 Indicates leaving most methods
Information EnterEventHandler 5903 Indicates entering a conventional event handler method
Information LeaveEventHandler 5904 Indicates leaving a conventional event handler method
Information TraceSource creation 5905 Indicates a StructuredTraceSource object creation

EnterEventHandler and LeaveEventHandler form a nexus for confusion about the term "event": they are sub-events of tracing events, but they both refer to conventional events! The code examples you'll see later in this article should disambiguate these for you.

The next two methods are representative samples of conventional event handlers for explicit user actions, clicking a button and checking a box. Each implements the same pattern: a call to TraceEnterEventHandler, some processing, one or more calls to TraceInformation, and a call to TraceLeaveEventHandler. Both TraceEnterEventHandler and TraceLeaveEventHandler are akin to the TraceEnter and TraceLeave that you just saw above, but they output additional information in the diagnostic log, indicating the object name and display name of the object acted upon by the user (extracted from the sender parameter to the event).

The name of the TraceEnterEventHandler method provides a good clue as to its intended purpose: it is a trace output method because it begins with "Trace", it is a method that indicates entering a method due to the second word, and it should be used to instrument a conventional event handler, as the final chunk indicates. The same concepts apply to the TraceLeaveEventHandler method name.

   private void goButton_Click(object sender, EventArgs e)
      AddOutputToTextBox("Go button pressed.");
      tracer.TraceInformation("running with checkbox "
         + (colorizeCheckBox.Checked ? "CHECKED" : "UNCHECKED"));
   private void colorizeCheckBox_CheckedChanged(object sender, EventArgs e)
      tracer.TraceInformation("checkbox changed from checked={0} to checked={1}",
         colorizeCheckBox.Checked, !colorizeCheckBox.Checked);
The next two methods are more representative of real methods, in that they do not do all the work themselves, but break it down and pass it along to subordinate methods. Again you will observe that each method has a TraceEnter/TraceLeave bracket, possibly some TraceInformation calls, and then calls to other methods. So ProcessLevel1 calls ProcessLevel2 which in turn calls an external method called SomeCalc, discussed next. As mentioned, each TraceEnter call not only outputs a trace event of type Information and sub-type Enter, it also increases the indentation level of the log. As you get deeper into your method stack, then, the diagnostic output gets indented correspondingly, providing a visual analog of your program structure's hierarchy.

One additional minor observation: in both of these methods you see the TraceInformation call is passed a single string. But look back at the colorizeCheckBox_CheckedChanged method and you will see that it also has a "built-in" formatting handler: it implicitly calls the String.Format method if you provide a format string and corresponding arguments:

   private void ProcessLevel1()
      tracer.TraceInformation("processing here at level1...");
      tracer.TraceInformation("Finished processing.");
   private void ProcessLevel2(string parm)
      tracer.TraceInformation("processing here at level2 with parm=" + parm);
      if ("abc".Equals(parm)) { TraceSourceDemoLibrary.SomeLibClass.SomeCalc(); }

Close Icon
Thanks for your registration, follow us on our social networks to keep up-to-date