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


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.

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


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

  1. System.Collections.Concurrent.CDSCollectionETWBCLProvider : This is used by the ConcurrentBag , ConcurrentDictionary and the ConcurrentStack
  2. System.Diagnostics.Eventing.FrameworkEventSource : This is used by System.Resources.ResourceManager
  3. System.Threading.CdsSyncEtwBCLProvider : This is used by SpinWait, SpinLock and Barrier
  4. 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.

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


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.

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


In the past I have debugged customers code ,where the code throws tons of exceptions. This is a huge performance problem. Tess has amazing post on why throwing ton of exceptions are bad. To debug this I had to resort to using Windbg and  getting call stacks of exceptions. The biggest issue was ,there were thousands of exceptions thrown from different points which made debugging extremely hard. I couldn’t just break-point based on exception type because the same type of exception were thrown from n different points. Windbg would  peg cpu for getting call stacks for each of these exceptions. I so wish I had ETW when I had to figure out those exceptions. FYI all these exception were handled and that made even harder.

Now with CLR 4.0 having ETW, this is so much easy to diagnose the same problem. Here is the sample code that I am going to use.

using System;
using System.Threading;
class Program {
 private void ProcessArgs() {
 for (int i = 0; i < 20; i++) {
 try {
 throw new ArgumentNullException(i.ToString());
 }
 catch (Exception e) {
 Console.WriteLine(e);
 }
 }
 }
 private static void Main(string[] args) {
 var p = new Program();
 ThreadPool.QueueUserWorkItem((x) => p.ProcessArgs());
 ThreadPool.QueueUserWorkItem((x) => p.ThrowNullReference());
 Console.Read();
 }
 private void ThrowNullReference() {
 for (int i = 0; i < 20; i++) {
 try {
 throw new NullReferenceException(i.ToString());
 }
 catch (Exception ex) {
 Console.WriteLine(ex);
 }
 }
 }
}

Here is the code to trace CLR exceptions

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

After which I started the console application. Then stopped the etw and then dumped the contents to a csv file.

xperf -stop clr
xperf -i clrevents.etl -o clrexceptions.csv

Here is a sample exception trace from ETW

Microsoft-Windows-DotNETRuntime/Exception /Start ,    3856446,        "Unknown" (27776),      30268,   0, , , , , "System.ArgumentNullException", "Value cannot be null.", 0x00480270, 0x80004003, 16, 15

Attached the application to Windbg. With in the etw trace is the Instruction Pointer where the exception was raised . And for above example it was raised at 0x00480270.

Issued a command to disassemble the sourcecode at the specific instruction pointer within Windbg

!u  0x00480270 

And here is the output from the above command

0:007> !u  0x00480270
Normal JIT generated code
Program.ProcessArgs()
Begin 00480200, size ad

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 4:
00480200 55              push    ebp
00480201 8bec            mov     ebp,esp
00480203 57              push    edi
00480204 56              push    esi
00480205 53              push    ebx
00480206 83ec30          sub     esp,30h
00480209 8bf1            mov     esi,ecx
0048020b 8d7dd8          lea     edi,[ebp-28h]
0048020e b906000000      mov     ecx,6
00480213 33c0            xor     eax,eax
00480215 f3ab            rep stos dword ptr es:[edi]
00480217 8bce            mov     ecx,esi
00480219 33c0            xor     eax,eax
0048021b 8945e8          mov     dword ptr [ebp-18h],eax
0048021e 894ddc          mov     dword ptr [ebp-24h],ecx
00480221 833d3c31310000  cmp     dword ptr ds:[31313Ch],0
00480228 7405            je      0048022f
0048022a e8464be768      call    clr!JIT_DbgIsJustMyCode (692f4d75)
0048022f 33d2            xor     edx,edx
00480231 8955d0          mov     dword ptr [ebp-30h],edx
00480234 c745d400000000  mov     dword ptr [ebp-2Ch],0
0048023b 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 5:
0048023c 33d2            xor     edx,edx
0048023e 8955d8          mov     dword ptr [ebp-28h],edx
00480241 90              nop
00480242 eb4d            jmp     00480291
00480244 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 6:
00480245 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 7:
00480246 8d4dd8          lea     ecx,[ebp-28h]
00480249 e882330568      call    mscorlib_ni+0x2635d0 (684d35d0) (System.Int32.ToString(), mdToken: 06000cd4)
0048024e 8945cc          mov     dword ptr [ebp-34h],eax
00480251 b98c475968      mov     ecx,offset mscorlib_ni+0x32478c (6859478c) (MT: System.ArgumentNullException)
00480256 e8c51de8ff      call    00302020 (JitHelp: CORINFO_HELP_NEWSFAST)
0048025b 8945c8          mov     dword ptr [ebp-38h],eax
0048025e 8b55cc          mov     edx,dword ptr [ebp-34h]
00480261 8b4dc8          mov     ecx,dword ptr [ebp-38h]
00480264 e8b7bbfc67      call    mscorlib_ni+0x1dbe20 (6844be20) (System.ArgumentNullException..ctor(System.String), mdToken: 06000795)
00480269 8b4dc8          mov     ecx,dword ptr [ebp-38h]
0048026c e835ffd668      call    clr!IL_Throw (691f01a6)

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 9:
00480271 8945c4          mov     dword ptr [ebp-3Ch],eax
00480274 8b45c4          mov     eax,dword ptr [ebp-3Ch]
00480277 8945d0          mov     dword ptr [ebp-30h],eax
0048027a 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 10:
0048027b 8b4dd0          mov     ecx,dword ptr [ebp-30h]
0048027e e841416268      call    mscorlib_ni+0x8343c4 (68aa43c4) (System.Console.WriteLine(System.Object), mdToken: 06000918)
00480283 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 11:
00480284 90              nop
00480285 e8ae1fbc68      call    clr!JIT_EndCatch (69042238)
0048028a eb00            jmp     0048028c
0048028c 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 12:
0048028d 90              nop

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 5:
0048028e ff45d8          inc     dword ptr [ebp-28h]
00480291 837dd814        cmp     dword ptr [ebp-28h],14h
00480295 0f9cc0          setl    al
00480298 0fb6c0          movzx   eax,al
0048029b 8945d4          mov     dword ptr [ebp-2Ch],eax
0048029e 837dd400        cmp     dword ptr [ebp-2Ch],0
004802a2 75a0            jne     00480244

C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs @ 13:
004802a4 90              nop
004802a5 8d65f4          lea     esp,[ebp-0Ch]
004802a8 5b              pop     ebx
004802a9 5e              pop     esi
004802aa 5f              pop     edi
004802ab 5d              pop     ebp
004802ac c3              ret

Now we see the call stacks of where the exception was raised, even without hooking for exceptions within the debugger.  The key reason for doing this is, for this specific case study I could have got all the unique Instruction pointers from the trace and just take one memory dump.With this I could have managed to get the call stacks all the exceptions. This would be non-invasive, which would save us lot of time and effort.

With ETW we can get all the exception even the ones that were handled, along with Instruction Pointer which helps us trace the root cause of the issue.

With this in hand ,we could easily write a small automation tool to extract the Instruction Pointer from the trace and then disassemble the source code and get the call stack.

All of this can be done on .NET 4.0 (clr.dll) and Silverlight (coreclr.dll).

In my forth coming posts ,I will share few more cool things that can be done with ETW.

Get GC Information in Silverlight using ETW


The coreclr.dll (Silverlight stripped down clr)  is a black box with respect to diagnostics information, until we had ETW. The only way was to get internal diagnostics information was using Windbg. But the idea is to get non-invasive diagnostic information. One of the most common performance issue in managed code, is the Garbage Collector. Either the application could be running out of memory, the percentage time spent on GC could be high and to address these GC performance issues in the desktop CLR, we would usually trouble shoot by observing at the performance counters, but this is not available in Silverlight. With the RIA , lot more work is done on the client and having  ETW/Xperf in our toolbox will certainly help us.

The coreclr.dll as well as the clr.dll provides ETW information, So what ever I am mentioning today is applicable to both Silverlight and the .NET framework 4.0. I am going to be profiling http://discoverbingmaps.com. FYI in this post I am going to be focusing only on the GC when collecting ETW traces.

Here is my original post on how to use ETW along with Silverlight. I am using xperf because I am running this out of windows 7. If you are using Windows XP then ,you could use Logman to record ETW traces.

Whenever I am troubleshooting perf issue I usually look for this

image

And in Silverlight we would have to get it from ETW. Here is the command

xperf -start clr -on Microsoft-Windows-DotNETRuntimeRundown:0x00000001:0x4 –f “clr GC.etl”

In the above command we are instructing xperf to start monitoring using the “clr” on the provider “Microsoft-Windows-DotNETRuntimeRundown”. The keyword within the provider which we want to log is “0x00000001” (which is for getting GC information) and “0x4” is the level of tracing which is Informational.

After starting the trace, I browsed the bing maps and then stopped the tracing and converted it to csv file

Xperf –stop clr
xperf  -i "CLR GC.etl" -o CLRGC.csv

Sample output of the HeapStats from the csv file

Microsoft-Windows-DotNETRuntime/GC /HeapStats,132775836,"Unknown" (5028),4424,0,0x0000000000a64d7c, 0x000000000000002c,0x0000000000000038,0x0000000000000024, 0x0000000002fca294 , 0x0000000002fc6048, 0x0000000003248478, 0x0000000001a07310, 0x0000000000000000,0,0,0,0,77

Sample output of GC Start / Stop

Microsoft-Windows-DotNETRuntime/GC /Start,6337636, "Unknown" (5028),4424,0,22,0,    0,    0,    77
Microsoft-Windows-DotNETRuntime/GC /Stop,     6342813,"Unknown" (5028),    4424,    0,    22,    0,    77

And here is the GC stats from the csv file after parsing it

Number of Gen 0:	 21
Number of Gen 1:	 26
Number of Gen 2:	 33
Collection Reason Small Object :	 21
Collection Reason Induced :	 14
Collection Reason LOH :	 1
Collection Reason Out Of Space (Small Objects) :	 3
Total Collections: 	  101
Total Time spent on GC: 	4087711
Generation Size 0:	10898812
Total Promoted Size 0:	44
Generation Size 2:	50111124
Total Promoted Size 2:	50094152
Generation Size 3:	52724856
Total Promoted Size 3:	27292432
Finalization Promoted Size 3:	0
Finalization Promoted count:	 0
Pinned object count:	 0
Sink block count:	 0
GC handle count:	 0

To get this ,I hacked a simple C# code to get it from csv file. This is sample code and by no means clean / perfect.

