Mdbg watch-trace Extension

It often comes while debugging that you would like to know which methods were called and in which order before you get to your stop location. To know this, you would normally build a method call tree using some profiler and analyze it. Fortunately, if we don’t have a profiler at hand, we can also use a debugger for this purpose. I wrote a simple extension for the MDbg debugger that adds a watch-trace (wt) command to its shell, allowing you to display and customize the method call trees. In this post, I’m going to show you how this extension was built and how it can be used.

Writing an Extension

MDbg is a command line debugger distributed with Windows SDK. It’s fairly simple to use and has a nice, extensible API. Some time ago, Microsoft also released its source code – if you are interested in .NET native debugging API, I really encourage you to have a look at it. With MDbg simplicity unfortunately comes its lack of some of the advanced debugging features, such as: conditional breakpoints, mixed-mode debugging or native assembly code support. Though I still consider it a great managed debugger which, with its XCopy deployment, is especially useful in situations where you have no access to a Visual Studio instance and it’s impossible to setup a remote debugging session. If you become interested, have a look at its MSDN page with a list of available commands. Let’s now have a look at its extension API. MDbg extensions are DLL files which can be loaded into the debugger using the load command. While loading, MDbg looks for a type with the MDbgExtensionEntryPointClass attribute and then calls its LoadExtension method. So this is how we start the watch-trace extension:

