.NET 4.0 | Naveen's Blog

Archive for the ‘.NET 4.0’ Category

In this post I am going to be discussing about debugging .Net Framework 4.0 using windbg . I am going to demonstrating how to have a break-point within a method, but without the framework source code. This would help in debugging .NET framework when you don’t have VS in a production environment and the same technique can be used to debug other third party assemblies where you don’t have the source code. This is kind of like .NET Reflector where you can step through third party assemblies, but without any cost. It is not going to be as convenient as the professional version of Reflector.

I am going to be using the same example that I used to debug .NET Framework source 3.5 using windbg.

FYI the .NET framework 4.0 has private symbols available on MS symbol server, but the source code is still not available. To debug .NET framework source code it is important to have correct symbol path and here is my symbol path in the _NT_SYMBOL_PATH environment variable.


SRV*d:\dev\symbols*http://referencesource.microsoft.com/symbols; SRV*d:\dev\symbols*http://msdl.microsoft.com/download/symbols

Here is the sample source code that I am going to be using to demonstrate framework debugging


using System;
 using System.Net;
 namespace Test
 {
 class Program
 {
 static void Main(string[] args)
 {
 Console.WriteLine("Hello World of debugging");
 var wr = WebRequest.Create("http://www.google.com");
 Console.WriteLine("Web request created");
 var req = wr.GetRequestStream();
 Console.WriteLine("Hello World Debugging");
 Console.Read();
 }
 }
 }

Launched the exe within the debugger

Then issued the command to notify when the clrjit is loaded,


sxe ld:clrjit

This is because, to load sos and sosex after the framework is loaded.Then issued the following commands to load sos, sosex and to set break-point on WebRequest.Create


.loadby sos mscorwks
.load sosex
!mbm System.Net.WebRequest.Create

And when the break-point hits the first time, let it continue by using the g command. It would break into the debugger for other overloaded method for WebRequest.Create and here is the call-stack

0:000> !mk
Thread 0:
ESP EIP
00:M 000000000023ece0 000007fef6ea5a44 System.Net.WebRequest.Create(System.Uri, Boolean)(+0×0 IL)(+0×14 Native) [f:\dd\ndp\fx\src\Net\System\Net\WebRequest.cs, @ 93,13]
01:M 000000000023ed60 000007ff00140176 Test.Program.Main(System.String[])(+0xc IL)(+0×56 Native)
02:U 000000000023edc0 000007fef8b210b4 clr!CallDescrWorker+0×84
03:U 000000000023ee10 000007fef8b211c9 clr!CallDescrWorkerWithHandler+0xa9
04:U 000000000023ee90 000007fef8b21245 clr!MethodDesc::CallDescr+0x2a1
05:U 000000000023f0c0 000007fef8c21675 clr!ClassLoader::RunMain+0×228
06:U 000000000023f310 000007fef8c217ac clr!Assembly::ExecuteMainMethod+0xac
07:U 000000000023f5c0 000007fef8c21562 clr!SystemDomain::ExecuteMainMethod+0×452
08:U 000000000023fb70 000007fef8c23dd6 clr!ExecuteEXE+0×43
09:U 000000000023fbd0 000007fef8c23cf3 clr!CorExeMainInternal+0xc4
0a:U 000000000023fc40 000007fef8ca7365 clr!CorExeMain+0×15
0b:U 000000000023fc80 000007fef9493309 mscoreei!CorExeMain+0×41
0c:U 000000000023fcb0 000007fef9525b21 MSCOREE!CorExeMain_Exported+0×57
0d:U 000000000023fce0 00000000776cf56d KERNEL32!BaseThreadInitThunk+0xd
0e:U 000000000023fd10 0000000077903281 ntdll!RtlUserThreadStart+0x1d

And here is the source code for this method using reflector


private static WebRequest Create(Uri requestUri, bool useUriBase)
{
 string absoluteUri;
 if (Logging.On)
 {
 Logging.Enter(Logging.Web, "WebRequest", "Create", requestUri.ToString());
 }
 WebRequestPrefixElement element = null;
 bool flag = false;
 if (!useUriBase)
 {
 absoluteUri = requestUri.AbsoluteUri;
 }
 else
 {
 absoluteUri = requestUri.Scheme + ':';
 }
 int length = absoluteUri.Length;
 ArrayList prefixList = PrefixList;
 for (int i = 0; i < prefixList.Count; i++)
 {
 element = (WebRequestPrefixElement) prefixList[i];
 if ((length >= element.Prefix.Length) && (string.Compare(element.Prefix, 0, absoluteUri, 0, element.Prefix.Length, StringComparison.OrdinalIgnoreCase) == 0))
 {
 flag = true;
 break;
 }
 }
 WebRequest retObject = null;
 if (flag)
 {
 retObject = element.Creator.Create(requestUri);
 if (Logging.On)
 {
 Logging.Exit(Logging.Web, "WebRequest", "Create", retObject);
 }
 return retObject;
 }
 if (Logging.On)
 {
 Logging.Exit(Logging.Web, "WebRequest", "Create", (string) null);
 }
 throw new NotSupportedException(SR.GetString("net_unknown_prefix"));
}

Let’s try and have a break-point on line “ ArrayList prefixList = PrefixList;” so that we can check the local variables value. Just because I have the private symbols ,I could have counted the line numbers manually and then set a break-point using !mbp command, but that is no fun. Here is another way of doing this.