public static int Dec(string hex)
 {
 var x1 = hex.Remove(0,3);
 return int.Parse(x1,System.Globalization.NumberStyles.AllowHexSpecifier);
 }
 void Main()
{
 var map = new Dictionary<int,string>() { {0,"Small Object "},{1,"Induced "},{2,"Low Memory "},{3,"Empty "},{4,"LOH "},{5, "Out Of Space (Small Objects) "},{6,"Out of space LOH "} };

 var gclines = from line in File.ReadAllLines(@"C:\temp\clrgc.csv")
 where line.Contains("Microsoft-Windows-DotNETRuntime/GC /Start") ||
 line.Contains("Microsoft-Windows-DotNETRuntime/GC /Stop")
 select line;

 var heapStats = (from line in File.ReadAllLines(@"C:\temp\clrgc.csv")
 where line.Contains("Microsoft-Windows-DotNETRuntime/GC /HeapStats")
 select line).Last();

 var GCInfo = ((from col in gclines
 let cols = col.Split(new char[] {','})
 select   new {Name = cols[0],Time = cols[1], Count= cols[9], Depth = cols[10],Reason = cols[11]}));

 var totalCollections = GCInfo.ToList().Skip(2).OrderByDescending (g => Convert.ToInt32(g.Count)).ElementAt(1).Count;

 var collectioncount = (from y in GCInfo.Skip(2)
 group y by y.Depth into g
 select new {Gen = g.Key, Count = (g.Count()) /2});

 var collectionReasoncount = (from y in GCInfo.Skip(2)
 where y.Name.Contains("Microsoft-Windows-DotNETRuntime/GC /Start")
 group y by y.Reason into g
 select new {Reason = map[Convert.ToInt32(g.Key)], Count = (g.Count()) /2});

 var totalTimeSpentONGC = (from y in GCInfo.Skip(2)
 group y by y.Name into g
 select g.Select(g1 => Convert.ToInt32(g1.Time)));

 var start = totalTimeSpentONGC.First();
 var end = totalTimeSpentONGC.ElementAt(1);

 var timespentOnGC = start.Zip(end,(x,y) => y-x).Aggregate(0,(a,b) => a +b);

 collectioncount.ToList().ForEach(x => Console.WriteLine("Number of Gen"+x.Gen +":\t " + x.Count) );
 collectionReasoncount.ToList().ForEach(x => Console.WriteLine("Collection Reason " +x.Reason +":\t " + x.Count) );
 Console.WriteLine("Total Collections: \t "+ totalCollections );
 Console.WriteLine("Total Time spent on GC: \t" + timespentOnGC);
 var stats = heapStats.Split(new [] {','});
 Console.WriteLine("Generation Size 0:\t" +Dec(stats.ElementAt(9)));
 Console.WriteLine("Total Promoted Size 0:\t" +Dec(stats.ElementAt(10)));
 Console.WriteLine("Generation Size 2:\t" +Dec(stats.ElementAt(13)));
 Console.WriteLine("Total Promoted Size 2:\t" +Dec(stats.ElementAt(14)));
 Console.WriteLine("Generation Size 3:\t" +Dec(stats.ElementAt(15)));
 Console.WriteLine("Total Promoted Size 3:\t" +Dec(stats.ElementAt(16)));
 Console.WriteLine("Finalization Promoted Size 3:\t" +Dec(stats.ElementAt(17)));
 Console.WriteLine("Finalization Promoted count:\t" +stats.ElementAt(18));
 Console.WriteLine("Pinned object count:\t" +stats.ElementAt(19));
 Console.WriteLine("Sink block count:\t" +stats.ElementAt(20));
 Console.WriteLine("GC handle count:\t" +stats.ElementAt(21));
}

This is just a sample of what can be done with ETW and CLR. There are more cool things to come.

Using .NET 4.0 Event Tracing for Windows (ETW) along with application ETW


At last CLR 4.0 has started showing some love towards ETW. Like I mentioned before ETW is very useful in understanding what is happening on the entire system, along with your application. Today I am going to be demonstrating a simple application, which is going to allocate large arrays 100 times. Along with the allocation, it is also going to log via ETW each time it allocated. The reason is to see the object allocation within our code and GC collection from CLR in the same trace file. How cool it is to see one trace file, in which our application traces sandwiched along with CLR traces. The requirements to build this trace are Windows SDK 7.0, CLR 4.0 and OS should be Windows Vista or above. I am using Windows 7. Here is an existing blog entry for creating the trace xml file. I am going to reusing the same xml for this sample. This xml file or the “.man” file contains information for the ETW framework to understand. This xml can be hand-crafted or use ecmangen.exe (which is the best) to generate. The ecmangen .exe has an inbuilt help, so I don’t want to repeat the same. The next step in the process is to use MC.exe which is the Message Compiler. FYI all the commands are executed from windows sdk command prompt, which has path set to all the tools.

mc.exe Simple.Manifest.xml

This command generates 3 files as output

1. Simple.Manifest.h

2. Simple.Manifest.rc

3. Simple.ManifestTEMP.BIN

The next command would generate the .cs file for writing the events. To do this we could use mc.exe

mc -css ETW Simple.Manifest.xml

So we are essentially instructing the tool to create a static class with static methods along with the defined namespace as ETW. This would generate a .cs file and update the cs file, with a simple static void Main and here is the code after updating the cs file

//---------------------------------------------------------------------
//
//
//     Generated by Message Compiler (mc.exe)
//
//     Copyright (c) Microsoft Corporation. All Rights Reserved.
//
//     Changes to this file may cause incorrect behavior and will be lost if
//     the code is regenerated.
//
//---------------------------------------------------------------------
namespace ETW
{
using System;
using System.Collections.Generic;
using System.Text;
using System.Diagnostics;
using System.Diagnostics.Eventing;
using Microsoft.Win32;
using System.Runtime.InteropServices;
using System.Security.Principal;
    public static class SampleProvider
    {
        //
        // Provider SampleProvider Event Count 1
        //
        static void Main(string[] args)
        {
            for (int i = 0; i < 100; i++)
            {
                var obj = new object[85001];
                ETW.SampleProvider.EventWriteSampleEvent("Allocating object" , i);
            }
        }
        private static EventProviderVersionTwo m_provider = new EventProviderVersionTwo(new Guid("d9b453b9-6230-486c-8dec-c7c5a2230d04"));
        //
        // Task :  eventGUIDs
        //
        private static Guid SampleTaskId = new Guid("9b0655be-219f-439e-9439-b604bd822e22");
        //
        // Event Descriptors
        //
        private static EventDescriptor SampleEvent;
        static SampleProvider()
        {
            unchecked
            {
                SampleEvent = new EventDescriptor(0x3e9, 0x1, 0x10, 0x4, 0xa, 0x1, (long)0x8000000000000001);
            }
        }
        //
        // Event method for SampleEvent
        //
        public static bool EventWriteSampleEvent(string StringData, int IntegerData)
        {
            if (!m_provider.IsEnabled())
            {
                return true;
            }
            return m_provider.TemplateSimpleTemplate(ref SampleEvent, StringData, IntegerData);
        }
    }
    internal class EventProviderVersionTwo : EventProvider
    {
         internal EventProviderVersionTwo(Guid id)
                : base(id)
         {}
        [StructLayout(LayoutKind.Explicit, Size = 16)]
        private struct EventData
        {
            [FieldOffset(0)]
            internal UInt64 DataPointer;
            [FieldOffset(8)]
            internal uint Size;
            [FieldOffset(12)]
            internal int Reserved;
        }
        internal unsafe bool TemplateSimpleTemplate(
            ref EventDescriptor eventDescriptor,
            string StringData,
            int IntegerData
            )
       {
           int argumentCount = 2;
            bool status = true;
            if (IsEnabled(eventDescriptor.Level, eventDescriptor.Keywords))
            {
               byte* userData = stackalloc byte[sizeof(EventData) * argumentCount];
                EventData* userDataPtr = (EventData*)userData;
                userDataPtr[0].Size = (uint)(StringData.Length + 1)*sizeof(char);
                userDataPtr[1].DataPointer = (UInt64)(&IntegerData);
                userDataPtr[1].Size = (uint)(sizeof(int)  );
                fixed (char* a0 = StringData)
                {
                    userDataPtr[0].DataPointer = (ulong)a0;
                    status = WriteEvent(ref eventDescriptor, argumentCount, (IntPtr)(userData));
                }
            }
            return status;
        }
    }
}