namespace Mdb.Extension
{
    [MDbgExtensionEntryPointClass(Url = "http://lowleveldesign.wordpress.com")]
    public sealed class WatchTraceExtension : CommandBase
    {
        /// <summary>
        /// Loads extension into the debugger.
        /// </summary>
        public static void LoadExtension()
        {
            MDbgAttributeDefinedCommand.AddCommandsFromType(
                       Shell.Commands, typeof(WatchTraceExtension));
            WriteOutput("wtrace extension loaded");
        }
        ...
}

The mysterious highlighted line adds the watch-trace command to the MDbg shell. The extension command is described using a CommandDescription attribute. CommandName is an actual command and MinimumAbbrev defines a number of characters which abbreviate it. ShortHelp is displayed when you issue help command with no parameters and LongHelp will be displayed whenever you call help with your command name as a parameter. In our case, the extension command will be defined as follows:

namespace Mdb.Extension
{
       [CommandDescription(CommandName = "wtrace",
                            MinimumAbbrev = 2,
                            ShortHelp = "Watch trace command.",
                            LongHelp = @"Steps through the function calls, constructing a call tree.
Usage:
    wt [-l <depth>] [-inc <namespace>] [-exl <namespace>]
    wt -continue

-l <depth>                          the maximum depth of the calls to display
-inc <namespace1[,namespace2,...]>  include only calls from these namespaces 
                                          (case sensitive, comma separated)
-exl <namespace[,namespace2,...]>   exclude calls from this namespace 
                                          (case sensitive, comma separated)
-continue                           continues the last interrupted session 
                                  (you need to switch to the session thread!)")]

        public static void WatchTrace(String argString)
        {
        ...
        }
}

As our extension accepts some arguments, we need to extract them from the argString parameter of the WatchTrace method. Here comes with help an ArgParser. It accepts as a parameter the argString, allowing us to specify also a list of switches which are available to our command. By adding a :1 token at the end of the switch name, you inform the parser that this switch requires a parameter. We can then retrieve the switch values using parser.GetOption function, as shown below in the code of the PrepareCall method:

namespace Mdb.Extension
{
    [MDbgExtensionEntryPointClass(Url = "http://lowleveldesign.wordpress.com")]
    public sealed class WatchTraceExtension : CommandBase
    {
       ...
       /* *** Extension options ** */

        private const String depthOption = "l";
        private const String incNamespacesOption = "inc";
        private const String excNamespacesOption = "exc";
        private const String continueOption = "continue";

        /* *** Extension helpers *** */

        // Parses arguments and prepares internal command variables
        private static void PrepareCall(String argString)
        {
            ArgParser parser = new ArgParser(argString, depthOption + 
               ":1;" + incNamespacesOption + ":1;" +
               excNamespacesOption + ":1;" + continueOption);
            if (parser.OptionPassed(continueOption))
            {
                if (depth < 0)
                {
                    throw new MDbgShellException("No last session found.");
                }
                WriteOutput("Continuing the last watch-trace session...");
            }
            else
            {
                // prepare a new watch-trace session
                threadId = Debugger.Processes.Active.Threads.Active.Id;

                startFuncName = 
                Debugger.Processes.Active.Threads.Active.CurrentFrame.Function.FullName;
                lastFuncName = startFuncName;
                depth = 0;

                if (parser.OptionPassed(depthOption))
                {
                    maxDepth = parser.GetOption(depthOption).AsInt;
                    if (maxDepth < 0)
                        throw new MDbgShellException("Depth cannot be negative.");
                }
                if (parser.OptionPassed(incNamespacesOption))
                {
                    incRgx = 
                    GetNamespaceRegex(parser.GetOption(incNamespacesOption).AsString);
                }
                if (parser.OptionPassed(excNamespacesOption))
                {
                    excRgx = 
                    GetNamespaceRegex(parser.GetOption(excNamespacesOption).AsString);
                }
            }
        }

        // creates a regex for matching traced function names
        private static Regex GetNamespaceRegex(String namespaceOption)
        {
            String[] tokens = namespaceOption.Split(new[] { ',' }, 
                                 StringSplitOptions.RemoveEmptyEntries);
            if (tokens.Length > 0)
            {
                return new Regex("^(?:" + String.Join("|", 
                   tokens.Select(s => "(?:" + s + ")")) + ")",
                   RegexOptions.Compiled | RegexOptions.Singleline);
            }
            return null;
        }
        ...
    }
}

We are now ready to implement our extension method body:

namespace Mdb.Extension
{
    [MDbgExtensionEntryPointClass(Url = "http://lowleveldesign.wordpress.com")]
    public sealed class WatchTraceExtension : CommandBase
    {
       ...
       public static void WatchTrace(String argString)
       {
            PrepareCall(argString);

            while (true)
            {
                if (!Debugger.Processes.HaveActive)
                    break;
                // check call depth
                if (maxDepth > 0 && depth >= maxDepth)
                {
                    // if greater than maximum step out of the function
                    Debugger.Processes.Active.StepOut().WaitOne();
                }
                else
                {
                    // otherwise step one instruction
                    Debugger.Processes.Active.StepInto(false).WaitOne();
                }

                MDbgFrame frame = GetCurrentFrame();
                if (frame == null)
                    break;
                String funcName = frame.Function.FullName;
                if (!String.Equals(funcName, lastFuncName, StringComparison.Ordinal))
                {
                    depth = CalculateCallDepth(frame);
                    if (depth < 0)
                    {
                        // it may happen if we are out of our base function
                        // so we need to stop tracing
                        break;
                    }
                    PrintCallStackTrace(funcName, depth);
                    lastFuncName = funcName;
                }
            }
            // let's handle control to the debugger
            Shell.DisplayCurrentLocation();
        }
        ...
    }
}

In the code above, we simply check whether we reached the maximum call depth (specified by the user using the -l switch) and based on this information, we either step out of the current function (so decrement the depth) or step into it (so either stay in it or enter a new one). The GetCurrentFrame method returns if possible the top frame from the thread call stack:

namespace Mdb.Extension
{
    [MDbgExtensionEntryPointClass(Url = "http://lowleveldesign.wordpress.com")]
    public sealed class WatchTraceExtension : CommandBase
    {
       ...
        private static MDbgFrame GetCurrentFrame()
        {
            // debuggee might be already dead
            if (!Debugger.Processes.HaveActive)
                return null;
            // valid are only step-complete stops
            Object stopReason = Debugger.Processes.Active.StopReason;
            Type stopReasonType = stopReason.GetType();
            if (stopReasonType != typeof(StepCompleteStopReason))
                return null;
            // must have active thread
            if (!Debugger.Processes.Active.Threads.HaveActive)
                return null;
            // if event came from a different thread we finish tracing
            var thread = Debugger.Processes.Active.Threads.Active;
            Debug.Assert(thread != null);
            if (thread.Id != threadId)
                return null;
            if (!thread.HaveCurrentFrame)
                return null;
            return thread.CurrentFrame;
        }
        ...
    }
}

There are two more methods that need to be explained: CalculateCallDepth and PrintCallStackTrace. The CalculateCallDepth method iterates through the thread’s call stack and calculates the depth of the call by counting the number of frames on the stack between the current frame and a frame representing our start function (so the function in which we started tracing):

namespace Mdb.Extension
{
    [MDbgExtensionEntryPointClass(Url = "http://lowleveldesign.wordpress.com")]
    public sealed class WatchTraceExtension : CommandBase
    {
       ...
       private static int CalculateCallDepth(MDbgFrame frame)
        {
            int depth = 0;
            while (frame != null && frame.IsManaged)
            {
                Debug.Assert(frame.Function != null);
                if (String.Equals(frame.Function.FullName, 
                                  startFuncName, StringComparison.Ordinal))
                    return depth;
                frame = frame.NextUp;
                depth++;
            }
            return -1;
        }
        ...
    }
}

PrintCallStackTrace simply checks if the current function name matches the namespace constraints provided by the user and prints the function name with the indentation adequate to its call depth:

namespace Mdb.Extension
{
    [MDbgExtensionEntryPointClass
    (Url = "http://lowleveldesign.wordpress.com")]
    public sealed class WatchTraceExtension : CommandBase
    {
       ...
        private static void PrintCallStackTrace(String funcName, int depth)
        {
            if ((incRgx == null || incRgx.IsMatch(funcName)) && 
                (excRgx == null || !excRgx.IsMatch(funcName)))
            {
                String indentStr = new String(' ', depth);
                WriteOutput(String.Format("[{0,3}]  
                {1}{2}", depth, indentStr, funcName));
            }
        }
        ...
    }
}

Using our Extension in Mdbg

Unfortunately, MDbg is not platform agnostic and if you have a 32-bit application, you require a 32-bit MDbg version to successfully debug it (for 64-bit, you will need a 64-bit MDbg version). Fortunately, both those versions should be installed with the Windows SDK accordingly in c:\Program Files\Microsoft SDKs\Windows\v7.1\Bin\NETFX 4.0 Tools\ and c:\Program Files\Microsoft SDKs\Windows\v7.1\Bin\NETFX 4.0 Tools\x64\ folders. So compile your extension for both those platforms and copy the DLLs to their corresponding directories. Now, we are finally ready to use our extension. We will debug a very simple application just to show you how the extension works. Here’s the code:

using System;

public class T {
    public T() {
        String str = TestClass.Test4;
    }
}

public static class TestClass 
{
    public static T Test1() {
        return new T();
    }
    
    public static void Test2() {
      Test1();
    }
    
    public static void Test3() {
      Test2();
    }
    
    public static String Test4 {
        get { return "test"; }
    }
    
    public static void Main(String[] args) {
      Test3();
    }
}

Compile it:

csc /debug+ /platform:x86 Program.cs

and run it under the MDbg debugger:

mdbg Program.exe

You should see something similar to:

MDbg (Managed debugger) v4.0.30319.1 (RTMRel.030319-0100) started.
Copyright (C) Microsoft Corporation. All rights reserved.

For information about commands type "help";
to exit program type "quit".

run Program.exe
STOP: Breakpoint Hit
27:    public static void Main(String[] args) {
[p#:0, t#:0] mdbg>

Now load the extension...

[p#:0, t#:0] mdbg> load wtrace
trying to load: .\wtrace.dll
wtrace extension loaded

...and issue the wt command excluding TestClass.Test3 method:

[p#:0, t#:0] mdbg> wt -exc TestClass.Test3
[  2]    TestClass.Test2
[  3]     TestClass.Test1
[  4]      T..ctor
[  5]       System.Object..ctor
[  4]      T..ctor
[  5]       TestClass.get_Test4
[  4]      T..ctor
[  3]     TestClass.Test1
[  2]    TestClass.Test2
[  0]  TestClass.Main
STOP: Process Exited
mdbg>

In the output, you can see an indented method call tree with excluded calls to TestClass.Test3. Although this case is a very simple example, you can try mdbg and the wt commands in more complicated scenarios, like dumping the ASP.NET pipeline calls or checking how your WCF service is being called. For instance, to debug the ASP.NET pipeline on IIS, you will start by attaching to IIS instance, placing a breakpoint on, for instance, HttpRuntime.System.Web.HttpRuntime.ProcessRequestNotificationPrivate and waiting till your breakpoint is hit. When the debugger stops on your breakpoint, use wt -l 6 and check which methods are being called.

I hope that I encouraged you to use the MDbg debugger. Maybe you have an idea for a different extension or maybe you already know a great one? If so, please leave a comment so others might also find it. :) As usual, the source code and binaries are available on my blog sample site.