.shell -ci "!u 000007fef6ea5a44 "  findstr get_PrefixList

In the above command I am disassembling the ip 000007fef6ea5a44 (which is there in the above callstack )to look for get_PrefixList Instruction pointer . Here is the outcome

0:000> .shell -ci “!u 000007fef6ea5a44 “ findstr get_PrefixList

000007fe`f6ea5a7a e8f1000000 call System_ni+0x275b70 (000007fe`f6ea5b70) (System.Net.WebRequest.get_PrefixList(), mdToken: 00000000060019bc)

.shell: Process exited

I use the .shell command to manually avoid searching for an instruction. Now that I have the instruction pointer ,I am going to set a break-point on that using


bp 000007fe`f6ea5a7a "!mdv"

and here is the result of the break-point

0:000> g
(1758.167c): CLR notification exception – code e0444143 (first chance)
(1758.167c): CLR notification exception – code e0444143 (first chance)
Frame 0×0: (System.Net.WebRequest.Create(System.Uri, Boolean)):
[A0]:requestUri:<?>
[A1]:useUriBase:<?>
[L0]:LookupUri:0x00000000022c1a98 (System.String) STRVAL=http://www.google.com/
[L1]:Current:<?>
[L2]:Found:0×0000000000000000 (System.Boolean)
[L3]:LookupLength:0×0000000000000016 (System.Int32)
[L4]:prefixList:<?>
[L5]:i:<?>
[L6]:webRequest:<?>

System_ni+0x275a7a:
000007fe`f6ea5a7a e8f1000000 call System_ni+0x275b70 (000007fe`f6ea5b70)

Voila! now I am able to have a break-point within the framework method and also see locals and parameters like Visual Studio. The same technique can be used to debug third party assemblies where you don’t have source code or symbols.

Written by Naveen

May 31, 2010 at 9:13 pm

Posted in .NET 4.0, SOSEX, Windbg

Tagged with .NET 4.0, SOSEX, Windbg

Exploring UnhandledException in .NET and Watson buckets

with 4 comments

I wanted to understand about UnhandledExceptions in .NET because of the few questions that I saw in the CLR Forum ,which had watson buckets in the event viewer. To get deep understanding unhandled exception filter there is a article on MSDN from CLR Team.

In this post I will be demonstrating how to get the Watson Bucket from within your code . FYI this is the same information you can get !WatsonBuckets from sos within Windbg whenever there is a termination of the .NET process. !WatsonBuckets is undocumented. I am using the CLR hosting interfaces to get the watson bucket. Here is the code that throws an unhandled exception and invokes clr to get watson bucket info.

using System;
using System.Runtime.InteropServices;

namespace WatsonTest
{
 internal class Test
 {
 private static void Main(string[] args)
 {
 var t = AppDomain.CurrentDomain;
 t.UnhandledException += (s, e) =>
 {
 var c = GetWatsonBuckets();
 Console.WriteLine(c);
 Console.Read();
 };
 throw new NullReferenceException();
 }
 private static WatsonBuckets GetWatsonBuckets()
 {
 var pParams = new WatsonBuckets();
 IClrRuntimeHost host = null;
 host = Activator.CreateInstance(Type.GetTypeFromCLSID(ClrGuids.ClsIdClrRuntimeHost)) as IClrRuntimeHost;
 if (host != null)
 {
 var clrControl = host.GetCLRControl();
 if (clrControl == null)
 {
 return pParams;
 }
 var clrErrorReportingManager =
 clrControl.GetCLRManager(ref ClrGuids.IClrErrorReportingManager) as IClrErrorReportingManager;
 if (clrErrorReportingManager == null)
 {
 return pParams;
 }
 clrErrorReportingManager.GetBucketParametersForCurrentException(out pParams);
 }
 return pParams;
 }
 }
 // BucketParameters Structure to get watson buckets back from CLR
 //http://msdn.microsoft.com/en-us/library/ms404466(v=VS.100).aspx
 [StructLayout(LayoutKind.Sequential, CharSet = CharSet.Auto)]
 internal struct WatsonBuckets
 {
 internal int fInited;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string pszEventTypeName;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param0;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param1;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param2;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param3;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param4;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param5;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param6;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param7;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param8;
 [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 0xff)] internal string param9;
 }

 internal static class ClrGuids
 {
 internal static readonly Guid ClsIdClrRuntimeHost = new Guid("90F1A06E-7712-4762-86B5-7A5EBA6BDB02");
 internal static Guid IClrErrorReportingManager = new Guid("980D2F1A-BF79-4c08-812A-BB9778928F78");
 internal static readonly Guid IClrRuntimeHost = new Guid("90F1A06C-7712-4762-86B5-7A5EBA6BDB02");
 }

 [Guid("90F1A06C-7712-4762-86B5-7A5EBA6BDB02"), InterfaceType(ComInterfaceType.InterfaceIsIUnknown)]
 internal interface IClrRuntimeHost
 {
 void Start();
 void Stop();
 void SetHostControl(IntPtr pHostControl);
 IClrControl GetCLRControl();
 void UnloadAppDomain(int dwAppDomainId, bool fWaitUntilDone);
 void ExecuteInAppDomain(int dwAppDomainId, IntPtr pCallback, IntPtr cookie);
 int GetCurrentAppDomainId();

 int ExecuteApplication(string pwzAppFullName, int dwManifestPaths, string[] ppwzManifestPaths,
 int dwActivationData, string[] ppwzActivationData);

 int ExecuteInDefaultAppDomain(string pwzAssemblyPath, string pwzTypeName, string pwzMethodName,
 string pwzArgument);
 }

 [Guid("9065597E-D1A1-4fb2-B6BA-7E1FCE230F61"), InterfaceType(ComInterfaceType.InterfaceIsIUnknown)]
 internal interface IClrControl
 {
 [return: MarshalAs(UnmanagedType.IUnknown)]
 object GetCLRManager([In] ref Guid riid);

 void SetAppDomainManagerType(string pwzAppDomainManagerAssembly, string pwzAppDomainManagerType);
 }
 // IClrErrorReportingManager to get watson bukets back from CLR
 //http://msdn.microsoft.com/en-us/library/ms164367(v=VS.100).aspx
 [Guid("980D2F1A-BF79-4c08-812A-BB9778928F78"), InterfaceType(ComInterfaceType.InterfaceIsIUnknown)]
 internal interface IClrErrorReportingManager
 {
 [PreserveSig]
 int GetBucketParametersForCurrentException(out WatsonBuckets pParams);
 }
}

The watson bucket information has ten items

AppName
Version
?
Assembly and Module Name
Assembly Version
?
MethodDef
IL Offset
Exception Type
?

In the above code WatsonBuckets is a structure to get watson bucket information back from CLR. In the code I use 3 hosting interfaces, IClrRuntimeHost which is the main interface, the next interface is IClrControl which has GetCLRManager method to get ErrorReportingManger. IClrErrorReportingManager which has the method to get the exception buckets which is GetBucketParametersForCurrentException. I know that there isn’t going to be much of use for this code. But it gives me better understanding of CLR integrates with watson when ever there is termination of an application.

Written by Naveen

April 24, 2010 at 9:34 pm

Posted in .NET, .NET 4.0, SOS, Windbg

Tagged with .NET, CLR Hosting, SOS, Watson, Windbg

Exploring SOSEX and Windbg to debug .NET 4.0

with 3 comments

With the latest release of sosex comes a new set of functions to debug. It is pretty awesome that one person (Steve) alone could pull of such cool things. In this blog post, I am just going to demonstrate how easy it is to debug managed code using sosex compared to sos.

using System;
using System.Collections.Generic;

namespace MemCheck
{
 internal class Test
 {
 Dictionary<int, string> dict = new Dictionary<int, string>();
 private static void Main(string[] args)
 {
 var p = new Test();
 for (int i = 0; i < 100; i++)
 {
 p.dict.Add(i, i.ToString());
 }
 Console.WriteLine("Done");
 Console.Read();
 }
 }
}

I like to keep the code simple , so it is easy to follow. The debugging goal for today is to get the Dictionary values. First I am going to demonstrate it using sos and then using sosex.

As usual I start the app and then attach it to windbg.

.loadby sos clr

FYI in .net 4.0 clr is the dll that has CLR implementation. In prior versions it used to be in mscorwks. The next command would look for the object Test in the memory

!dumpheap -type MemCheck.Test
0:000> !dumpheap -type MemCheck.Test
 Address               MT     Size
0000000002761e20 000007ff00054110       24
 total 0 objects
 Statistics:
 MT    Count    TotalSize Class Name
 000007ff00054110        1           24 MemCheck.Test
 Total 1 objects

The next step is to dump the object

0:000> !do 0000000002761e20
Name:        MemCheck.Test
MethodTable: 000007ff00054110
EEClass:     000007ff00162350
Size:        24(0x18) bytes
File:        C:\Users\naveen\Documents\Visual Studio 2010\Projects\Test\bin\Debug\Test.exe
Fields:
 MT    Field   Offset                 Type VT     Attr            Value Name
000007feec2b7a48  4000001        8 ...tring, mscorlib]]  0 instance 0000000002761e38 dict

Notice the dict object is in the 8th offset . To dump contents dict object I would use the command !do poi(0000000002761e20+8) , which is pointer deference of Test object on it is 8th offset. And here is the output

0:000> !do poi(0000000002761e20+8)
Name:        System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib],[System.String, mscorlib]]
MethodTable: 000007feec2b7a48
EEClass:     000007feebe113c0
Size:        88(0x58) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
 MT    Field   Offset                 Type VT     Attr            Value Name
000007feec27c7d8  4000bee        8       System.Int32[]  0 instance 0000000002764788 buckets
000007feecbd3dc8  4000bef       10 ...non, mscorlib]][]  0 instance 0000000002764ab8 entries
000007feec27c848  4000bf0       40         System.Int32  1 instance              100 count
000007feec27c848  4000bf1       44         System.Int32  1 instance              100 version
000007feec27c848  4000bf2       48         System.Int32  1 instance               -1 freeList
000007feec27c848  4000bf3       4c         System.Int32  1 instance                0 freeCount
000007feec2a5a48  4000bf4       18 ...Int32, mscorlib]]  0 instance 0000000002761ef0 comparer
000007feecc75f78  4000bf5       20 ...Canon, mscorlib]]  0 instance 0000000000000000 keys
000007feecc72078  4000bf6       28 ...Canon, mscorlib]]  0 instance 0000000000000000 values
000007feec275ab8  4000bf7       30        System.Object  0 instance 0000000000000000 _syncRoot
000007feec29a1b8  4000bf8       38 ...SerializationInfo  0 instance 0000000000000000 m_siInfo

And the dictionary object in turn stores them within an array which is again the 8th offset. This time because we know it is an array we are going to use the !dumparray command on the memory location. The command to get the details is

!dumparray -details poi(poi(0000000002761e20+8)+8)
MT    Field   Offset                 Type VT     Attr            Value Name
 000007feec27c848  400047b        0             System.Int32      1     instance                   -1     m_value
 [195] 0000000002764aa4
 Name:        System.Int32
 MethodTable: 000007feec27c848
 EEClass:     000007feebe00890
 Size:        24(0x18) bytes
 File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
 Fields:
 MT    Field   Offset                 Type VT     Attr            Value Name
 000007feec27c848  400047b        0             System.Int32      1     instance                   -1     m_value
 [196] 0000000002764aa8
 Name:        System.Int32
 MethodTable: 000007feec27c848
 EEClass:     000007feebe00890
 Size:        24(0x18) bytes
 File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
 Fields:
 MT    Field   Offset                 Type VT     Attr            Value Name
 000007feec27c848  400047b        0             System.Int32      1     instance                   -1     m_value

Here is the partial output.

Now lets try and do the same thing using sosex. The one thing that I really like about the new sosex is that I can use names rather than pointer deference which is way much easier. Launched the app and then loaded sosex using the command

.load F:\Work\Tools\debuggers\sosex.dll

and then switched the thread from 4th to 0th thread using ~0s. By default the debugger injects a thread into the process for debugging and that was the 4th thread. The next command I issued was to get stack trace

!mk
0:000> !mk
Thread 0:
 ESP              EIP
00:U 000000000015e408 0000000077bc00da ntdll!ZwRequestWaitReplyPort+0xa
01:U 000000000015e410 0000000077a72b08 KERNEL32!ConsoleClientCallServer+0x54
02:U 000000000015e440 0000000077aa5601 KERNEL32!ReadConsoleInternal+0x1f1
03:U 000000000015e590 0000000077aba922 KERNEL32!ReadConsoleA+0xb2
04:U 000000000015e670 0000000077a89934 KERNEL32!zzz_AsmCodeRange_End+0x8bea
05:U 000000000015e6b0 000007feed0317c7 clr!DoNDirectCall__PatchGetThreadCall+0x7b
06:M 000000000015e760 000007feec1d34a1 DomainNeutralILStubClass.IL_STUB_PInvoke(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)(+0x0 IL)(+0x0 Native)
07:M 000000000015e880 000007feec97f59a System.IO.__ConsoleStream.ReadFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, Int32, Int32 ByRef)(+0x53 IL)(+0xba Native)
08:M 000000000015e8f0 000007feec97f402 System.IO.__ConsoleStream.Read(Byte[], Int32, Int32)(+0x5d IL)(+0x62 Native)
09:M 000000000015e950 000007feec18e63c System.IO.StreamReader.ReadBuffer()(+0xa0 IL)(+0x5c Native)
0a:M 000000000015e9a0 000007feec915630 System.IO.StreamReader.Read()(+0x21 IL)(+0x30 Native)
0b:M 000000000015e9e0 000007feec987458 System.IO.TextReader+SyncTextReader.Read()(+0x0 IL)(+0x38 Native)
0c:M 000000000015ea30 000007ff00170213 MemCheck.Test.Main(System.String[])(+0x39 IL)(+0xf3 Native) [C:\Users\naveen\Documents\Visual Studio 2010\Projects\Test\Program.cs, @ 17,13]
0d:U 000000000015eaa0 000007feed0710b4 clr!CallDescrWorker+0x84
0e:U 000000000015eaf0 000007feed0711c9 clr!CallDescrWorkerWithHandler+0xa9
0f:U 000000000015eb70 000007feed071245 clr!MethodDesc::CallDescr+0x2a1
10:U 000000000015eda0 000007feed171675 clr!ClassLoader::RunMain+0x228
11:U 000000000015eff0 000007feed1717ac clr!Assembly::ExecuteMainMethod+0xac
12:U 000000000015f2a0 000007feed171562 clr!SystemDomain::ExecuteMainMethod+0x452
13:U 000000000015f850 000007feed173dd6 clr!ExecuteEXE+0x43
14:U 000000000015f8b0 000007feed173cf3 clr!CorExeMainInternal+0xc4
15:U 000000000015f920 000007feed1f7365 clr!CorExeMain+0x15
16:U 000000000015f960 000007fef8f13309 mscoreei!CorExeMain+0x41
17:U 000000000015f990 000007fef8fa5b21 MSCOREE!CorExeMain_Exported+0x57
18:U 000000000015f9c0 0000000077a6f56d KERNEL32!BaseThreadInitThunk+0xd
19:U 000000000015f9f0 0000000077ba3281 ntdll!RtlUserThreadStart+0x1d

FYI the command !mk has been part of sos from the initial version. I am interested in only looking at the code that I wrote so I would like to move stack frame to 0c which is MemCheck.Test.Main . To do that the command is !mframe 0c, which moves to that stackframe. The reason to move the particular stack frame is to look for variables in the stack and the command to variables is !mdv , which display managed local variables

0:000> !mdv
Frame 0xc: (MemCheck.Test.Main(System.String[])):
[A0]:args:0x0000000002761dd8 (System.String[])
[L0]:p:0x0000000002761e20 (MemCheck.Test)
[L1]:i:0x0000000000000064 (System.Int32)
[L2]:CS$4$0000:0x0000000000000000 (System.Boolean)

Notice we see the local variable “p” which is of type MemCheck.Test. To display type p we issue the command !mdt p


0:000> !mdt p

0000000002761e20 (MemCheck.Test)

dict:0000000002761e38 (System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib],[System.String, mscorlib]])

I didn’t have to get memory address , I am using the names which is very intuitive ,especially when we have to debug large application with N levels of nesting.So to get the dict values from p the command to issue is !mdt -e p.dict

!mdt -e p.dict
[98] (System.Collections.Generic.Dictionary`2+Entry[[System.Int32, mscorlib],[System.String, mscorlib]]) VALTYPE (MT=000007feec2b7b28, ADDR=0000000002765400)
 key:0x62 (System.Int32)
 value:0000000002765e48 (System.String: "98")
