Instrumenting Applications with .NET Tracing

By Mayo, Joe
Published in: : 2004 - September/October
Last updated: February 19, 2019

Published in:

Filed under:

Application instrumentation gives you the ability to perform runtime diagnosis of enterprise application state, which is critical to mission success.

To help with instrumentation and logging, .NET ships with tracing types in the System.Diagnostics namespace. Using these types, you have the ability to log information to multiple output streams for diagnosis of application runtime behavior. Information produced by instrumentation and tracing types enable you to examine the runtime state of an application and fix problems that would be otherwise expensive and painful to solve.

For many small and medium sized programs, it isn't too difficult to find and fix bugs based on reproducible information from users. As applications increase in size and complexity, the ability to figure out what is causing a bug becomes more difficult. On larger enterprise systems you need a way to track what is happening to find out what is causing problems. You must instrument your application so you can turn on tracing that will reveal pertinent information about your program's behavior.

The Trace class allows you to perform logging in a production system, giving you the ability to analyze application behavior during run time.

Two of the primary types in the System.Diagnostics namespace for application instrumentation are the Debug and Trace classes. Both classes have the same functionality but different use cases. Use the Debug class during development and use the Trace class in production applications.

The types for debugging and tracing, which come with the .NET Framework library, are convenient because they provide reuse and extendable functionality. You don't have to create your own logging library and you can build custom instrumentation types.

When tracing, you can control output with switches. A BooleanSwitch turns tracing on and off. TraceSwitch lets you trace at different levels. Alternatively, you can create a custom switch to define identifiers, granularity, and logic that meets the requirements of a given application.

Trace output is sent to another type called a TraceListener. .NET ships with trace listeners for writing to the console, event log, or text files. You can also define your own trace listener for output to the stream of your choice.

Instrumentation is a critical component of enterprise application development, enabling you to build maintainable, reliable, and robust systems. Through Debug and Trace classes, switches, and trace listeners, you have the ability to instrument your application in an easy and flexible manner.

Configuration

The Debug and Trace classes have the same functionality, but Microsoft designed them for different purposes. You use the Debug class for development purposes and it relies on DEBUG being defined. Use the Trace class for production purposes. It relies on TRACE being defined.

By default, Visual Studio .NET (VS.NET) defines both DEBUG and TRACE for Debug (development) configurations and only TRACE for Release (production) configurations. To view your project configurations in VS.NET, right-click on the project, select Properties, select Configuration Properties, select the Build option, and view the Conditional Compilation Constants property. When compiling C# applications from the command-line, compilation configuration options are specified with the /define: or /d: option, as follows:

csc.exe /d:TRACE MyApp.cs

Basic Tracing

For this article we'll use the Trace class to show how to use .NET types for instrumentation of production systems. While I wrote the examples in this article as Console applications for simplicity, you can use this information for instrumenting any kind of .NET application, including ASP.NET, remoting, Web services, and Windows Forms. The Trace class has several members that control output, which you can see in Listing 1.

When your tracing needs are simple, that is, you only need to turn tracing on or off, a Boolean switch is a good choice.

The first line in Listing 1 adds a TraceListener to the Listeners collection. TraceListeners are discussed in the Trace Listeners section of this article. They let you specify where the output of write statements will go.

The WriteLine and Write methods write output with and without a newline, respectively. The WriteLineIf and WriteIf methods write output if a condition evaluates to true. The category parameter enables you to prefix the output with a tag string, which is useful for filtering log entries.

The Assert method displays a dialog and writes output when the specified condition evaluates to false. The condition is explicitly set to false in Listing 1 to raise the assertion. You normally use the Assert method with the Debug class so you can test assumptions in your code during development. You don't normally want assertion message boxes popping up in front of users.

The Fail method raises an assertion dialog and writes to output unconditionally. Although Listing 1 shows the Fail statement with the Trace class, you should use it with the Debug class because you don't want a message box popping up in front of your users. You can use the Fail method when you reach an illogical segment of code such as a default in a switch statement that doesn't make sense or in an exception catch block. The benefit of the Fail method is that you can press the Retry button and break into the debugger to determine the cause of the problem.

The Trace class also includes other members for controlling output, including properties for indentation, output flushing, and closing listeners. Their implementations are straight forward and I refer you to the documentation for more information.

The next two sections discuss switches, which you use for conditional output with the WriteIf and WriteLineIf methods.

Boolean Switches

