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.

About Naveen
Write code.

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

  1. Pingback: DotNetShoutout

  2. Pingback: The Morning Brew - Chris Alcock » The Morning Brew #562

  3. Pingback: iAwaaz-News-by-People

  4. Pingback: uberVU - social comments

  5. Pingback: Our case against debugging « The SoftFluent Blog

  6. Hi Naveen,

    Thanks a lot for this great post – thanks to it I was able to figure out what was wrong with my managed provider. If anyone ever encounters the 15002 (ERROR_EVT_PUBLISHER_METADATA_NOT_FOUND) error while using the managed provider remember to add a template for your event – I also described my struggle on my blog: http://lowleveldesign.wordpress.com/2012/03/14/a-managed-etw-provider-and-the-15002-error/

    Best,
    Sebastian

  7. Pingback: IIS related System.ExecutionEngineException | PHP Developer Resource

  8. Sapan Roy says:

    Hi Naveen and Friends,

    Need your help.

    Thanks for this blog it helped me to get good understanding about ETW. I need to use ETW in one of our product where ETW has been already implemented, we have another Library which should be able to Log error by ETW techniuqe. Below are the details

    Able to log through channels defined by our product but its truncation string message.

    ETW.PROVIDER.EventWriteSampleEvent(“12345678″, “testing”);

    I need to display “12345678″ under source and testing under Additional Info.

    Event viewer display below
    Source: ’1′ Thread ID: ’0×330032′ Additional Info: ’4′

    from string “12345678″ the first character is going under source whereas ’4′ is under Addition info.

    The message template as below

    I can’t make changes in above template, as don’t have rights for it.

    Below is some code I am using.

    EventDescriptor eventDescriptor = new EventDescriptor(0×3, 0×0, 0×1, 0×4, 0×0, 0×0, (long)(long)0×8000000000000000);

    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 LogMessage(ref EventDescriptor eventDescriptor, string source, string StringData)
    {
    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)(source.Length + 1) * sizeof(char);
    //userDataPtr[1].Size = (uint)(StringData.Length + 1);

    fixed (char* chrPtr1 = source)
    {
    userDataPtr[0].DataPointer = (ulong)chrPtr1;
    status = WriteEvent(ref eventDescriptor, argumentCount, (IntPtr)(userData));
    }
    }

    return status;

    }

    }

    • Sapan Roy says:

      Please ignore spelling mistake. Read this as below
      “Able to log through channels defined by our product but its truncating string message.”

  9. Pingback: Windows事件追踪入门与使用方式 | Enterprise Just Builder

  10. Alois Kraus says:

    Great description. I have found nowhere ecmangen mentioned exept here. Your blog seems to be the only source of information how to write ETW events via .NET 4.0.

  11. Pingback: An easy way to use XPerf and Event Tracing for Windows (ETW) | Nemeth Tamas

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: