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.

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: