Naveen's Blog

There have been times when we would like to the know function return value ,debug within the function and get profiling information like the duration of a function. VS.NET provides all these features, but in production environment we won’t have VS.NET. This is where Windbg comes in handy.  Here is the sample code that I am going to use.

using System;
using System.Collections.Generic;
using System.Threading;
using System.Windows.Forms;
namespace WindowsFormsApplication1
{
public partial class Form1 : Form
{
public Form1(){
InitializeComponent();
}
private void Button1Click(object sender, EventArgs e){
Func<string> x = () => “Lambda “;
var result = x();
Console.WriteLine(result);
}
private void Button2Click(object sender, EventArgs e){
Console.WriteLine(longRunningMethod() );
}
string Test(){
return “Cool trick ” + Test1();
}
string Test1(){
return “foo”;
}
string longRunningMethod() {
Thread.Sleep(2000);
return “slowone”;
}
}
}

So the first step is to figure out what would be value of “result” within the Button1Click. To do this I would have to get the return value of “x” lambda.

Launched the exe , attached to Windbg. Loaded SOS. Look for methodtable

0:004> .loadby sos mscorwks
0:004> !dumpheap -type Form1
Address               MT     Size
0000000002861fa8 000007ff00026af0      472
total 1 objects
Statistics:
MT    Count    TotalSize Class Name
000007ff00026af0        1          472 WindowsFormsApplication1.Form1
Total 1 objects

Look for the method Button1

0:004> .shell -ci “!dumpmt -md 000007ff00026af0 ” findstr Button1
000007ff0002c050 000007ff00026a18      JIT WindowsFormsApplication1.Form1.Button1Click(System.Object, System.EventArgs)
000007ff00170a10 000007ff00026a68      JIT WindowsFormsApplication1.Form1.<Button1Click>b__0()
.shell: Process exited

The above result gave address for “Button1Click” as well as the lambda that we have inside the Button1Click called “b__0”. But in real-world we could probably have more than one lambda within a function, and it is hard to guess which one we should debug.Here are the steps to verify and extract name of the lambda. Lets disassemble the Button1Click by looking at it IL. So to get the IL we would need the MethodDesc which is  “000007ff00026a18 “ this information available from our previous command.

0:004> !dumpil 000007ff00026a18
ilAddr = 000000000136228c
IL_0000: nop
IL_0001: ldsfld WindowsFormsApplication1.Form1::CS$<>9__CachedAnonymousMethodDelegate1
IL_0006: brtrue.s IL_001b
IL_0008: ldnull
IL_0009: ldftn WindowsFormsApplication1.Form1::<Button1Click>b__0
IL_000f: newobj class [System.Core]System.Func`1<string>::.ctor
IL_0014: stsfld WindowsFormsApplication1.Form1::CS$<>9__CachedAnonymousMethodDelegate1
IL_0019: br.s IL_001b
IL_001b: ldsfld WindowsFormsApplication1.Form1::CS$<>9__CachedAnonymousMethodDelegate1
IL_0020: stloc.0
IL_0021: ldloc.0
IL_0022: callvirt class [System.Core]System.Func`1<string>::Invoke
IL_0027: ldarg.0
IL_0028: call WindowsFormsApplication1.Form1::Test
IL_002d: call System.String::Concat
IL_0032: stloc.1
IL_0033: ldloc.1
IL_0034: call System.Console::WriteLine
IL_0039: nop
IL_003a: ret

From the IL we can figure out the method name of the lambda is “b__0”. Now that we have the name, we will put a break-point on the function b__0 to get the return value

bp /1 000007ff00170a10 ” bp poi(@rsp) \” du @rax+10;g \”; g “

In the above break-point I have used to “/1” to create a one-shot break-point. This means create the BP, and once when it hits remove the BP.   The reason for one-shot Break-Point is we are not interested in the start of the function, we are interested only on the return.

Here is the trick ,so when the initial Break-Point hits on this address “000007ff00170a10” it executes what ever is there within quotes. And the command I have used ,is to create another break-point. So I am creating a dynamic break-point “bp poi(@rsp)”. The function return address is stored in the @rsp register for x64 and @esp for x86. So with @rsp having the address of the function return, I have managed to set bp with on lambda function return.

The next step is to get the return value from the function. The function return value is stored in the address register rax in x64 and eax in x86 . The “du @rax+10” du command is for dumping string at the register @rax and “+10” is the actual location of the string inside the managed object.

So we have managed to get the output of the lambda function

0:004> g
00000000`028a9a38  “Lambda “

Using the same trick we can even profile methods, like getting function execution time within Windbg. Here I am going to profile the method “longRunningMethod”

0:004> .shell -ci “!dumpmt -md 000007ff00026af0 ” findstr long
000007ff0002c070 000007ff00026a58      JIT WindowsFormsApplication1.Form1.longRunningMethod()
.shell: Process exited

I get the function address in the above command. The next step is to set the Break-Point.

bp  000007ff0002c070 “.printf \” longrunningmethod \”; .echotime ;bp poi(@rsp) \”  .echotime;g \”; g “

In the above command within function start break-point, I use the command .printf to print the “longrunningmethod” and then .echotime to print out the start time of the function, and like I did before I am dynamically creating another break-point (bp poi(@rsp)),at the return of function ,on which I am also printing out the system time using .echotime.

0:004> g
longrunningmethod Debugger (not debuggee) time: Sun Feb 21 16:47:35.117 2010 (GMT-5)
Debugger (not debuggee) time: Sun Feb 21 16:47:37.122 2010 (GMT-5)

So in the above output the function duration is about 2 seconds as we expected it to be (in the code i have sleep for 2000 milliseconds). This is almost like having log statement on the function start and the function end.