A BooleanSwitch will allow you to produce trace output only when the switch is true. When all tracing is turned on, the output can quickly use a lot of resources if saving output to file or some other persistent store. If your application is small or you don't hold log information longer than immediate diagnosis, a BooleanSwitch will work fine. Listing 2 shows how to use a BooleanSwitch.

The code in Listing 2 is very simple?if boolSwitch.Enabled evaluates to true, then the string parameter to the WriteLineIf method is sent to output.

When instantiating the boolSwitch variable, you set the first parameter to a configuration file parameter named MyBooleanSwitch. As shown in Listing 3, the System.Diagnostics element contains a switches element where you can add a switch statement. In this case there is an element for MyBooleanSwitch and it is turned on. A value of 1 turns the switch on and 0 turns the switch off. You can add multiple switches to the configuration file to help manage tracing at a more granular level in different parts of your application.

Trace Switches

The problem with a BooleanSwitch approach to instrumentation is that it is all-or-nothing. Most of the time, you need more granularity in your approach. For example, perhaps during normal operations you only want to know about error conditions. However, to diagnose a problem, you need the ability to trace more information for a short period of time. The level of information you need at any given time could vary depending on what you need to know. Here you'll find value using the TraceSwitch.

The TraceSwitch has five levels of control, defined by the TraceLevel enum (with corresponding value): Off (0), Error (1), Warning (2), Info (3), and Verbose (4). You determine when to use each switch level. To help out, I'll explain how I use them. I use Error to detect errors in code, catch filters, and global exception handlers. I rarely use Warning, but I use it for strange situations that aren't really errors but I should pay attention to them. If that sounds ambiguous, it is; which is why I rarely use Warning. I use Info to enter and exit methods. I log state conditions in an algorithm with Verbose. Be aware that too many trace statements could make an algorithm harder to read, so use them only where you think they have debugging value. Basically, think about what information you need to detect problems and debug your application if something went wrong. Listing 4 shows how to use TraceSwitch in your code.

Use a TraceSwitch switch when you need to filter the amount of output based on an increasing level of detail and severity.

When your code declares the TraceSwitch variable, it is instantiated with the MyTraceSwitch parameter, which corresponds to the same entry in the switches element of the configuration file in Listing 5. This configuration file sets MyTraceSwitch to 4, which turns on tracing for Verbose and every level below it. As implied, the trace level setting in the configuration file turns on tracing for the level it is set at in addition to all lower levels.

The TraceSwitch class has Boolean properties that correspond to each trace level. Listing 4 demonstrates how to use the traceSwitch variable as the first parameter to WriteLineIf to determine if a specific trace level is set before logging output.

Custom Switches

Switches that ship with .NET will work fine for most cases. However, there are times when you may want to implement your own custom switches. Perhaps you want to migrate another system where you have a different logging strategy that worked and you want to mimic that strategy in .NET. What if the all-inclusive logic of the TraceSwitch didn't quite meet your needs?

Existing switches don't provide the output control you need? With reusable types in the .NET Framework Class Library you can create your own custom switch.

I'll demonstrate how to create a custom switch. I designed my example to give you ideas of how you could implement your own custom switch to achieve the granularity and logic handling appropriate for your needs.

The custom switch in Listing 6, FlagSwitch, creates new switch categories: None, Enter, Exit, Info, and Exception. As opposed to the TraceSwitch where higher switch levels are all inclusive of lower levels, the FlagSwitch lets you turn categories on and off at will.

The FlagLevel enum is decorated with the [Flags] attribute, allowing you to use it in bitwise operations. You can explicitly set each element with a hex value to ensure their values don't overlap.

Notice how my example exposes each switch setting as a property. The get accessors use the SwitchSetting of the base class, Switch, and use a bit-wise AND operation to check if the bit representing that condition is set. The Switch class takes care of reading configuration file settings and ensures that the SwitchSetting property is set accordingly. The implementation also ensures that in all properties, except for None, the None bit is turned off, since this would represent an illogical condition.

Trace Configuration

The configuration files in previous examples showed how to add a single switch to an application. You can do more with configuration files including add additional switches and remove switches. The following snippet shows these additional switch configuration capabilities:


<?xml version="1.0" encoding="utf-8" ?>
<configuration>
 <system.diagnostics>
   <switches>
      <add name="TraceSwitch3" value="4" />
      <add name="TraceSwitch2" value="4" />
      <add name="TraceSwitch1" value="4" />
      <remove name="TraceSwitch2" />
   </switches>
 </system.diagnostics>
