Jaa

Event Tracing in HTTP.sys: Part 2 - Anatomy of an Event

  • Artikkeli

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="https://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">https://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 https://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

Comments

  • Anonymous
    March 23, 2008
    I found these articles handy when looking into SQL Server HTTP/SOAP endpoints. You mention there are 65 unique event ID's for HTTP.sys, is there a list available? I've not been able to find one. Thanks Aaron

  • Anonymous
    February 11, 2010
    xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

  • <System>  <Provider Name="Microsoft-Windows-Kernel-Power" Guid="{331C3B3A-2005-44C2-AC5E-77220C37D6B4}" />  <EventID>41</EventID>  <Version>2</Version>  <Level>1</Level>  <Task>63</Task>  <Opcode>0</Opcode>  <Keywords>0x8000000000000002</Keywords>  <TimeCreated SystemTime="2010-02-11T23:37:52.607200000Z" />  <EventRecordID>53286</EventRecordID>  <Correlation />  <Execution ProcessID="4" ThreadID="8" />  <Channel>System</Channel>  <Computer>larry-PC</Computer>  <Security UserID="S-1-5-18" />  </System>
  • <EventData>  <Data Name="BugcheckCode">0</Data>  <Data Name="BugcheckParameter1">0x0</Data>  <Data Name="BugcheckParameter2">0x0</Data>  <Data Name="BugcheckParameter3">0x0</Data>  <Data Name="BugcheckParameter4">0x0</Data>  <Data Name="SleepInProgress">false</Data>  <Data Name="PowerButtonTimestamp">0</Data>  </EventData>  </Event> this happens on my computer every 15 to 30 min please tell me what is causing it i am using windows 7  64 bits on evga 650 i board running nvidia video  pentuim d processer  larry