Chris Taylor

Debug Output Formatting

Back in the good old days when learning a new technology was fun because we actually had the time to learn it I picked up a few neat tricks. I started working with VC++ 1.0, pretty much the month it shipped and one of the really cool features was the integrated debugger. From within an MFC application you put a call to a TRACE macro and your message was displayed in the output of the debugger, for vanilla Win32 apps you simply called the OutputDebugString API. More that 10 years later and in my opinion this is still one of the very useful debugging aids the environment offers. One of the little known, is that a cleverly formatted message will enable you to simply double click the message and you are immediately teleported to the source file and line number specified in the message.

For example if the following message was displayed in your debug output window, no this is not a compiler output,

d:\source\myapp\test.cs(23) : Some cool message

Simply by double clicking on the line you will be presented with the source file d:\source\myapp\test.cs and your cursor positioned on line 23.

The following C# function demonstrates a very simplistic implementation, which can be used to log debug messages which automatically include the context information required to easily jump straight into your code by double clicking the message.

public static void TraceEx( string message )
{
  // Only log this message if the debugger is attached
  if ( System.Diagnostics.Debugger.IsAttached )
  {
    StackTrace st = new StackTrace(true);

    // Get the calling stack frame, the current stack frame is at index 0,
    // the caller stack frame is at index 1 and so on.
    StackFrame sf = st.GetFrame(1); 
    if ( sf != null )
    {
      // Build an appropriately formated message
      string str = string.Format( "{0}({1}) : {2}",
        sf.GetFileName(), sf.GetFileLineNumber(), message );

      // Log the message to the debug window
      System.Diagnostics.Trace.WriteLine( str );
    }
  }
}

If you require, you can also include the column that you would like the cursor positioned at. The following shows this format, take a look at where the line number is specified, it now includes a second value, the column number.

d:\source\myapp\test.cs(23,15) : Some cool message

In this case when you double click the message in the debug window, you will be taken to d:\source\myapp\test.cs line 23, column 15. I have not found much use for this particular formatting, but who knows what you might come up with.

Performance - Case insensitive string comparisons

Recently I have come across code performing case insensitive comparisons of strings by first performing a conversion to uppercase/lowercase of both strings and comparing the result. Since .NET strings are immutable, the conversion of the string to uppercase or lowercase is not an in place conversion, but results in a new string being created which contains the converted contents. The extra memory allocation increases memory pressure which leads to more frequent garbage collections, which potentially degrades system performance. To demonstrate the point I decided to fire up my performance test harness and throw a few tests at it. Here I will show the results of two of those tests.

For the these tests I used the text from the King James New Testament, I started comparing all the words from one end of the text to the words on the other end. I chose two techniques for comparing the text, the following code demonstrates the two approaches tested.

1. if ( _words[i].ToUpper() == _words[j].ToUpper() )
2. if ( string.Compare(_words[i], _words[j], true) == 0 )

The following graph shows the results of that test.

The first bar in red is represents the time taken to perform the case insensitive comparison of all the words using the ToUpper technique, the second bar in green represents the time taken to perform the a case insensitive comparison using the string.Compare method.

Other than duration of execution my performance harness also captures a number of other statistics among which is the number of garbage collections initiated during a single run of the test routine. The following table presents these results.

The table shows that the test using ToUpper invoked  the garbage collector 138 times during the duration of the test. while using the Compare method the garbage collector was not required to run at all, in fact there was no evidence of any managed memory allocation taking place at all.

Note: The results of the string.Compare method will vary with different cultures. For the above tests I used the en-US culture. While I do not know the comparison rules used for every culture I am certain that relative to using the ToUpper technique the string.Compare will alway perform much better.