</configuration>

The configuration file adds three switches, which you can use in different parts of an application to give you more control over where you want to view debug output. The remove element essentially un-defines TraceSwitch2, making any conditional Trace statements in your code evaluate to false and not print. The remove element provides a way to turn a switch off, which is an alternative to deleting, commenting, or setting a value to 0 (assuming that 0 represents a condition that prevents trace output) of an existing switch.

Dynamic Switch Settings

Besides using configuration files, you can change switch settings dynamically in code. For example, the following code modifies the TraceLevel setting to None for a TraceSwitch:


   switch1.Level = TraceLevel.Off;

If you needed to dynamically set the switch on a custom switch, you should provide a property that accepts an enum for the custom switch type. The implementation of that property can get and set base.SwitchSetting appropriately. The following property implements this for the custom switch described in the Custom Switches section of this article:


   public FlagLevel Level
   {
      get
      {
         return base.SwitchSetting;
      }
      set
      {
         base.SwitchSetting = (int)value;
      }
   }

This is necessary because the Switch.SwitchSetting property has protected visibility.

Trace Listeners

You use tracing so you can collect run time information from your application to diagnose problems. This means that there is a location where you can obtain the information, which is where trace listeners come in. A trace listener is a type that allows you to persist your trace information to a location where it can be stored and analyzed. .NET ships with three built-in trace listeners: DefaultTraceListener, TextWriterTraceListener, and EventLogTraceListener.

Using DefaultTraceListener

The DefaultTraceListener, as its name implies, is where .NET automatically sends all trace output. The output is sent to a Win32 API called OutputDebugString. In Visual Studio .NET, the DefaultTraceListener output appears in the Output window.

You can use trace listeners to control output destination including debug output, console, or the Windows Event Log.

You can configure a given application with multiple trace listeners. When this occurs, each write operation will be routed to every trace listener installed. Additionally, .NET shares all trace listeners with the Debug and Trace classes, regardless of what switch they are using.

The Listeners property of the Trace class exposes a ListenersCollection type, which implements IList. This means that if you prefer not to have output sent to the DefaultTraceListener you can use the Remove method as follows:

   Trace.Listeners.Remove("Default");

Using TextWriterTraceListener

A TextWriterTraceListener writes trace output to a file. To use it, instantiate a TextWriterTraceListener class and add it to the Listeners collection. Listing 7 shows you how to set up a TextWriterTraceListener.

The code in Listing 7 creates a file stream and passes it to the TextWriterTraceListener, which will then write trace output to the TraceDemo.log file as well as to all the other trace listeners in the Listeners collection.

Using EventLogTraceListener

Another trace listener that ships with .NET is the EventLogTraceListener, which writes to the Windows Event Log. Listing 8 shows how to use the EventLogTraceListener.

The code in Listing 8 adds an EventLogTraceListener type to the Trace class Listeners collection, along with other listeners. The algorithm automatically starts the mmc snap-in for the Windows Event Viewer so you can see the new entry.

Because Windows optimizes access to the Event Log, the EventLogTraceListener is a very efficient way to write trace output. However, one concern with writing to the Event Log is the fact that it could run out of space quickly, depending on how the administrator has the Windows Event Log configured. For this reason, I prefer using the TextWriterTraceListener because it creates a file that I can refer to immediately and then archive for later analysis.

Creating a Custom Trace Listener

The trace listeners that ship with .NET are good for most applications. However, you may need to direct trace output to another destination that the existing trace listeners don't support. For example, suppose you want to send trace output to a database or maybe output to a special window in your application? Fortunately, you can use types in the .NET Framework Library to create a custom trace listener.

When existing trace listeners don't meet your needs, you can create your own.

All trace listeners inherit the TraceListener class, an abstract class providing default behavior and virtual methods for you to override in your own custom trace listener. The TraceListener class has abstract Write and WriteLine methods that take a single string as a parameter. Listing 9 shows the implementation of the custom trace listener.

The demo in Listing 9 contains a custom trace listener, WindowTraceListener, which opens a Windows Form and writes trace output to a text box. The WindowTraceListener class inherits TraceListener. Its implementation is minimal, overriding only the required Write and WriteLine methods, but Listing 9 demonstrates how easy it is to create a custom trace listener. You will want to override all of the virtual overloads of the TraceListener class for Write, WriteLine, Fail, and Assert for a more robust implementation.

Conclusion