And also here is the link for downloading the cs file. Within the main method I am allocating large array which should trigger GC and after which I am logging via ETW. The next step is to compile the rc in to res using

RC Simple.Manifest.rc

The next step is to embed the generate resource file into the exe

c:\Windows\Microsoft.NET\Framework64\v4.0.30128\csc.exe /out:EtwProvider.exe /win32res:simple.manifest.res Simple.Manifest.cs /unsafe

Make sure that you use the CLR 4.0 CSC.exe to compile. After compiling update the Simple.Manifest.xml to the location of the exe in the attributes resourceFileName and messageFileName

<provider name="SampleProvider" message="$(string.ProviderMessage)" guid="{D9B453B9-6230-486C-8DEC-C7C5A2230D04}" symbol="SampleProvider" resourceFileName="f:\downloads\EtwProvider.exe" messageFileName="f:\downloads\EtwProvider.exe"

After which we would have to register the xml file with OS.

WEVTUTIL im Simple.Manifest.xml

FYI if the path of the exe within the xml is not accessible or is not a valid then the above command would throw a warning. So now we are done registering and compiling the code , the next step is to subscribe to these events

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

The above command starts subscribing to clr event traces. I am using the clr etw guid to capture the events. And the events are captured into the clrevents.etl Next we capture events from our application

xperf -start usersession -on "SampleProvider" -f usersession.etl

So we are telling windows to capture events for clr as well as our application. So in the above command we are using the provider name “SampleProvider” instead of guid.

EtwProvider.exe

Then run the application. After running the application , the next step is to stop these traces.

xperf -stop clr
xperf -stop usersession

After stopping we would want to merge the two different traces into one single trace file.

xperf -merge clrevents.etl usersession.etl mergedexample.etl
xperf mergedexample.etl

We should see something like this make sure the sample provider and Microsoft-Windows-DotNETRuntime is checked in the xperf tool

Then zoom in to the section where there are events for sample provider along with CLR events and then right click and choose summary table option.

We should see something like this. Now expand the tree for dotnet as well as the Sample provider. To merge them in to one use the column chooser and uncheck the provider name. It is essentially instructing the xperf not to group by the provider.

Now our custom trace is merged with .NET traces and we can see GC happening when we are allocating objects. This is really cool, so we should be able to figure out what is happening in the runtime when we are doing certain things within the code. Till this day CLR / .NET was always a black box and now it is not any more. I am sure going forward it would only be better. In the forth coming posts I will explain how ETW can help us troubleshoot most of the issues in an non-invasive manner.

Undocumented Silverlight Feature – ETW Tracing


Event Tracing for Windows is tracing mechanism built into windows kernel. It is like log file for windows, but way cool and can log thousands events per second, with very less CPU utilization. From windows vista onwards, we can have windows ETW combined with our application tracing. It would be one trace file which would contain information about windows as well as our application, so it is easy to diagnose and figure what is happening in the OS combined with our application. Today I am not going be discussing about how to do this. I will write about in another post.  This post is going to be about how to have ETW tracing from Silverlight, which is not documented. I am using Silverlight 4.0 and I haven’t checked in another vesion.

I was looking to in to coreclr.dll inside the Windbg. FYI coreclr.dll is the runtime for Silverlight. And I happened to notice ETW. I used the command


x coreclr!etw*

0:026> x coreclr!etw*

6574af13 coreclr!ETW::MethodLog::MethodJitting = <no type information>

657434e5 coreclr!ETW::MethodLog::MethodJitted = <no type information>

6588810e coreclr!ETW::LoaderLog::CollectibleLoaderAllocatorUnload = <no type information>

65886240 coreclr!ETW::MethodLog::SendHelperEvent = <no type information>

6588327f coreclr!ETW::SamplingLog::SaveCurrentStack = <no type information>

6588752d coreclr!ETW::EnumerationLog::StartRundown = <no type information>

65887f30 coreclr!EtwCallback = <no type information>

65886e10 coreclr!ETW::EnumerationLog::IterateAssembly = <no type information>

6578ad0c coreclr!ETW::MethodLog::MethodRestored = <no type information>

65886450 coreclr!ETW::MethodLog::StubInitialized = <no type information>

65886729 coreclr!ETW::LoaderLog::SendModuleEvent = <no type information>

65884d0a coreclr!ETW::EnumerationLog::SendThreadRundownEvent = <no type information>

65884960 coreclr!ETW::LoaderLog::SendDomainEvent = <no type information>

65737ac1 coreclr!ETW::ExceptionLog::ExceptionThrown = <no type information>

658862e6 coreclr!ETW::MethodLog::SendEventsForNgenMethods = <no type information>

658837b0 coreclr!etwStackSupportedEvents = <no type information>

65887a60 coreclr!ETW::EnumerationLog::EndRundown = <no type information>

657a7b57 coreclr!ETW::MethodLog::StubsInitialized = <no type information>

657bb514 coreclr!ETW::CEtwTracer::Register = <no type information>

6588363e coreclr!EtwCallout = <no type information>

656de72b coreclr!ETWTraceStartup::ETWTraceStartup = <no type information>

658865c2 coreclr!ETW::MethodLog::DynamicMethodDestroyed = <no type information>

658853e8 coreclr!ETW::MethodLog::SendMethodEvent = <no type information>

65808659 coreclr!ETW::EnumerationLog::ProcessShutdown = <no type information>

657a67b0 coreclr!ETW::InfoLog::RuntimeInformation = <no type information>

65884e23 coreclr!ETW::LoaderLog::SendAssemblyEvent = <no type information>

65885198 coreclr!ETW::MethodLog::SendMethodJitStartEvent = <no type information>

658872ff coreclr!ETW::EnumerationLog::IterateCollectibleLoaderAllocator = <no type information>

