Share via

Event Tracing – Painful but worth it

  • Article

Why bother with something painful?  What is event tracing and why is it worth my time to work with it?

Trace events describe the current state of an application or operation for the purpose of debugging or performance tuning.

Some Good Reasons to use Event Tracing (according to world class developer Matt Pietrek)

Here are some really good reasons:
  1. Is usable from both drivers and application programs
  2. Supports multiple processes logging concurrently Very high throughput (on the order of 20,000 events/second with less than 5% CPU load
  3. Can be easily enabled/disabled at run time without any special application awareness
  4. Lets you work with trace files on any machine
  5. Logging to a file or real time tracing in memory
  6. Circular buffers

Developer Audience

ETW is designed for C and C++ developers who write user-mode applications.

Run-Time Requirements

ETW is included in Microsoft Windows 2000 and later.

Intro to Event Tracing For Windowshttps://blogs.msdn.com/matt_pietrek/archive/2004/09/16/230700.aspxImprove Debugging And Performance Tuning With ETW (April 2007)https://msdn.microsoft.com/en-us/magazine/cc163437.aspxJIT ETW tracing in .NET Framework 4https://blogs.msdn.com/clrcodegeneration/archive/2009/05/11/jit-etw-tracing-in-net-framework-4.aspx

CLR 4.0 & ETW

Prior to CLR 4.0 developers have no way of knowing why the runtime decided to disallow inlining or tail calls. Event tracing may provide the vehicle to inspect more closely what the CLR is doing.

There are a couple of new events exposed by the JIT to enable performance junkies to hurt themselves

To start logging ETW events do this:

    logman start clrevents –p {e13c0d23-ccbc-4e12-931b-d9cc2eee27e4} 0x1000 5 –ets

If you want more information on logman, go here https://technet.microsoft.com/en-us/library/bb490956.aspx.

After you’ve started ETW, run your scenario, and then stop ETW as follows:

    logman stop clrevents –ets

This will create clrevents.etl. To decode it further run this:

   tracerpt clrevents.etl

This will create 2 files: dumpfile.xml and summary.txt.

Here is a sample MethodJitInliningSucceeded event:

 <Event xmlns="https://schemas.microsoft.com/win/2004/08/events/event">
       <System>
                   <Provider Name="Microsoft-Windows-DotNETRuntime" Guid="{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}" />
                   <EventID>185</EventID>
                   <Version>0</Version>
                   <Level>5</Level>
                   <Task>9</Task>
                   <Opcode>83</Opcode>
                   <Keywords>0x1000</Keywords>
                   <TimeCreated SystemTime="2009-04-14T14:31:52.168851900Z" />
                   <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
                   <Execution ProcessID="15476" ThreadID="16936" ProcessorID="3" KernelTime="90" UserTime="60" />
                   <Channel />
                   <Computer />
       </System>
       <UserData>
                   <MethodJitInliningSucceeded xmlns='myNs'>
                         <MethodBeingCompiledNamespace>Factorial</MethodBeingCompiledNamespace>
                         <MethodBeingCompiledName>Main</MethodBeingCompiledName>
                               <MethodBeingCompiledNameSignature>void (class System.String[])</MethodBeingCompiledNameSignature>
                               <InlinerNamespace>Factorial</InlinerNamespace>
                               <InlinerName>Main</InlinerName>
                               <InlinerNameSignature>void (class System.String[])</InlinerNameSignature>
                               <InlineeNamespace>Factorial</InlineeNamespace>
                               <InlineeName>fact</InlineeName>
                               <InlineeNameSignature>unsigned int32 (unsigned int32)</InlineeNameSignature>
                               <ClrInstanceID>13</ClrInstanceID>
                   </MethodJitInliningSucceeded>
       </UserData>
       <RenderingInfo Culture="en-US">
                   <Level>Verbose </Level>
                   <Opcode>JitInliningSucceeded </Opcode>
                   <Keywords>
                               <Keyword>JitTracingKeyword </Keyword>
                   </Keywords>
                   <Task>CLR Method </Task>
                   <Message>MethodBeingCompiledNamespace=Factorial; MethodBeingCompiledName=Main; 
 MethodBeingCompiledNameSignature=void (class System.String[]); InlinerNamespace=Factorial; 
 InlinerName=Main; InlinerNameSignature=void (class System.String[]); InlineeNamespace=Factorial; 
 InlineeName=fact; InlineeNameSignature=unsigned int32 (unsigned int32); ClrInstanceID=13 </Message>
       </RenderingInfo>
 </Event>
  
  .csharpcode, .csharpcode pre
{
 font-size: small;
   color: black;
   font-family: consolas, "Courier New", courier, monospace;
   background-color: #ffffff;
  /*white-space: pre;*/
}
.csharpcode pre { margin: 0em; }
.csharpcode .rem { color: #008000; }
.csharpcode .kwrd { color: #0000ff; }
.csharpcode .str { color: #006080; }
.csharpcode .op { color: #0000c0; }
.csharpcode .preproc { color: #cc6633; }
.csharpcode .asp { background-color: #ffff00; }
.csharpcode .html { color: #800000; }
.csharpcode .attr { color: #ff0000; }
.csharpcode .alt 
{
   background-color: #f4f4f4;
  width: 100%;
    margin: 0em;
}
.csharpcode .lnum { color: #606060; }
The idea here is that you have visibility into how the code is jit-ed in the CLR.