The .NET Framework ships with several types that make it easy to instrument your applications. You can use BooleanSwitches, TraceSwitches, or create your own switch to specify conditions under which logging will occur. To specify the destination of your tracing output, use the DefaultTraceListener, TextWriterTraceListener, and EventLogTraceListener. Because these libraries are extensible you can also create your own trace listener for sending instrumentation output to the destination of your choice. Instrumentation is a critical part of enterprise application development and the types presented in this article should provide you with more tools to accomplish your work.

Listing 1: Basic tracing methods

using System;
using System.Diagnostics;

class BasicTracing
{
   static void Main()
   {
      // specify where trace output should go
      Trace.Listeners.Add(
         new TextWriterTraceListener(Console.Out));

      // category tag for output
      string category = "Basic Tracing";

      // just write, no newline
      Trace.Write("Trace.Write(); ", category);

      // write with a newline
      Trace.WriteLine("Trace.WriteLine(); ", category);

      // write if condition is true, no newline
      Trace.WriteIf(true, "Trace.WriteIf(); ", category);

      // write with newline if condition is true
      Trace.WriteLineIf(true,
          "Trace.WriteLineIf(); ", category);

      // raise assertion alert if condition is false
      Trace.Assert(false, "Trace.Assert(); ",
         "Shown when condition is false");

      // unconditionally raise assertion alert
      Trace.Fail("Trace.Fail(); ", "Shown unconditionally.");

      Console.ReadLine();
   }
}

Listing 2: Boolean switches

using System;
using System.Diagnostics;

class BooleanSwitches
{
   static BooleanSwitch boolSwitch = new BooleanSwitch(
            "MyBooleanSwitch",
            "Bool Switch Demo");

   static void Main()
   {
      Trace.WriteLineIf(
                  boolSwitch.Enabled,
                  "Testing Boolean Switch.",
                  boolSwitch.Description);

      Console.ReadLine();
   }
}

Listing 3: Boolean switch configuration

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
   <system.diagnostics>
   <switches>
         <add name="MyBooleanSwitch" value="1" />
   </switches>
   </system.diagnostics>
</configuration>

Listing 4: Trace switches

class TraceSwitches
{
   static TraceSwitch traceSwitch =
      new TraceSwitch(
         "MyTraceSwitch",
         "Trace Switch Demo");

   static void Main()
   {
      Trace.WriteLineIf(
         traceSwitch.TraceError,
         "Testing Error Trace Switch.",
         traceSwitch.Description);
      Trace.WriteLineIf(
         traceSwitch.TraceWarning,
         "Testing Warning Trace Switch.",
         traceSwitch.Description);
      Trace.WriteLineIf(
         traceSwitch.TraceInfo,
         "Testing Info Trace Switch.",
         traceSwitch.Description);
      Trace.WriteLineIf(
         traceSwitch.TraceVerbose,
         "Testing Verbose Trace Switch.",
         traceSwitch.Description);

      Console.ReadLine();
   }
}

Listing 5: Trace switch configuration

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
   <system.diagnostics>
   <switches>
         <add name="MyTraceSwitch" value="4" />
   </switches>
   </system.diagnostics>
</configuration>

Listing 6: Custom switch demo

using System;
using System.Diagnostics;

namespace CustomSwitches
{
   class CustomSwitchDemo
   {
      private static FlagSwitch flagSwitch = new FlagSwitch(
         "MyCustomSwitch", "Flag Switch Demo");

      static void Main()
      {
         CustomSwitchDemo csd = new CustomSwitchDemo();
         csd.RunDemo();
         flagSwitch.Level = FlagLevel.Enter;
         csd.RunDemo();
         Trace.Flush();
         Console.WriteLine(
            "Traces appear in VS.NET Output window.");
         Console.ReadLine();
      }

      public void RunDemo()
      {
         Trace.WriteLineIf(
            flagSwitch.Enter, "Entered RunDemo()");

         Trace.WriteLineIf(
            flagSwitch.None,
            "FlagLevel.None is true.");

         try
         {
            Trace.WriteLineIf(
               flagSwitch.Info,
               "Preparing to divide number.");
            int zero = 0;
            int result = 13/zero;
         }
         catch (DivideByZeroException dbze)
         {
            Trace.WriteLineIf(
               flagSwitch.Exception, dbze.Message);
         }

         Trace.WriteLineIf(
            flagSwitch.Exit, "Leaving RunDemo()");
      }
   }

   [Flags]
   public enum FlagLevel
   {
      None = 0x0,
      Enter = 0x1,
      Exit = 0x2,
      Info = 0x4,
      Exception = 0x8
   }

