Continuing the series on Http.sys ETW Tracing, we will dissect an event as displayed in the default XML format. To review creating an ETW trace, see Capturing a Trace

Pictured is an example of a typical event in a trace. Note how the event is wrapped in an <Event> element. This particular event happens to be our Parse event: 

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
   <System>
      <Provider Name="Microsoft-Windows-HttpService" Guid="{dd5ef90a-6398-47a4-ad34-4dcecdef795f}" />
      <EventID>2</EventID>
      <Version>0</Version>
      <Level>4</Level>
      <Task>1</Task>
      <Opcode>12</Opcode>
      <Keywords>0x8000000000000002</Keywords>
      <TimeCreated SystemTime="2006-09-06T16:59:22.251258100Z" />
      <Correlation ActivityID="{80000002-0001-fb00-0000-000000000000}" />
      <Execution ProcessID="4" ThreadID="1276" ProcessorID="1" KernelTime="15" UserTime="0" />
      <Channel>Microsoft-Windows-HttpService/Trace</Channel>
      <Computer />
   </System>
   <EventData>
      <Data Name="RequestObj">0xFFFFFA8001BB5320</Data>
      <Data Name="HttpVerb">4</Data>
      <Data Name="Url">http://localhost:80/RequestQueueTests/</Data>
   </EventData>
   <RenderingInfo Culture="en-US">
      <Level>Information </Level>
      <Opcode>Parse </Opcode>
      <Keywords>
         <Keyword>Flagged on all HTTP events dealing with request processing </Keyword>
      </Keywords>
      <Task>HTTP Request Trace Task </Task>
      <Message>Parsed request (request pointer 0xFFFFFA8001BB5320, method 4) with URI http://localhost:80/. </Message>
      <Channel>HTTP Service Channel </Channel>
      <Provider>Microsoft-Windows-HttpService </Provider>
   </RenderingInfo>
</Event>

The <event> node has three sub-nodes, <System>, <EventData>, and <RenderingInfo>. Each contains specific data. The <System> node holds information such as the name of the traced component and the event time stamp. The <EventData> node holds information specific to the event. The Http.sys dev decides what information should be logged for each of our events. The <RenderingInfo> node holds much of the same information as the <System> node, but in a more readable form. Also, this node holds the <Message> sub-node, which describes the event. Below is complete description of the elements contained under each sub-node.

The System node

  • Provider: This contains the name and the Guid of the component responsible for the event.
  • EventID: Each event has a unique EventID associated with it. In the case of Http.sys, we have 65 unique events.
  • Version: Beyond scope of this post.
  • Level: This is the verbosity level of the event. Each event has a verbosity level, LogAlways, Critical, Error, Warning, Informational, and Verbose numbered from 0 to 5 respectively. I generally trace with the highest verbosity level to collect the maximum amount of data.
  • Task: Beyond scope of this post.
  • Opcode: A numeric value representing the name of the particular event, short for “Operational Code”.
  • Keywords: Keywords are tags attached to events in order to group various events based on their use.
  • TimeCreated: This is the timestamp of the event. It includes the data in YYYY-MM-DD format and the time in HH:MM:SS.SSSSSSSSS format.
  • Correlation: This includes the ActivityID for the request.
  • Execution: Beyond scope of this post.
  • Channel: Again, this is the name of the trace provider.
  • Computer: Beyond scope of this post.

The EventData node

  • Data: Each request has it’s own unique data. Typically, a data node includes the name of the data (show as the value of the Name attribute) and the data itself.

The RenderingInfo node

  • Level: Like the Level element under the <System> node, this is the verbosity of the event. However, instead of the numeric level, this gives the name of the level, such as Error or Informational.
  • Opcode: This is the same Opcode as above, only not rendered in it’s numeric form. Here it is displayed via the friendly name of the event. Hereafter, I will refer to the opcode as the “EventName”.
  • Keywords: Keywords are used to group events into groups.
  • Task: NA.
  • Message: This is a friendly, more readable message describing the event.
  • Channel: Beyond scope of this post.
  • Provider: This is the name of the provider.

I know this amount of information appears overwhelming, especially considering a typical trace can have hundreds or even thousands of events and be several megabytes in size. Consequently, when using ETW, I “cherry-pick” a few bits of information from the XML file:

The event name, or opcode element, under the <RenderingInfo> node and all the Data elements under the <EvenData> node.

EventName Data1 Data2 Data3 Data4 ...

When sorted in a table format it’s easy to follow one event to another. We’ll go over the best ways to do this (using a script, xslt, etc...) in a separate post.

In the next ETW post, I’ll go over an ETW trace for a typical HTTP transaction with multiple events.

-Jeff Balsley