Exploring Secrets of .NET Diagnostics : Page 2

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()
   {
      InitializeComponent();
      AddOutputToTextBox(tracer.Dump());
   }
   

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.TraceEnter();
      tracer.TraceInformation("constructor processing here...");
      tracer.TraceLeave();
      // 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).

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).

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).

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.TraceEnterEventHandler(sender);
      tracer.TraceInformation("running with checkbox "
         + (colorizeCheckBox.Checked ? "CHECKED" : "UNCHECKED"));
      ProcessLevel1();
      tracer.TraceLeaveEventHandler(sender);
   }
   
   private void colorizeCheckBox_CheckedChanged(object sender, EventArgs e)
   {
      tracer.TraceEnterEventHandler(sender);
      tracer.TraceInformation("checkbox changed from checked={0} to checked={1}",
         colorizeCheckBox.Checked, !colorizeCheckBox.Checked);
      tracer.TraceLeaveEventHandler(sender);
   }
   

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.TraceEnter();
      tracer.TraceInformation("processing here at level1...");
      ProcessLevel2("abc");
      ProcessLevel2("xyz");
      tracer.TraceInformation("Finished processing.");
      tracer.TraceLeave();
   }
   
   private void ProcessLevel2(string parm)
   {
      tracer.TraceEnter();
      tracer.TraceInformation("processing here at level2 with parm=" + parm);
      if ("abc".Equals(parm)) { TraceSourceDemoLibrary.SomeLibClass.SomeCalc(); }
      tracer.TraceLeave();
   }
   

Previous Page

Next Page