   public class FlagSwitch : Switch
   {
      public FlagSwitch(
         string displayName, string description)
         : base(displayName, description)
      {
      }

      public FlagLevel Level
      {
         get
         {
            return (FlagLevel)Enum.Parse(
               typeof(FlagLevel),
               base.SwitchSetting.ToString());
         }
         set
         {
            base.SwitchSetting = (int)value;
         }
      }

      public bool Enter
      {
         get
         {
            return (base.SwitchSetting &
               (int)FlagLevel.Enter) > 0 && !None;
         }
      }

      public bool Exit
      {
         get
         {
            return (base.SwitchSetting &
               (int)FlagLevel.Exit) > 0 && !None;
         }
      }

      public bool Exception
      {
         get
         {
            return (base.SwitchSetting &
               (int)FlagLevel.Exception) > 0 &&
               !None;
         }
      }

      public bool Info
      {
         get
         {
            return (base.SwitchSetting &
               (int)FlagLevel.Info) > 0 && !None;
         }
      }

      public bool None
      {
         get
         {
            return base.SwitchSetting ==
               (int)FlagLevel.None;
         }
      }
   }
}

Listing 7: Using a TextWriterTraceListener

using System;
using System.Diagnostics;
using System.IO;

class TextWriterTraceListenerDemo
{
   static void Main()
   {
      string logFileName = "TraceDemo.Log";
      Stream logFileStream = File.Create(logFileName);

      TextWriterTraceListener myListener =
         new TextWriterTraceListener(logFileStream);
      Trace.Listeners.Add(myListener);

      Trace.WriteLine("Testing the Trace Listener.");
      Trace.Flush();

      Process.Start("Notepad.exe", logFileName);
   }
}

Listing 8: Using the EventLogTraceListener

using System;
using System.Diagnostics;

class EventLogTraceListenerDemo
{
   static void Main()
   {
      EventLogTraceListener myListener =
         new EventLogTraceListener(
            "EventLogTraceListenerDemo");
      Trace.Listeners.Add(myListener);

      Trace.WriteLine("Testing the Trace Listener.");
      Trace.Flush();

      Process.Start(
         "mmc.exe",
         "%SystemRoot%\\system32\\eventvwr.msc /s");
   }
}

Listing 9: A custom trace listener

using System;
using System.Diagnostics;
using System.Threading;

class WindowTraceListener : TraceListener
{
   private TraceWindow traceWin = null;

   // test the WindowTraceListener
   static void Main()
   {
      WindowTraceListener windowTrace =
         new WindowTraceListener();
      Trace.Listeners.Add(windowTrace);

      Trace.WriteLine(
         "Testing Trace Listener WriteLine().");
      Trace.Write(
         "Testing Trace Listener Write().");
      Trace.WriteLine("");

      Trace.WriteLineIf(true,
         "Testing Trace Listener WriteLineIf().");
      Trace.WriteIf(true,
         "Testing Trace Listener WriteIf().");
      Trace.WriteLine("");

      Trace.Assert(false,
         "Testing Trace Listener Assert().");
      Trace.Fail("Testing Trace Listener Fail().");

      Trace.Flush();

      Console.ReadLine();
   }

   // opens the trace window
   private void ShowTraceWindow()
   {
      Thread traceThread = new Thread(
         new ThreadStart(ShowTraceWindowInThread));
      traceThread.Name = "ShowTraceWindowInThread";
      traceThread.Start();

      int maxNaps = 10;
      int napCount = 0;

      // this is to make sure that traceWin
      // is initialized before we return
      while (traceWin == null && napCount < maxNaps)
      {
         Thread.Sleep(500);
      }
   }

   // run the window in a thread
   private void ShowTraceWindowInThread()
   {
      if (traceWin == null)
      {
         traceWin = new TraceWindow();
         traceWin.ShowDialog();
      }
   }

   // handle TraceListener Write calls
   public override void Write(string traceInfo)
   {
      ShowTraceWindow();
      traceWin.Write(traceInfo);
   }

   // handle TraceListener WriteLine calls
   public override void WriteLine(string traceInfo)
   {
      ShowTraceWindow();
      traceWin.WriteLine(traceInfo);
   }

}

This article was filed under:

This article was published in:

Have additional technical questions?

Get help from the experts at CODE Magazine - sign up for our free hour of consulting!

Contact CODE Consulting at techhelp@codemag.com.