658831d5 coreclr!ETW::SamplingLog::Append = <no type information>

6588840d coreclr!ETW::LoaderLog::ModuleLoad = <no type information>

656de705 coreclr!ETWTraceStartup::StartupTraceEvent = <no type information>

6588744b coreclr!ETW::EnumerationLog::EnumerationHelper = <no type information>

656fa2f8 coreclr!ETW::MethodLog::MethodTableRestored = <no type information>

65886f78 coreclr!ETW::EnumerationLog::IterateModule = <no type information>

656d11a4 coreclr!ETW::SecurityLog::StrongNameVerificationStart = <no type information>

658847f3 coreclr!ETW::GCLog::GCSettingsEvent = <no type information>

So this is cool we can get ETW tracing from Silverlight regarding loader, GC, threading, ThreadPool. But one thing I couldn’t find was a “.man” file like “CLR-ETW.man” for CLR 4.0. This was disappointing. The next thing to do was fired up .NET 4.0, attached to the debugger and issues the command x clr!ETW*.And it was same as the coreclr.dll output above.So the API's being the same I guessed I could use the clr-etw.man for tracing Silverlight. Then the next thing to do is try tracing Silverlight using CLR-ETW.man. FYI I am using Windows 7 and this will work only from Windows Vista onwards. Make sure the CLR-ETW is registered. To register issue the command (clr-etw.man would be .NET 4.0 directory)


wevtutil im CLR-ETW.man

And to check if the provider is installed issue the command


xperf -providers I | Findstr ".NET"

And the output should be something like this

C:\>xperf -providers I | Findstr ".NET"

a669021c-c450-4609-a035-5af59af4df18     : Microsoft-Windows-DotNETRuntimeRundown

aff081fe-0247-4275-9c4e-021f3dc1da35      : ASP.NET Events

e13c0d23-ccbc-4e12-931b-d9cc2eee27e4    : .NETCommon Language Runtime

e13c0d23-ccbc-4e12-931b-d9cc2eee27e4    : Microsoft-Windows-DotNETRuntime

Try and close all .NET applications like VS2010, so that you don’t get traces from VS2010. From the command line issue the command


xperf -start usersession -on ".NET Common Language Runtime" -f usersession.etl

Start IE and browse a Silverlight site and then stop the trace


xperf -stop usersession

And to view the output of the etl file, issue the command


xperf usersession.etl

There we go now, we are able to see coreclr ETW tracing. From the above picture we can see information like assembly load, module load.  This can be used for GC, Exception, threading etc. So the next time someone tells the Silverlight site is slow on their box, you can ask them to run an etw trace and you would be able to see what is happening on their system.

Piracy in .NET /Silverlight Code – Part 1 – Even when the code is obfuscated


This is going to be a series of posts where I am going to demonstrating how someone with little advanced knowledge in .NET can hack in to the code, and circumventing licensing logic. I know there are other ways to prevent this ,which I am not going to be discussing about.

The usual assumption is that, if the code is obfuscated and signed , then it is close to impossible for someone to hack in to the code because the method names and variables are jumbled up, which would prevent someone from figuring what is happening.

In this post I am going to demonstrate a simple application which would prevent the user from updating the DataGrid because the user had downloaded only a trial version of the software. The software was supposed to disable grid and prevent the consumer from adding or updating the existing data, in a trial version. This was customer case, whom I helped in figuring out the vulnerability.

Here is the list of things the software did to prevent users from not accessing features that they were not entitled to

  1. Obfuscated the code, that prevented the code from being disassembled.
  2. The code that validated the consumers role either paid / trial alone was maintained in a separate assembly .So that for trial consumer’s, assembly version always returned false, for key features and for the paid subscribers got the assembly version that would return true. The organization assumption was ,by not even having the assembly ,trial users would never be able to circumvent the licensing logic. The customer could not maintain two versions of entire software, one for the trial another one paid because of the cost involved in maintenance and that’s the driving factor behind having a separate assembly.
  3. The code was signed and this prevented the users from hacking into the code and changing the code.

So here is code for figuring out the user role

public interface ICustomer{
bool HasAccess();}

And the trial assembly version code for figuring the role had

public class TrialCustomer : ICustomer {
public bool HasAccess() {
return false;
}
}

And here is the code that actually use the above code

private void Button1Click(object sender, EventArgs e)
{
if (!this.customer.HasAccess()) {
MessageBox.Show("Available only for paid customer");
}
else {
this.dataGridView1.Enabled = true;
}
}

So the idea behind this was, the trial version user would always get false as response, and would never be able to hack, because consumer does not even have library that would return true.

So I was asked to check for vulnerabilities. The first step was to disassemble the code using reflector and you can imagine the code had all weird names because of obfuscation.

The next step was to run the application and check when I get a dialog box for “Available only for paid customer”. The reason behind this was to get a callstack ,because all the methods names are jumbled and I didn’t know where to start.

When the messagebox popped up I attached the application to windbg and here is callstack

0:000> !clrstack

OS Thread Id: 0x4850 (0)

Child SP IP       Call Site

004ce758 752b438d [InlinedCallFrame: 004ce758]

004ce754 636308ec DomainBoundILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef, System.String, System.String, Int32)

004ce758 636f4a53 [InlinedCallFrame: 004ce758] System.Windows.Forms.SafeNativeMethods.MessageBox(System.Runtime.InteropServices.HandleRef, System.String, System.String, Int32)

004ce7ac 636f4a53 System.Windows.Forms.MessageBox.ShowCore(System.Windows.Forms.IWin32Window, System.String, System.String, System.Windows.Forms.MessageBoxButtons, System.Windows.Forms.MessageBoxIcon, System.Windows.Forms.MessageBoxDefaultButton, System.Windows.Forms.MessageBoxOptions, Boolean)

004ce7b0 001b0513 [InlinedCallFrame: 004ce7b0]

004ce84c 001b0513 c.a(System.Object, System.EventArgs)

004ce85c 630bfd6c System.Windows.Forms.Control.OnClick(System.EventArgs)

004ce874 630beb1e System.Windows.Forms.Button.OnClick(System.EventArgs)

004ce88c 636574b8 System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)

004ce8a8 63629639 System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)

004ce93c 639d1a87 System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)