[99] (System.Collections.Generic.Dictionary`2+Entry[[System.Int32, mscorlib],[System.String, mscorlib]]) VALTYPE (MT=000007feec2b7b28, ADDR=0000000002765418)
 key:0x63 (System.Int32)
 value:0000000002765e68 (System.String: "99")

Here is the partial output. Notice I never had to use a memory pointer or do a pointer deference .This is very similar to VS.NET debugging where I am used to the variable names compared the memory address. Thanks to Steve for providing such a cool extension.

Written by Naveen

April 21, 2010 at 1:55 am

Posted in .NET, .NET 4.0, SOS, SOSEX, Windbg

Tagged with .NET, .NET 4.0, SOS, sos.dll, SOSEX, Windbg

Exploring internal implementation of C# 4.0 Default and Optional arguments

with 2 comments

I wanted to explore how C# compiler has implemented the optional and the default parameter. So here is the sample code that I wrote to verify.

using System;
namespace OptionalTest {
 internal class Program {
 private static void Main(string[] args) {
 var p = new Program();
 Test();
 }
 private static void Test(int x = 10) {
 Console.WriteLine(x);
 }
 }
}

As you can see the default parameter value for x is 10 and it is an optional parameter. After compiling the source code the next step was to disassemble with Reflector.

private static void Test([Optional, DefaultParameterValue(10)] int x){
Console.WriteLine(x);
}

Now it makes sense, looks like the C# compiler emits a custom attribute for System.Runtime.InteropServices.OptionalAttribute which marks the method to have an optional argument and the DefaultParameterValue stores the default value for the parameter. The next step was to disassemble the caller of this function.

And here is the disassembled Main method using reflector

private static void Main(string[] args)
{
Program p = new Program();
Test(10);
}

Notice we didn’t include 10 as an argument to method Test. So the compiler notices that the calling code does not have value for the argument and copies the value from the DefaultParameterValue and sticks it in.

Written by Naveen

April 16, 2010 at 1:34 am

Posted in .NET 4.0

Tagged with .NET 4.0, C#4.0

Get Managed and Native Call Stacks from Event Tracing for Windows (ETW)

with 6 comments

Here is the TOC of series of posts on ETW

With the latest release of PerfMonitor from the CLR team now we can have Managed call stacks along with native code. How cool is that? To get managed / native call stacks we need minimum of Vista, this is not available in XP.

Here is the sample source code I am going to be using to demonstrate the managed and the native call-stacks

using System;
using System.Linq;
namespace ConsoleApplication9 {
class Program {
private static void Main() {
Console.Read();
AllocateLOH();
}
private static void AllocateLOH() {
for (int i = 0; i < 10; i++) {
var x = new object[85000];
x.Count();
}
}
}
}

This is a very simple app that allocates large chunks of memory, which will get allocated in the LOH and frequent allocations in LOH causes high CPU. To identify this we would have to attach it to windbg and put a break-point on “WKS::gc_heap::allocate_large_object” and here I have blogged about the same

But with ETW we will not need Windbg, the ETW can do stack walks for the function calls and this makes it really great. To enable this feature first thing is to download the source and compile the code from codeplex . FYI if you are using x64 th tool would not work. It would work on wow64 , so compile it for x86.

After which run the command


PerfMonitor crawlableCLRStacks

This will take a while to complete, it is essentially setting the ngened images to debug attributes so we can get better stack walks. The next command is to start etw trace


PerfMonitor.exe  /lineNumbers /stacks /keyAny:0x1 start

So we are essentially instructing the tool to get GC Information (/keyAny:0×1) along with stackwalk . The tool provides help which really useful.

After which I start the application and let the complete and then I stop the trace.


Perfmonitor.exe stop

And then dump the trace to a xml file


perfmonitor.exe print

This will dump out a huge file but what we are interested in Large Object Allocations on GC call stacks


<Event MSec=  "6940.8972" PID="365044" PName="ConsoleApplication9" TID="364352" EventName="GCAllocationTick" AllocationAmount="0x00053040" AllocationKind="Large" ClrInstanceID="15">

<StackTrace>

<CodeAddress Address="0x66669909" FullMethodName="ETW::SamplingLog::SendStackTrace" ModuleName="clr"/>

<CodeAddress Address="0x66669a8d" FullMethodName="EtwCallout" ModuleName="clr"/>

<CodeAddress Address="0x6669d870" FullMethodName="CoMofTemplate_qqh" ModuleName="clr"/>

<CodeAddress Address="0x666d5d44" ModuleName="clr"/>

<CodeAddress Address="0x6653ff5b" FullMethodName="WKS::gc_heap::allocate_more_space" ModuleName="clr"/>

<CodeAddress Address="0x66475d43" FullMethodName="WKS::gc_heap::allocate_large_object" ModuleName="clr"/>

<CodeAddress Address="0x666d61d8" FullMethodName="WKS::GCHeap::Alloc" ModuleName="clr"/>

<CodeAddress Address="0x666a39a7" ModuleName="clr"/>

<CodeAddress Address="0x664ef3d8" FullMethodName="AllocateArrayEx" ModuleName="clr"/>

<CodeAddress Address="0x664ef464" ModuleName="clr"/>

<CodeAddress Address="0x1f00ee" FullMethodName="ConsoleApplication9.Program.AllocateLOH()"/>

<CodeAddress Address="0x1f008e"/>

<CodeAddress Address="0x663f213b" FullMethodName="CallDescrWorker" ModuleName="clr"/>

<CodeAddress Address="0x66412c2f" FullMethodName="CallDescrWorkerWithHandler" ModuleName="clr"/>

<CodeAddress Address="0x66412dcc" FullMethodName="MethodDesc::CallDescr" ModuleName="clr"/>

<CodeAddress Address="0x66412e01" FullMethodName="MethodDesc::CallTargetWorker" ModuleName="clr"/>

<CodeAddress Address="0x66412e21" FullMethodName="MethodDescCallSite::Call_RetArgSlot" ModuleName="clr"/>

<CodeAddress Address="0x664c8872" FullMethodName="ClassLoader::RunMain" ModuleName="clr"/>

<CodeAddress Address="0x664c8980" FullMethodName="Assembly::ExecuteMainMethod" ModuleName="clr"/>

<CodeAddress Address="0x664c8794" FullMethodName="SystemDomain::ExecuteMainMethod" ModuleName="clr"/>

<CodeAddress Address="0x664ed6f5" FullMethodName="ExecuteEXE" ModuleName="clr"/>

<CodeAddress Address="0x664ed5f7" FullMethodName="_CorExeMainInternal" ModuleName="clr"/>

<CodeAddress Address="0x664e6db8" FullMethodName="_CorExeMain" ModuleName="clr"/>

<CodeAddress Address="0x704561f0" ModuleName="mscoreei"/>

<CodeAddress Address="0x706f7f16" FullMethodName="ShellShim__CorExeMain" ModuleName="mscoree"/>

<CodeAddress Address="0x706f4de3" FullMethodName="_CorExeMain_Exported" ModuleName="mscoree"/>

<CodeAddress Address="0x77bc9d72" FullMethodName="__RtlUserThreadStart" ModuleName="ntdll"/>

<CodeAddress Address="0x77bc9d45" FullMethodName="_RtlUserThreadStart" ModuleName="ntdll"/>

</StackTrace>

</Event

Here is a simple linq statement to extract the above information

 void Main()
 {
 var events = from e in XDocument.Load(@"c:\temp\test.xml").Descendants("Events").Descendants("Event").Take(5)
 where e.Attribute("EventName").Value == "GCAllocationTick" && e.Attribute("AllocationKind").Value == "Large"
 select new {Amount = Dec(e.Attribute("AllocationAmount").Value) ,
 Stack = e.Descendants("StackTrace").Descendants().Attributes("FullMethodName")};

var f = from e in events
 let stack = e.Stack.Select (s => s.Value )
 select new {AllocatedAmount = e.Amount,callstack = stack};
 }
 public static  int Dec(string hex)
 {
 var x1 = hex.Remove(0,3);
 return int.Parse(x1,System.Globalization.NumberStyles.AllowHexSpecifier);
 }

And here is the outcome from the linq code

IEnumerable<> (2 items)





AllocatedAmount

callstack



340032





IEnumerable<String> (23 items)



ETW::SamplingLog::SendStackTrace



EtwCallout



CoMofTemplate_qqh



WKS::gc_heap::allocate_more_space



WKS::gc_heap::allocate_large_object



WKS::GCHeap::Alloc



AllocateArrayEx



ConsoleApplication9.Program.AllocateLOH()



CallDescrWorker



CallDescrWorkerWithHandler



MethodDesc::CallDescr



MethodDesc::CallTargetWorker



MethodDescCallSite::Call_RetArgSlot



ClassLoader::RunMain



Assembly::ExecuteMainMethod



SystemDomain::ExecuteMainMethod



ExecuteEXE



_CorExeMainInternal



_CorExeMain



ShellShim__CorExeMain



_CorExeMain_Exported



__RtlUserThreadStart



_RtlUserThreadStart







340032





IEnumerable<String> (23 items)



ETW::SamplingLog::SendStackTrace



EtwCallout



CoMofTemplate_qqh



WKS::gc_heap::allocate_more_space



WKS::gc_heap::allocate_large_object



WKS::GCHeap::Alloc



AllocateArrayEx



ConsoleApplication9.Program.AllocateLOH()



CallDescrWorker



CallDescrWorkerWithHandler



MethodDesc::CallDescr



MethodDesc::CallTargetWorker



MethodDescCallSite::Call_RetArgSlot



ClassLoader::RunMain



Assembly::ExecuteMainMethod



SystemDomain::ExecuteMainMethod



ExecuteEXE



_CorExeMainInternal



_CorExeMain



ShellShim__CorExeMain



_CorExeMain_Exported



__RtlUserThreadStart



_RtlUserThreadStart







680064

Wow now we can see every callstack from ntdll to CLR along with our code in callstack. How cool it is to see managed callstack and native in one single block. This wasn’t possible until now. Thanks to the CLR team. Just like I mentioned in my previous blog post we wouldn’t have to use Windbg to get this information. This is only tip of the iceberg , we can do lot of cool things with this. I am sure Microsoft is working hard to integrate this within XPERF , but I am going to take a stab and see how I can display this data in a much more graphical way in my future posts. So next time someone complains of Performance issue in managed code you can probably ask them to just get on trace file , which will include everything to figure compared to getting few memory dumps , perfmon counters , webserver log .

Written by Naveen

April 2, 2010 at 2:01 am

Posted in .NET 4.0, ETW

Tagged with Debugging, ETW, GC, xperf

Exploring Event Tracing for Windows (ETW) within Task Parallel Library (TPL) using PerfMonitor

with one comment

Like I mentioned in my previous post , Today I am going to exploring TPL ETW traces. Yes, I know we could use the built in VS.NET profiler, but in production environment we don’t have VS.NET and guess what even VS.NET parallel profiler uses only ETW to get those good looking graphs.

With the today’s release of source code from BCL, I am going to be using PerfMonitor to parse these traces and dump them out in xml file. TPL uses ‘self-manifests’ (The manifest is dumped as event data) we don’t need a man file to interpret it (since it is in the stream). The TraceEvent code has the ability to decode these events using the manifest in the data stream.

The sample I am going to be using for tracing is MandelbrotFractals_CSharp which is from the PFX Team

I am starting the trace using xperf , on the TPL ETW provider


xperf -start clr -on 2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5 -f clrevents.etl

Started the application and then stopped the trace using


xperf -stop clr

I had to make few changes to the TraceEvent Code, these are minor . Especially the code didn’t handle Boolean and it was throwing an exception , anybody can make this simple fix.

To get the trace from the ETL to xml here is the command


PerfMonitor.exe /keepETL print clrevents.etl

In the above command we are instructing the exe to convert the etl to xml and not to delete the ETL file after doing it.

The above command output’s an xml file. Here is a sample output from the actual xml file.


<Event MSec= "24181.0409" PID="1635144" PName="(1635144)" TID="1634556" EventName="TaskStarted" ProviderName="TplEtwProvider" OriginatingTaskSchedulerID="1" OriginatingTaskID="0" TaskID="5"/>

<Event MSec= "24181.0734" PID="1635144" PName="(1635144)" TID="1634556" EventName="TaskScheduled" ProviderName="TplEtwProvider" OriginatingTaskSchedulerID="1" OriginatingTaskID="5" TaskID="6" CreatingTaskID="4" TaskCreationOptions="10500"/>

<Event MSec= "24181.0772" PID="1635144" PName="(1635144)" TID="1634556" EventName="ParallelFork" ProviderName="TplEtwProvider" OriginatingTaskManager="1" OriginatingTaskID="5" ForkJoinContextID="1"/>

<Event MSec= "24413.3543" PID="1635144" PName="(1635144)" TID="1634556" EventName="ParallelJoin" ProviderName="TplEtwProvider" OriginatingTaskSchedulerID="1" OriginatingTaskID="5" ForkJoinContextID="1"/>

<Event MSec= "24413.3624" PID="1635144" PName="(1635144)" TID="1634556" EventName="TaskScheduled" ProviderName="TplEtwProvider" OriginatingTaskSchedulerID="1" OriginatingTaskID="5" TaskID="7" CreatingTaskID="4" TaskCreationOptions="10500"/>

<Event MSec= "24413.3791" PID="1635144" PName="(1635144)" TID="1634556" EventName="TaskCompleted" ProviderName="TplEtwProvider" OriginatingTaskSchedulerID="1" OriginatingTaskID="0" TaskID="5" IsExceptional="False"/>

From the above we can see when the task was scheduled, which is the originating task and when did it complete.

This wouldn’t have been possible without ETW, even with Windbg we cannot these information. This can help us understand what is happening with in TPL , which will enable us to design better.

FYI, Perfmonitor is just an implementation of the TraceEvent API which converts the ETW data to xml. It gives us possibilities to extend this.

In the coming posts I will be exploring how ETW can literally replace debugger in Production environment. Don’t get me wrong, I am very BIG fan of Windbg and have been using it to understand the OS and the CLR.

Thanks to Vance Morrison for letting me know about TraceEvent.

Written by Naveen

March 30, 2010 at 11:02 pm

Posted in .NET 4.0, ETW

Tagged with .NET 4.0, ETW, PFX, TPL

Undocumented Event Tracing for Windows (ETW) providers in .NET 4.0 (BCL)

with one comment

Continuing with my explorations in ETW I happened notice that there are few undocumented ETW providers within the .NET 4.0 BCL. These are in the mscorlib.dll and they are

System.Collections.Concurrent.CDSCollectionETWBCLProvider : This is used by the ConcurrentBag , ConcurrentDictionary and the ConcurrentStack
System.Diagnostics.Eventing.FrameworkEventSource : This is used by System.Resources.ResourceManager
System.Threading.CdsSyncEtwBCLProvider : This is used by SpinWait, SpinLock and Barrier
System.Threading.TplEtwProvider & System.Linq.Parallel.PlinqEtwProvider : This is already documented here

To get list of ETW providers on an application ,get pid of the application and then issue this command


logman query providers -pid 1853452

The outcome of the above command is

For example .from above result ,the provider 2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5 belongs to TplEtwProvider , it is not a registered with a man file. These providers that i have mentioned above are specifically useful in diagnosing parallel applications. In the forth coming posts I will demonstrate how we can leverage ETW in understanding parallel applications performance.

Written by Naveen

March 27, 2010 at 11:48 pm

Posted in .NET 4.0, ETW

Tagged with ETW, xperf

Track down DLL loading in .NET using Event Tracing for Windows (ETW)

with 3 comments

Sometime ago I was doing some performance work for start-up of an .NET application ,and it so happened the CLR Perf team had blogged specifically about this. One of critical pieces to start-up speed is loading only necessary Dll’s. And loading these Dll’s on demand reduces the memory consumption, reduces look-up ,which could potentially save few hundred milliseconds based on different configuration. I am going to be using the same example as the CLR perf team had used. Here is the sample code.


using System.IO;
using System.Xml.Linq;

internal class Program
{
 private static void ProcessArgs(string[] args)
 {
 if (args.Length == 2 && args[0] == "text")
 File.WriteAllText(args[1], "Here is the data I am writing");
 else if (args.Length == 2 && args[0] == "xml")
 {
 var myXml = new XElement("data", "Here is the data I am writing");
 myXml.Save(args[1]);
 }
 }
 private static int Main(string[] args)
 {
 ProcessArgs(args);

 return 0;
 }
}

In this sample code we wouldn’t want to load System.Xml.Linq.dll to be loaded if the command line option was set to “text”. In the past to diagnose the load of System.Xml.Linq.dll I would have to attached the windbg and set a break-point on load of System.Xml.Linq using sxe:ld and then get the call-stack using !clrstack. With the ETW it is as simple starting and stopping a trace.


xperf -start clr -on e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x400010dc:0xffffffff -f clrevents.etl

This is the clr guid for etw “e13c0d23-ccbc-4e12-931b-d9cc2eee27e4:0x400010dc” and the keyword is 0x400010dc, which is for Fusion,Loader,Jit and Stackwalk combined together. So we are essentially asking clr to log events for Jit,Loader, Fusion and as well as stack-walk information.

After issuing the command start the console app

EtwProvider.exe text text

Stop the trace

xperf -stop clr

And here is the sample output from the etl file

Opcode name	MethodNameSpace	MethodName	MethodSignature
JittingStarted	“Program”	“ProcessArgs”	“void (class System.String[])”
Walk	[0x719c9909 : 0x719c9a8d]
AssemblyLoad	“System.Xml.Linq; Version=4.0.0.0; Culture=neutral; PublicKeyToken=b77a5c561934e089″	15
Walk	[0x719c9909 : 0x719c9a8d]

The above table represents the ordered trace where the Jit compiler is trying to compile ProcessArgs method ,which is in-turn causing the System.Xml.Linq.dll to be loaded. The reason for doing this is because the Jit compiler is not aware of which code path would be taken and that’s the reason for loading the dll even though command line was text and not xml.

The idea behind this post is not show how the dll loading can be avoided, this has been already demonstrated in the CLR blog. I am trying to demonstrate how we can leverage ETW tracing , which is non-invasive and we don’t have to jump though hoops to get the information.

Written by Naveen

March 24, 2010 at 1:26 am

Posted in .NET 4.0, ETW

Tagged with .NET 4.0, clr.dll, ETW, loader, xperf

Naveen's Blog

Archive for the ‘.NET 4.0’ Category

Downloading PDC10 videos using the new async feature

Debugging .Net Framework 4.0 without source code using windbg

Exploring UnhandledException in .NET and Watson buckets

Exploring SOSEX and Windbg to debug .NET 4.0

Exploring internal implementation of C# 4.0 Default and Optional arguments

Get Managed and Native Call Stacks from Event Tracing for Windows (ETW)

Exploring Event Tracing for Windows (ETW) within Task Parallel Library (TPL) using PerfMonitor

Undocumented Event Tracing for Windows (ETW) providers in .NET 4.0 (BCL)

Track down DLL loading in .NET using Event Tracing for Windows (ETW)

Case Study: Tracking .NET Exceptions with Event Tracing for Windows (ETW)

Pages

Search

Recent Posts

Top Posts

Naveen Tweet’s

Categories

Archives

Follow “Naveen's Blog”

Archive for the ‘.NET 4.0’ Category

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Share this:

Like this:

Pages

Search

Recent Posts

Top Posts

Categories

Archives

Follow “Naveen's Blog”