Logging and Debugging Techniques
The .NET Runtime provides a few facilities to make programming less dangerous. Conditional methods and tracing can be used to add checks and log code to an application, to catch errors during development, and to diagnose errors in released code.
Conditional methods are typically used to write code that performs operations only when compiled in a certain way. This is often used to add code that is called only when a debug build is made and is not called in other builds, usually because the additional check is too slow.
In C++, you would do this by using a macro in the include file that changes a function call to nothing if the debug symbol isn’t defined. This doesn’t work in C#, however, because there is no include file or macro.
In C#, a method can be marked with the conditional attribute, which indicates when calls to it should be generated. Here’s an example:
using System;
using System.Diagnostics;
class MyClass
{
public MyClass(int i)
{
m_i = i;
}
[Conditional("DEBUG")]
public void VerifyState()
{
if (m_i != 0)
{
Console.WriteLine("Bad State");
}
}
int m_i = 0;
}
class Test
{
public static void Main()
{
MyClass myClass = new MyClass(1);
myClass.VerifyState();
}
}
The VerifyState() function has the Conditional attribute applied to it, with DEBUG as the conditional string. When the compiler comes across a function call to such a function, it looks to see whether the conditional string has been defined. If it hasn’t been defined, the call to the function is eliminated.
If this code is compiled using /D:DEBUG on the command line, it will print out Bad State when it is run. If compiled without DEBUG defined, the function won’t be called, and there will be no output.
Note Because conditional methods are sometimes missing, they cannot be used in any situation where their absence would be missed. This includes returning a value, overriding a virtual method, or implementing an interface method.
An assert is simply a statement of a condition that should be true, followed by some text to output if it is false. The preceding code example would be written better as this:
using System;
using System.Diagnostics;
class MyClass
{
public MyClass(int i)
{
m_i = i;
}
public void VerifyState()
{
Debug.Assert(m_i == 0, "Bad State");
}
int m_i = 0;
}
class AssertExample
{
public static void Test()
{
MyClass myClass = new MyClass(1);
myClass.VerifyState();
}
}
The call to Debug.Assert() validates that the specified condition is true. If it is not true and the program was built with a debug build, the runtime will show a message box with the specified text.
If the same behavior is desired in all builds, Trace.Assert() should be used instead of Debug.Assert().
The traditional view has been that using Debug.Assert() is a good thing to do; it improves the quality of the code and doesn’t cause any performance degradation in the actual software.
This is true. There are two other things that are also true, however.
- The cost of most assertions is small enough that it has no measurable impact on the performance of programs.
- The kind of information that is produced by assertions is hugely valuable when you are trying to debug a problem in your program after it has been released.
If an assertion is important enough to write, it’s likely to be useful in both debug and release builds. For release builds, however, it’s usually more useful to write the information to a file instead of showing the user an ugly dialog. The next section shows how to do this.
The previous example showed the default behavior of calling Assert(). This may not be the desired behavior for some programs; a web page or service is unable to show a message box, and even on programs with UI, it may be desirable not to interrupt the user with the information.
class AssertToFileExample
{
public static void Test()
{
Debug.Listeners.Clear();
Debug.Listeners.Add(new ConsoleTraceListener());
MyClass myClass = new MyClass(1);
myClass.VerifyState();
}
}
Both the Debug and Trace classes expose a collection of TraceListener instances, and when an Assert() message needs to be sent, the class will send the assert message to each of them. There are a wide variety of predefined listeners, which can send output to the event log, to a file, to a web page, or to other destinations. If those are sufficient, a custom trace listener can be created.
Adding Other Messages to Debug or Trace Output
In addition to asserts, the Debug and Trace classes can be used to send useful information to the current debug or trace listeners. This is a useful adjunct to running in the debugger, in that it is less intrusive and can be enabled in release builds to generate log files.
The Write() and WriteLine() functions send output to the current listeners. These are useful in debugging but not really useful in released software, since it’s rare to want to log something all the time.
The WriteIf() and WriteLineIf() functions send output only if the first parameter is true. This allows the behavior to be controlled by a static variable in the class, which could be changed at runtime to control the amount of logging that is performed.
using System;
using System.Diagnostics;
class MyClass
{
public MyClass(int i)
{
m_i = i;
}
public void VerifyState()
{
Debug.WriteLineIf(debugOutput, "In VerifyState");
Debug.Assert(m_i == 0, "Bad State");
}
static public bool DebugOutput {get; set;}
int m_i = 0;
}
class Test
{
public static void Main()
{
Debug.Listeners.Clear();
Debug.Listeners.Add(new TextWriterTraceListener(Console.Out));
MyClass myClass = new MyClass(1);
myClass.VerifyState();
MyClass.DebugOutput = true;
myClass.VerifyState();
}
}
This code produces the following output:
Fail: Bad State
In VerifyState
Fail: Bad State
Using Switches to Control Debug and Trace
The previous example showed how to control logging based upon a bool variable. The drawback of this approach is that there must be a way to set that variable within the program. What would be more useful is a way to set the value of such a variable externally.
The BooleanSwitch and TraceSwitch classes provide this feature. Their behavior can be controlled at runtime by setting either an environment variable or a registry entry.
The BooleanSwitch class encapsulates a simple boolean variable, which is then used to control logging.
using System;
using System.Diagnostics;
class MyClass
{
public MyClass(int i)
{
m_i = i;
}
[Conditional("DEBUG")]
public void VerifyState()
{
Debug.WriteLineIf(m_debugOutput.Enabled, "VerifyState Start");
if (m_debugOutput.Enabled)
{
Debug.WriteLine("VerifyState End");
}
}
BooleanSwitch m_debugOutput =
new BooleanSwitch("MyClassDebugOutput", "Control debug output");
int m_i = 0;
}
class Test
{
public static void Main()
{
Debug.Listeners.Clear();
Debug.Listeners.Add(new TextWriterTraceListener(Console.Out));
MyClass myClass = new MyClass(1);
myClass.VerifyState();
}
}
In this example, an instance of BooleanSwitch is created as a static member of the class, and this variable is used to control whether output happens. If this code is run, it produces no output, but the debugOutput variable can be controlled by setting the value in the configuration file for the assembly. This file is named <assembly-name>.config, which for this example means it’s called boolean.exe.config, and it has to be in the same directory as the assembly. Not surprisingly, the config file uses XML to store its values. Here’s the config file for the example:
<configuration>
<system.diagnostics>
<switches>
<add name="MyClassDebugOutput" value="1" />
</switches>
</system.diagnostics>
</configuration>
Running the code using this file produces the following result:
VerifyState Start
VerifyState End
The code in VerifyState shows two ways of using the variable to control output. The first usage passes the flag off to the WriteLineIf() function and is the simpler one to write. It’s a bit less efficient, however, since the function call to WriteLineIf() is made even if the variable is false. The second version, which tests the variable before the call, avoids the function call and is therefore slightly more efficient.
It is sometimes useful to use something other than a boolean to control logging. It’s common to have different logging levels, each of which writes a different amount of information to the log.
The TraceSwitch class defines four levels of information logging. They are defined in the TraceLevel enum (see Table 40-1).
Table 40-1. Levels of Logging Defined by TraceSwitch
| Level | Numeric Value |
|---|---|
| Off | 0 |
| Error | 1 |
| Warning | 2 |
| Info | 3 |
| Verbose | 4 |
Each of the higher levels implies the lower level; if the level is set to Info, Error and Warning will also be set. The numeric values are used when setting the flag via an environment variable or Registry setting.
The TraceSwitch class exposes properties that tell whether a specific trace level has been set, and a typical logging statement would check to see whether the appropriate property was set. Here’s the previous example, modified to use different logging levels:
using System;
using System.Diagnostics;
class MyClass
{
public MyClass(int i)
{
m_i = i;
}
[Conditional("DEBUG")]
public void VerifyState()
{
Debug.WriteLineIf(m_debugOutput.TraceInfo, "VerifyState Start");
Debug.WriteLineIf(m_debugOutput.TraceVerbose,
"Starting field verification");
if (m_debugOutput.TraceInfo)
{
Debug.WriteLine("VerifyState End");
}
}
static TraceSwitch m_debugOutput =
new TraceSwitch("MyClassDebugOutput", "Control debug output");
int m_i = 0;
}
class Test
{
public static void Main()
{
Debug.Listeners.Clear();
Debug.Listeners.Add(new TextWriterTraceListener(Console.Out));
MyClass c = new MyClass(1);
c.VerifyState();
}
}
The Switch class nicely encapsulates getting the switch value from the Registry, so it’s easy to derive a custom switch if the values of TraceSwitch don’t work well.
The following example implements SpecialSwitch, which implements the Mute, Terse, Verbose, and Chatty logging levels:
using System;
using System.Diagnostics;
enum SpecialSwitchLevel
{
Mute = 0,
Terse = 1,
Verbose = 2,
Chatty = 3
}
class SpecialSwitch: Switch
{
public SpecialSwitch(string displayName, string description) :
base(displayName, description)
{
}
public SpecialSwitchLevel Level
{
get
{
return((SpecialSwitchLevel) base.SwitchSetting);
}
set
{
base.SwitchSetting = (int) value;
}
}
public bool Mute
{
get { return(base.SwitchSetting == 0); }
}
public bool Terse
{
get
{
return(base.SwitchSetting >= (int) (SpecialSwitchLevel.Terse));
}
}
public bool Verbose
{
get
{
return(base.SwitchSetting >= (int) SpecialSwitchLevel.Verbose);
}
}
public bool Chatty
{
get
{
return(base.SwitchSetting >=(int) SpecialSwitchLevel.Chatty);
}
}
protected new int SwitchSetting
{
get
{
return((int) base.SwitchSetting);
}
set
{
if (value < 0)
{
value = 0;
}
else if (value > 4)
{
value = 4;
}
base.SwitchSetting = value;
}
}
}
class MyClass
{
public MyClass(int i)
{
m_i = i;
}
[Conditional("DEBUG")]
public void VerifyState()
{
Console.WriteLine("VerifyState");
Debug.WriteLineIf(m_debugOutput.Terse, "VerifyState Start");
Debug.WriteLineIf(m_debugOutput.Chatty,
"Starting field verification");
if (m_debugOutput.Verbose)
{
Debug.WriteLine("VerifyState End");
}
}
static SpecialSwitch m_debugOutput =
new SpecialSwitch("MyClassDebugOutput", "application");
int m_i = 0;
}
class Test
{
public static void Main()
{
Debug.Listeners.Clear();
Debug.Listeners.Add(new TextWriterTraceListener(Console.Out));
MyClass myClass = new MyClass(1);
myClass.VerifyState();
}
}
This switch can be controlled with the same config file as the other example.
The simple information written in a typical trace call may not be sufficient to track down an issue in a complex situation; it may be important know what thread and process created the trace. To allow this information to be captured without forcing the developer to manually code its retrieval, the Trace class includes a method called TraceInformation().
This method can provide the following information:
- The callstack
- The date and time the Trace statement was made
- The logical operation stack (which is the chain of calls in the current call context and may span multiple threads)
- The process ID
- The thread ID
- A timestamp, containing the number of ticks in the system timer.
The user of the trace decides which information to use. To output all the available information, you could use the following code:
ConsoleTraceListener ctl = new ConsoleTraceListener();
ctl.TraceOutputOptions =
TraceOptions.Callstack | TraceOptions.DateTime |
TraceOptions.LogicalOperationStack | TraceOptions.ProcessId |
TraceOptions.ThreadId | TraceOptions.Timestamp;
System.Diagnostics.Trace.Listeners.Add(ctl);
Trace.TraceInformation("An error occured ");
This code produces the following output:
Trace.exe Information: 0 : An error occured ProcessId=2324
LogicalOperationStack=
ThreadId=1
DateTime=2005-01-25T10:52:56.4135000Z
Timestamp=15259908099
Callstack= at System.Environment.GetStackTrace(Exception e,
Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Diagnostics.TraceEventCache.get_Callstack()
at System.Diagnostics.TraceListener.WriteFooter(TraceEventCache eventCache)
at System.Diagnostics.TraceListener.TraceEvent(TraceEventCache eventCache,
String source, TraceEventType severity, Int32 id, String message)
at System.Diagnostics.TraceInternal.TraceEvent(TraceEventType severity,
Int32 id, String format, Object[] args)
at System.Diagnostics.Trace.TraceInformation(String message)
at Trace1.Program.Main(String[] args) in
z:code race raceprogram.cs:line 17
Collecting all of this information is an expensive process, and programs should collect only the information that is necessary.
Improving Your Debugger Experience
The Visual Studio debugger has some nice facilities that allow you to inspect the values of variables as you debug; you can drill down into the values of variables and even view the contents of XML or text variables in a nice pop-up window. What is often overlooked is that it is possible to customize and extend this behavior, using a set of features known collectively as debugger visualizations.
Consider the following class:
class CommaSeparatedValues
{
public CommaSeparatedValues(string valuesAsString)
{
m_values = valuesAsString.Split(','),
}
string[] m_values;
}
This class takes in a simple, comma-separated string and breaks it apart into separate values. If you are using this class in code and you look at a variable of this type, the debugger will show the following value:
CommaSeparatedValues
This is, of course, just the result of the call to ToString(). You can add an override.
public override string ToString()
{
return String.Format("({0}) {1}", m_values.Length, String.Join(",", m_values));
}
The output is now the following:
(5) a,b,c,d,efg
That displays both the count of items and the actual string, both of which are useful for debugging. But it also introduces another issue; you can’t use ToString() to get the actual comma-separated string out of the class. What you need is a way to specify a different string to use during debugging.
The DebuggerDisplay attribute allows you to do just that: to specify how an item should be displayed in the debugger.
[DebuggerDisplay("({m_values.Length}) {ToString()}")]
class CommaSeparatedValues
{
public CommaSeparatedValues(string valuesAsString)
{
m_values = valuesAsString.Split(','),
}
public override string ToString()
{
return String.Join(",", m_values);
}
string[] m_values;
}
The DebuggerDisplay attribute declares a single string that will be used by the debugger to display the value of the instance. The values you want to show are listed inside curly braces ({}). In the debugger, the value will now be shown as follows:
(5) "a,b,c,d,efg"
Note that the count is obtained from the private m_values field; the attribute is evaluated by the debugger, which can access all fields.
The debugger display format is a mix of a String.Format-like approach and a C# expression approach; this makes it hard to read, and if you use C#-specific syntax (such as the ? or ?? operator), it will fail when used in other languages. There is a better approach.
[DebuggerDisplay("{DebuggerDisplay,nq}")]
class CommaSeparatedValues
{
public CommaSeparatedValues(string valuesAsString)
{
m_values = valuesAsString.Split(','),
}
public override string ToString()
{
return String.Join(",", m_values);
}
public string DebuggerDisplay
{
get
{
return String.Format(@"({0}) ""{1}""",
m_values.Length,
ToString());
}
}
string[] m_values;
}
The class now exposes a DebuggerDisplay property, and the attribute merely refers to the property. The nq in the attribute specifies that the value should not be displayed inside quotes.
Changing the Display of Existing Types
If you don’t own a type that has a poor display in the debugger, you can still change the way in which the type displays. You can find an autoexp.cs file in the <user>DocumentsVisual Studio XXXXVisualizers directory. In it, you will find a series of lines that look like this:
[assembly: DebuggerDisplay(@"{X = {x} Y = {y}}", Target = typeof(Point))]
This defines a DebuggerDisplay attribute for the System.Drawing.Point type.
Changing the Detail Display for a Type
When the user clicks the + icon for a display, the debugger will show all fields for that instance. You can control the visibility and default state of each member by adding the DebuggerBrowsable attribute.
[DebuggerBrowsable(DebuggerBrowsableState.Never)]
string[] m_values;
The array of values will no longer show up in the detail view for the instance. If, on the other hand, you want to always show all of the values in that array, you can use the following:
[DebuggerBrowsable(DebuggerBrowsableState.RootHidden)]
string[] m_values;
This will remove the m_values line from the display and instead show the contents of the array; the display will look something like this:
[0] a
[1] b
[2] c
[3] d
[4] efg
This capability is very useful to hide implementation details from the users of a class.
Full Customization of the Detail Display
When the user clicks the + icon for a display, the debugger will show all public properties and fields for that instance. It is sometimes desirable to substitute a modified view. This is done by defining a debugger type proxy for the type.
[DebuggerTypeProxy(typeof(CommaSeparatedValuesDebuggerProxy))]
class CommaSeparatedValues
{
public CommaSeparatedValues(string valuesAsString)
{
m_values = valuesAsString.Split(','),
}
string[] m_values;
class CommaSeparatedValuesDebuggerProxy
{
CommaSeparatedValues m_commaSeparatedValues;
public CommaSeparatedValuesDebuggerProxy(CommaSeparatedValues commaSeparatedValues)
{
m_commaSeparatedValues = commaSeparatedValues;
}
public int Count
{
get { return m_commaSeparatedValues.m_values.Length; }
}
public string FirstItem
{
get
{
return m_commaSeparatedValues.m_values.Length != 0 ?
m_commaSeparatedValues.m_values[0] : null;
}
}
public string[] Items { get { return m_commaSeparatedValues.m_values; } }
}
}
The DebuggerTypeProxy attribute instructs the debugger that when it needs to display the details of a CommaSeparatedValues instance, it should instead construct a CommaSeparatedValuesDebuggerProxy instance and pretend that the user asked for that instance’s values to be displayed. This allows the format of the debugger display to be customized; members can be renamed, hidden lists can be promoted to the top level, and so on. In this case, the debugger will now display the following:
Count 5
FirstItem "a"
Items {string[5]}
The default debugger detail view is limited to a grid-based approach, with a single line for each element. There are many types for which that is not a useful way to view data. The debugger provides a way to write visualizers, which can provide whatever view you want on an instance (the text, XML, and HTML views for string are implemented as visualizers). Visualizers can also be written that allow editing of the current instance.
For more information, see “How to: Write a Visualizer” in the MSDN documentation.
Debugging into the .NET Framework
The Visual Studio debugger makes it very simple to debug the code you write, but there are some scenarios where it would be useful to be able to debug into the .NET Framework source.
The Visual Studio debugger supports this. See the “How To: Debugging .NET Framework Source” topic in the MSDN documentation.