004ce940 639f141d [InlinedCallFrame: 004ce940]

004ce994 639f141d System.Windows.Forms.ButtonBase.WndProc(System.Windows.Forms.Message ByRef)

004ce9d8 6312f8e0 System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)

004ce9e4 630ce493 System.Windows.Forms.Control+ControlNativeWindow.OnMessage(System.Windows.Forms.Message ByRef)

004ce9ec 630ce411 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)

004cea00 630ce356 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)

004ceba4 007a09e5 [InlinedCallFrame: 004ceba4]

004ceba0 631347dc DomainBoundILStubClass.IL_STUB_PInvoke(MSG ByRef)

004ceba4 630de59f [InlinedCallFrame: 004ceba4] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)

004cebe8 630de59f System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(IntPtr, Int32, Int32)

004cebec 630de1cc [InlinedCallFrame: 004cebec]

004cec84 630de1cc System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)

004cecdc 630de021 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)

004ced0c 630c5ecd System.Windows.Forms.Application.Run(System.Windows.Forms.Form)

004ced20 001b009a e.a()

004cef58 6d1d213b [GCFrame: 004cef58]

Notice that there is a method c.a(System.Object, System.EventArgs) on the top of stack the before the framework code. This was my starting point, and I looked up for it in the reflector

private void a(object A_0, EventArgs A_1)
{
if (!this.d.a())
{
MessageBox.Show("Available only for paid customer");
}
else
{
this.b.Enabled = true;
}
}

So my next step was to disassemble the call to “this.d.a()” and here is output from reflector

public class d : b
{
// Methods
public bool a()
{
return false;
}
}

And I was hoping there would be a class variable that I could update inside the debugger to activate the feature.  Like I mentioned I before ,I couldn’t update the assembly using ILASM or anything, because the assemblies were signed and there wasn’t any class variable to update. This assembly was for the trial version consumers which were supposed to always return false.

But there was one trick that I had. I could update the register on the function return, So what I mean is, when the function “a” is invoked by the button click to validate the consumer , I would update the return register  from false to true. By doing this my grid would be enabled and I circumvent the logic with the existing constraints.

So here are the steps to do it

  • So I looked for the type “d”  !dumpheap -type d, remember the TrialCustomer class  was the renamed  to d by obfuscator .
  • Go the method table as 00146b9c from the above command , using  the method table  I had to get the entry address for the function public bool a() because the buttonclick  was invoking the function.
  • I used the command  !dumpmt -md 00146b9c   to get the entry address for   d.a()  and here was the entry address 001b0540  .

0:005> !dumpmt -md 00146b9c

EEClass:      0020054c

Module:       00142e9c

Name:         d

mdToken:      02000009

File:         C:\Users\naveen\Documents\Visual Studio 2010\Projects\SecureApplication\bin\Debug\Dotfuscated\SecureApplication.exe

BaseSize:        0xc

ComponentSize:   0x0

Slots in VTable: 6

Number of IFaces in IFaceMap: 1

--------------------------------------

MethodDesc Table

Entry MethodDesc      JIT Name

649f5b34   64795750   PreJIT System.Object.ToString()

649c8be0   64795758   PreJIT System.Object.Equals(System.Object)

649c8af0   64795778   PreJIT System.Object.GetHashCode()

649e8aa0   6479578c   PreJIT System.Object.Finalize()

001b0540   00146b8c      JIT d.a()

0014c085   00146b94     NONE d..ctor()

  • The idea behind getting the address was to set a break-point on 001b0540  . I used the command bp 001b0540 . So when the break-point hits I would create another break-point for the function return, which  is stored in the register @esp  bp poi(@esp). So what bp poi(@esp) essentially means is,   create a break-point on the return of function  , it is almost like having a break-point on the last line inside a function within VS.NET.
  • So when the break-point hits for the function return ,the return value is stored in the @eax register and here is the output

0:000> g

Breakpoint 1 hit

eax=00000000 ebx=0230e6f8 ecx=0230cfcc edx=02328884 esi=0230ce7c edi=02328884

eip=001b04f2 esp=004ce8a0 ebp=004ce8a4 iopl=0         nv up ei pl zr na pe nc

cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246

001b04f2 85c0            test    eax,eax

Now the trick is to update the @eax register from 00000000 to 00000001, by doing this we are changing the value from false to true, using the command  “r eax=00000001” and here is the output after updating the register

0:000> r

eax=00000001 ebx=0230e6f8 ecx=0230cfcc edx=02328884 esi=0230ce7c edi=02328884

eip=001b04f2 esp=004ce8a0 ebp=004ce8a4 iopl=0         nv up ei pl zr na pe nc

cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246

001b04f2 85c0            test    eax,eax

Now we have managed to update return of the function, which in turn has let us update the grid ,which was supposed to be available only to the paid customers.

In the forth coming posts I will continue to post of few more things that I figured out.

Debugging .Net framework source code within Windbg


One the coolest thing Microsoft did was to release the .NET Framework source code. In this post, I am going to demonstrate, how we could have a break-point on the .NET framework source code by line numbers ,using Windbg ,very similar to doing in  VS.NET.

The first step towards doing this is to download .NET Framework Source Code and installing it on the local machine. The next step is to set the symbol path environment variable. My _NT_SYMBOL_PATH is set to


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

Setting the correct symbol path is important to download symbols from MS.

Here is the source code that I would be using to demonstrate this


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();
 }
 }
}

I am going to demonstrate the same thing using multiple versions of debugger. The first one that I am going to demonstrate is using  Windows Debugger Version 6.12.0002.633 X86 which is the latest version.

Launched the exe within windbg and opened the source code WebRequest.cs and Program.cs withing Windbg.

The WebRequest.cs is the source code that was downloaded from MS Reference Source code and Program.cs is the above sample code.

Then issued the command, to be notified when mscorlib is loaded

sxe ld:mscorlib

And here is the output from the above command

ModLoad: 53fd0000 54ac8000   C:\Windows\assembly\NativeImages_v2.0.50727_32\mscorlib\8c1770d45c63cf5c462eeb945ef9aa5d\mscorlib.ni.dll
eax=00000000 ebx=00000000 ecx=00000000 edx=00000000 esi=7efdd000 edi=0040eaf4
eip=7723fc02 esp=0040e9c8 ebp=0040ea1c iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
ntdll!ZwMapViewOfSection+0x12:
7723fc02 83c404          add     esp,4

then issued the following commands to load by sos, sosex and set break-points

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

So with the above command I am requesting for a break-point on the method  System.Net.WebRequest.Create using symbol (!mbm). I am issuing the command !mbm ,just so that sosex can hook up with CLR for getting notifications on JIT. Without this I was unable to set break-point on source code using line numbers. The next command !mbp WebRequest.cs 98 means, have a break-point on the line number 98  in the WebRequest.cs file . The line 98 contents are "if (!useUriBase)"  .  I forgot to mention the .NET framework 4.0 source code is not released so I am using 3.5

Also make sure that the correct private pdb symbols are loaded for framework assemblies, and to verify that, issue the command "lme" and the output should contain something like this

0:000> lme
start    end        module name
013b0000 013b8000   ConsoleApplication1 C (private pdb symbols)  C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\bin\Debug\ConsoleApplication1.pdb
53fd0000 54ac8000   mscorlib_ni C (private pdb symbols)  d:\dev\symbols\mscorlib.pdb\F85F3DD0C7024D528B4C37F1ACF2123D1\mscorlib.pdb
58930000 590c9000   System_ni C (private pdb symbols)  d:\dev\symbols\System.pdb\97A082CB5BC64B30887253632D3901EE1\System.pdb

And here is the output after letting it run

Breakpoint 1 hit
eax=00000001 ebx=0040f37c ecx=0282c160 edx=00000000 esi=008ba398 edi=0282c160
eip=58dec8b7 esp=0040f32c ebp=0040f334 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
System_ni+0x4bc8b7:
58dec8b7 85ff

then issued the commands to see the list of break-points (managed and native)


!mbl

bl

and here is the output

0:000> !mbl
0 e : *!SYSTEM.NET.WEBREQUEST.CREATE ILOffset=0: pass=1 oneshot=false thread=ANY
System!System.Net.WebRequest.Create(Uri, bool)+0xfffffffe(IL)
0 e 58a71630
System!System.Net.WebRequest.Create(string)
1 e 58dec8b7
System!System.Net.WebRequest.Create(Uri)+0xfffffffe(IL)
2 e 58a71600
1 eu: WebRequest.cs, line 98: pass=1 oneshot=false thread=ANY
0:000> bl
0 e 58a71630     0001 (0001)  0:**** System_ni+0x141630
1 e 58dec8b7     0001 (0001)  0:**** System_ni+0x4bc8b7
2 e 58a71600     0001 (0001)  0:**** System_ni+0x141600

because Webrequest.Create has two overloads, sosex has set a break-point on both these methods and that's the reason we are seeing 3 break-points, instead of 2. And after issuing the "g" command for couple of hits for the Webrequest.Create , then comes the Breakpoint 3 hit. Voila ,we have the managed to set break-point on framework source code using line numbers and here is the output of  !mk command

Breakpoint 3 hit
eax=00000000 ebx=0014ecdc ecx=0282dde4 edx=00000000 esi=00000000 edi=00000000
eip=58a71650 esp=0014ec68 ebp=0014ec84 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
System_ni+0x141650:
58a71650 8bc7            mov     eax,edi
0:000> !mk
ESP      RetAddr
00:M 0014ec68 58a71650 System.Net.WebRequest.Create(System.Uri, Boolean)(+0x23 IL)(+0x0 Native) [f:\dd\ndp\fx\src\Net\System\Net\WebRequest.cs, @ 96,13]
01:M 0014ec8c 58dec8dd System.Net.WebRequest.Create(System.String)(+0x14 IL)(+0x26 Native)
02:M 0014ec9c 005000a9 Test.Program.Main(System.String[])(+0xc IL)(+0x18 Native) [C:\Users\naveen\Documents\Visual Studio 2010\Projects\ConsoleApplication1\Program.cs, @ 7,13]
03:U 0014ecb8 6cfb1b6c mscorwks!CallDescrWorker+0x33
04:U 0014ecc8 6cfc2209 mscorwks!CallDescrWorkerWithHandler+0xa3
05:U 0014ed48 6cfd6511 mscorwks!MethodDesc::CallDescr+0x19c
06:U 0014ee8c 6cfd6544 mscorwks!MethodDesc::CallTargetWorker+0x1f
07:U 0014eea8 6cfd6562 mscorwks!MethodDescCallSite::CallWithValueTypes_RetArgSlot+0x1a
08:U 0014eec0 6d040c45 mscorwks!ClassLoader::RunMain+0x223
09:U 0014f024 6d040b65 mscorwks!Assembly::ExecuteMainMethod+0xa6
0a:U 0014f28c 6d0410b5 mscorwks!SystemDomain::ExecuteMainMethod+0x456
0b:U 0014f75c 6d04129f mscorwks!ExecuteEXE+0x59
0c:U 0014f7ac 6d0411cf mscorwks!_CorExeMain+0x15c
0d:U 0014f7f4 73a461f0 mscoreei!_CorExeMain+0x38
0e:U 0014f800 74337f16 MSCOREE!ShellShim__CorExeMain+0x99
0f:U 0014f810 74334de3 MSCOREE!_CorExeMain_Exported+0x8
10:U 0014f818 74f73677 KERNEL32!BaseThreadInitThunk+0xe
11:U 0014f824 77259d72 ntdll!__RtlUserThreadStart+0x70
12:U 0014f864 77259d45 ntdll!_RtlUserThreadStart+0x1b

Notice on the top frame of the stack (00:M) we see source information. The advantage of this is, for example I can check the values of the local variable with in the function after certain calls ,which wouldn't  have been possible without jumping hoops. Here is the the output !mdv after the line breakpoint

0:000> !mdv
Frame 0x0: (System.Net.WebRequest.Create(System.Uri, Boolean)):
[A0]:requestUri:0x282d2fc (System.Uri)
[A1]:useUriBase:0x0 (System.Boolean)
[L0]:LookupUri:<?>
[L1]:Current:null (System.Net.WebRequestPrefixElement)
[L2]:Found:0x0 (System.Boolean)
[L3]:LookupLength:<?>
[L4]:prefixList:<?>
[L5]:i:<?>
[L6]:webRequest:<?>

And my next quest was to figure What if I could use the actual break-point on the source code directly instead of using sosex.  So chose program.cs and hit the F9 key on the second Console.WriteLine and the color changed to red

And here is the output o f the bl command

0:000> bl
0 e 58a71630     0001 (0001)  0:**** System_ni+0x141630
1 e 58dec8b7     0001 (0001)  0:**** System_ni+0x4bc8b7
2 e 58a71600     0001 (0001)  0:**** System_ni+0x141600
3 e 58a71650     0001 (0001)  0:**** System_ni+0x141650
4 e 013b0017     0001 (0001)  0:**** ConsoleApplication1!Main+0x17

Notice there is a new break-point 4.  But bad luck, when i let it run it didn't work and I had to clear the break-point 4 . It failed to create a break-point and here is the output

0:000> g
Unable to insert breakpoint 4 at 013b0017, Win32 error 0n998
"Invalid access to memory location."
bp4 at 013b0017 failed
WaitForEvent failed
eax=00000000 ebx=0014ecdc ecx=0282dde4 edx=00000000 esi=00000000 edi=00000000
eip=58a71650 esp=0014ec68 ebp=0014ec84 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000346
System_ni+0x141650:
58a71650 8bc7            mov     eax,edi

The next step was to debug the with the version of debugger which had capabilities to see managed call stacks, Windbg version 6.7.5.0. Did the same thing loaded up the exe and the Program.cs in to the debugger and set a break-point on mscorlib load using  " sxe ld:mscorlib" and then issued the command ".loadby sos mscorwks" ,".load sosex" and "!mbm System.Net.WebreRequest.Create". And the let it run, and to my surprise here is the integrated debugging experience, the source code is highlighted, when break-point is hit for WebRequest.Create

And after hitting F10 ,it moved to the next line

Wow this is way cool. The next step was to set a break-point using the bp command on the Program.cs


bp (@@masm(`Program.cs:8+`))

And  the break-point was hit and I was successfully able to have Integrated debugging environment. I know most of us don't  have Windbg version 6.7.5.0 , but there are few debugging geeks who still have them. I was happy that I kept the version.

Take Away

We should be able to debug within the framework source code using the latest version of debugger and if you have 6.7.5.0 , can have integrated debugging experience similar to VS.NET .

Debugging unknown termination of adplusmanager.exe – Windbg


With the latest release of debugging tools (6.12.0002.633) comes AdplusManager.exe  ,which is in managed code.  The adplusmanager.exe is a tool to manage multiple instance of adplus running across in different machines. Essentially a Master to control different slaves.  I will blog about the usage of this in a future post.

When I tried to start the AdplusManager.exe from the command line , nothing happened. My guess was if I didn’t enter any command line parameters , the tool should come up with the help text in the command line, similar to rest of command line tools I have used from MS. The next option I tried was  “AdplusManager.exe HELP” and there wasn’t any output. Surprisingly I went back to the documentation to look for command line parameters , which I never do, because I expect the tool to provide me with options. After reading the documentation for the parameters , the next option I tried was “D:\Program Files\Debugging Tools for Windows (x64)\adplusmanager.exe” GUI and nothing happened.  The only choice was to launch adplusmanager.exe using Windbg.

Because it was failing on the startup of the application ,I had set a load break-point when mscorwks was loaded in to the process , So that I can load sos after CLR is  loaded.

sxe -c ".loadby sos mscorwks;g" ld:mscorwks

And then setup a break-point on CLR exception , to dump the call stack and exception information

sxe -c "!clrstack;!pe" clr

And here is the output from the debugger

ModLoad: 000007fe`ef420000 000007fe`efdce000   C:\Windows\Microsoft.NET\Framework64\v2.0.50727\mscorwks.dll
(37760.36d40): CLR exception - code e0434f4d (first chance)
OS Thread Id: 0x36d40 (0)
*** WARNING: Unable to verify checksum for C:\Windows\assembly\NativeImages_v2.0.50727_64\mscorlib\9a017aa8d51322f18a40f414fa35872d\mscorlib.ni.dll
Child-SP         RetAddr          Call Site
000000000026e320 000007fee8f57b24 System.IO.__Error.WinIOError(Int32, System.String)
000000000026e380 000007fee8f570aa System.IO.FileStream.Init(System.String, System.IO.FileMode, System.IO.FileAccess, Int32, Boolean, System.IO.FileShare, Int32, System.IO.FileOptions, SECURITY_ATTRIBUTES, System.String, Boolean)
000000000026e510 000007fee8f587f2 System.IO.FileStream..ctor(System.String, System.IO.FileMode, System.IO.FileAccess, System.IO.FileShare, Int32, System.IO.FileOptions, System.String, Boolean)
000000000026e5a0 000007fee8f25b1b System.IO.FileStream..ctor(System.String, System.IO.FileMode, System.IO.FileAccess, System.IO.FileShare, Int32, System.IO.FileOptions)
000000000026e630 000007fee95fdefa System.IO.StreamWriter..ctor(System.String, Boolean, System.Text.Encoding, Int32)
000000000026e6b0 000007ff001a1653 System.IO.StreamWriter..ctor(System.String)
000000000026e700 000007ff001a15d4 ADPlusManager.Logger.Open(System.String)
000000000026e740 000007ff001a036d ADPlusManager.Logger.Open(System.String, System.String)
000000000026e7b0 000007feef6ed502 ADPlusManager.Program.Main(System.String[])
Exception object: 0000000002599e50
Exception type: System.IO.DirectoryNotFoundException
Message: Could not find a part of the path 'c:\logs\AdplusManager_20100308_195722_NAVEEN-PC_GUI.log'.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80070003
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
KERNELBASE!RaiseException+0x39:
000007fe`fd05aa7d 4881c4c8000000  add     rsp,0C8h

And the exception is DirectoryNotFoundException because I don't have C:\logs directory.  The next step was to disassemble the code and Why am I not surprised to see something

Within the exception handler the code is invoking ErrorOutput method

and the ErrorOutput method is trying to Log it to the disk  that's the reason it blew up. I would imagine that Microsoft would have a caught this bug and addressed it.

Takeaway

Make sure the code within catch block does not throw an exception.

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: