CAPTURING AND ANALYZING AN ETW TRACE (event TRACING FOR WINDOWS)

  • Artykuł

Continuing my conversations on using tools, today I want to explain how to capture an ETW trace and parse it. Event tracing for Windows (ETW) is a very powerful, tracing mechanism built into the Windows operating system that allows you to view messages from various subsystems. This is very helpful in troubleshooting problems on the server side. We use it a lot in the IIS support group to troubleshoot various customer issues. In an earlier post, I discussed and explained the various Providers in Windows that spit information. We will use some of these providers today.  To view a list of providers available on your system, run the following command in a command prompt window.

Logman query providers

Stage 1: Capture an ETW trace in Windows Server 2003 with Service Pack 1 or upwards.

NOTE: You must be logged on as a computer administrator to perform these steps:

  1. Create a Trace text file that contains a list of the providers that you want to trace.
  2. Create a folder called ETW in C drive root
  3. Open a command prompt.
  4. Switch to C:\ETW folder.
  5. Type: Logman Query Providers > Providers.txt <enter> [This will output the results into Providers.txt file]
  6. Open Providers.txt in Notepad. you will have 2 columns – Provider & GUID.
  7. Remove the lines of those providers you do not wish to use. For IIS it will be something like this

IIS: WWW Global {d55d3bc9-cba9-44df-827e-132d3a4596c2}
IIS: SSL Filter {1fbecc45-c060-4e7c-8a0e-0dbd6116181b}
IIS: Request Monitor {3b7b0b4b-4b01-44b4-a95e-3c755719aebf}
IIS: WWW Server {3a2a4e84-4c21-4981-ae10-3fda0d9b0f83}
IIS: Active Server Pages (ASP) {06b94d9a-b15e-456e-a4ef-37c984a2cb4b}
IIS: IISADMIN Global {DC1271C2-A0AF-400f-850C-4E42FE16BE1C}
IIS: WWW Isapi Extension {a1c2040e-8840-4c31-ba11-9871031a19ea}
HTTP Service Trace {dd5ef90a-6398-47a4-ad34-4dcecdef795f}

Now delete the values from the first column. We get:

{d55d3bc9-cba9-44df-827e-132d3a4596c2}
{1fbecc45-c060-4e7c-8a0e-0dbd6116181b}
{3b7b0b4b-4b01-44b4-a95e-3c755719aebf}
{3a2a4e84-4c21-4981-ae10-3fda0d9b0f83}
{06b94d9a-b15e-456e-a4ef-37c984a2cb4b}
{DC1271C2-A0AF-400f-850C-4E42FE16BE1C}
{a1c2040e-8840-4c31-ba11-9871031a19ea}
{dd5ef90a-6398-47a4-ad34-4dcecdef795f}

Now we will add flags to each provider. Flags indicate the areas to trace and the verbosity levels. Each flag will be separated by a TAB. After each entry, press Tab and type 0xFFFFFFFF, press Tab and type 0x5. For IIS: WWW Server only, this will be 0xFFFFFFFE 0x5. The flags 0xFFFFFFFF & 0xFFFFFFFE indicate all areas and 0x5 indicates full verbose mode.

Thus, we get:

{d55d3bc9-cba9-44df-827e-132d3a4596c2} 0xFFFFFFFF 0x5
{1fbecc45-c060-4e7c-8a0e-0dbd6116181b} 0xFFFFFFFF 0x5
{3b7b0b4b-4b01-44b4-a95e-3c755719aebf} 0xFFFFFFFF 0x5
{3a2a4e84-4c21-4981-ae10-3fda0d9b0f83} 0xFFFFFFFE 0x5
{06b94d9a-b15e-456e-a4ef-37c984a2cb4b} 0xFFFFFFFF 0x5
{DC1271C2-A0AF-400f-850C-4E42FE16BE1C} 0xFFFFFFFF 0x5
{a1c2040e-8840-4c31-ba11-9871031a19ea} 0xFFFFFFFF 0x5
{dd5ef90a-6398-47a4-ad34-4dcecdef795f} 0xFFFFFFFF 0x5

  1. Save the Providers.txt file.
  2. Go back to command prompt. We are now ready to start ETW Tracing.
  3. At the command prompt, type: Logman -start MyTrace -pf providers.txt –ets <enter>
  4. MyTrace is a name for the trace and is a mandatory parameter.

Now, we can reproduce the problem. Execute the HTTP request from any HTTP capable client or make the request via browser. Once the problem has been reproduced, we can stop the trace as follows:

At the command prompt, type: Logman –stop MyTrace –ets <enter>

We should now have a file called MyTrace.ETL in C:\ETW folder. This file is not readable using any editor. It first needs to be parsed.

Stage 2: Parsing an ETW Trace.

OK, so we now have a trace file that cannot be read by any editors because it is a binary file. To parse an ETW trace file, we need another tool – LogParser. I am sure many have heard great stories about this. This is another powerful tool and provided by Microsoft as a free download. Download LogParser v2.2. Then install it to C:\LogParser folder.

Important: You need to parse an ETW trace on the same version of the OS from where it was captured. This is because the ETW providers will be different for different versions of Windows.

Before you can use LogParser, there are a couple of things you need to do - Register LogParser.dll in system registry and make a slight modification to the parsing Windows script so that it doesn’t prompt you.

  1. Open another command prompt and switch to C:\LogParser folder.
  2. Type: Regsvr32 Logparser.dll <Enter>. Click OK after the message.
  3. Copy the DumpTraceReqs.js file from C:\LogParser\Samples\Scripts to C:\Logparser [this is just for convenience]
  4. Open DumpTraceReqs.js in Notepad.
  5. Search for the text: “//Prompt the user to press a key”
  6. Comment out the lines WScript.Echo("[Hit ENTER...]"); and WScript.StdIn.ReadLine(); It should be as
    • //WScript.Echo("[Hit ENTER...]");
    • //WScript.StdIn.ReadLine();
  7. Save the file & close Notepad.

We are now ready to parse the ETW trace file. At the second command prompt, type the following command and press ENTER

Cscript DumpTraceReqs.js C:\ETW\MyTrace.etl > Output.txt <enter>

Wait for the command to finish and then open the file, Output.txt in Notepad. You should now have a file that contains a very organized collection of information that shows the activities in each stage of the request processing pipeline. Any kind of permissions problems, compression failure etc should show up here. It is self explanatory. However, if you do have questions on what you see in the ETW trace file, please share it or post it here and I’ll help.

LogParser is a very powerful tool and you can use SQL like commands for a variety of purposes including reading event logs, IIS logs, Pure text files, Network trace files and many others. It also includes many functions which you can use to transform data. Take a look at this post that contains a lot of examples.

I hope you found this post useful in debugging problems. Please feel free to leave your feedback.

Comments

  • Anonymous
    February 25, 2009
    Thanks a lot for the great post.The tips for Google news is very much useful. Hereafter i need not go Google news every time

  • Anonymous
    February 27, 2009
    Sudeep, thanks for the good write-up. BTW, you don't necessarily have to wade through boatloads of parsed traces -- there is a nice viewer that shows the trace visually -- SvcTraceView (http://msdn.microsoft.com/en-us/library/ms732023.aspx)

  • Anonymous
    February 27, 2009
    Hi Max, Thank you for this info. I downloaded and used this tool and its really great. We also use another tool that gives a nice UI. Its called Failed request tracing log (IIS). But this one is also very cool Thanks again, Sudeep

  • Anonymous
    August 29, 2009
    Hi Sudeep - Firstly, thanks for the great post. There is much information about EWT on the Internet (at least I couldn't find much!) except for the IIS documentation, so this was really helpful! I have a problem with request-based tracing, though. I can't seem to get it up and running.. Basically I am trying to trace requests to an ASP page, located at D:data www.mywebsiteforetw.compublic_htmlABCincludedataSheetMY_etwPage.asp (I gave a fake name for security reasons, but the length of the path and the filename is the same as original, thinking it may be a length issue that you might point out...) Even though I set w3svc/<n>/TraceUriPrefix to this page, logman seems to be still logging all the pages.. I did an iisreset, I tried different parameter files, to no avail. Could you give me an idea where I might be doing wrong? My IIS is v6.0 running on Windows 2003 Server Standard Edition+SP2. The parameter file I use: {3a2a4e84-4c21-4981-ae10-3fda0d9b0f83} 0xFFFFFFFE 0x5 {d55d3bc9-cba9-44df-827e-132d3a4596c2} 0xFFFFFFFF 0x5 {06b94d9a-b15e-456e-a4ef-37c984a2cb4b} 0xFFFFFFFF 0x5 {a1c2040e-8840-4c31-ba11-9871031a19ea} 0xFFFFFFFF 0x5 ..which is basically "IIS: WWW Server", "IIS: WWW Global", "IIS: Active Server Pages (ASP)" and "IIS: WWW Isapi Extension"... I also tried with "IIS: Active Server Pages (ASP)" only, but DumpTraceReqs.js gave me the following error: C:perflogstracedumptracereqs.js(70, 2) CLogRecordClass: Cannot find field "RequestURL" in RecordSet [The parameter is incorrect.] Many thanks, Erkin PS: Just as an FYI, in IIS 6.0 documentation in MS TechNet, the adsutil operation suggested to turn on request-based tracing actually has a syntax error - I guess we should not use the equal sign, but rather, a space between w3svc/<n>/TraceUriPrefix and the URL path. e.g.:  C:>cd inetpub  C:Inetpub>cd adminscripts  C:InetpubAdminScripts>cscript adsutil.vbs set w3svc/1/TraceUriPrefix="D:data www.mywebsiteforetw.compublic_htmlABCincludedataSheetMY_etwPage.asp" Microsoft (R) Windows Script Host Version 5.6 Copyright (C) Microsoft Corporation 1996-2001. All rights reserved.  Error: Wrong number of Args for the SET command  C:InetpubAdminScripts>cscript adsutil.vbs set w3svc/1/TraceUriPrefix "D:data www.mywebsiteforetw.compublic_htmlABCincludedataSheetMY_etwPage.asp" Microsoft (R) Windows Script Host Version 5.6 Copyright (C) Microsoft Corporation 1996-2001. All rights reserved. TraceUriPrefix                  : (LIST) "D:datawww.mywebsiteforetw.compublic _htmlABCincludedataSheetMY_etwPage.asp"  C:InetpubAdminScripts>

  • Anonymous
    August 31, 2009
    Erkin, I haven't experimented a lot with TraceUriPrefix, simply because it always helped to see all the associated requests. From what I can recollect, this setting needs to have the UseUrlFilter Flag also enabled. Perhaps a cycle of the appPool. Not 100% sure though. I am a bit swamped now but I'll find some time to test it out and update.

  • Anonymous
    September 01, 2009
    Sudeep - Thanks for the response. The reason I'm trying to trace a single URL is because I am going to have to run this about 30-60 mins on the production server (I know I should normally avoid this, but I have no choice as this is a very intermittent performance issue that we could not reproduce on QA or dev.boxes), and when I run it for all URLs, size of the .etl file gets incredibly large. I had also suspected of UseUrlFilter, but so far I am quite confused as to how to turn it on...Let me explain: Firstly, below is the snippet from MS Technet IIS 6.0 Documentation, taken from http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/757a3990-d8ae-4d72-94af-70fa46edc985.mspx?mfr=true [QUOTE] Enter one of the following items in your provider file: "IIS: WWW Server" UseUrlFilter 5 The UseUrlFilter flag enables tracing for the URL specified in the TraceUriPrefix metabase property. -or- "IIS: WWW Server" 0xFFFFFFFE 5 The 0xFFFFFFFE flag enables all the WWW server tracing flags, including the UseUrlFilter flag. [/QUOTE] Now - I actually tried both options and couldn't seem to get them working. I guess one needs to actually set the flag to either 1 or 0xffffffff, but then, I don't get any results at all, even though I made several requests to my asp page. I paste my results below. Sorry for being verbose, but I thought it would shed some light... Any thoughts are welcomed! Thanks!

First, verify TraceUriPrefix is setup correctly.

C:InetpubAdminScripts>cscript adsutil.vbs get w3svc/1/TraceUriPrefix Microsoft (R) Windows Script Host Version 5.6 Copyright (C) Microsoft Corporation 1996-2001. All rights reserved. TraceUriPrefix                  : (LIST)  (1 Items)  "D:datawww.mywebsiteforetw.compublic_htmlABCincludedataSheetMY_etwPage.asp"

EXAMPLE 1: With IIS: WWW Server provider's flag set to 0xFFFFFFFE RESULT   : URL filter doesn't work. DumpTraceReqs and LogParser work.

C:InetpubAdminScripts>cd C:perflogstrace C:perflogstrace>logman start testtrace -pf providers.txt -ets Name:                      testtrace Age Limit:                 15 Buffer Size:               64 Buffers Written:           1 Clock Type:                System Events Lost:               0 Flush Timer:               0 Buffers Free:              2 Buffers Lost:              0 File Mode:                 Sequential File Name:                 C:perflogstracetesttrace.etl Logger Id:                 4 Logger Thread Id:          1572 Maximum Buffers:           32 Maximum File Size:         0 Minimum Buffers:           10 Number of buffers:         10 Real Time Buffers Lost:    0 Provider                                  Flags                     Level

  • "IIS: WWW Server"                       (IISAuthentication,IISSecurity,IISFilt er,IISStaticFile,IISCGI,IISCompression,IISCache,IISAll)  0x05  {3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}  0xfffffffe                0x05
  • "IIS: Active Server Pages (ASP)"        0x00000000                0x05  {06B94D9A-B15E-456E-A4EF-37C984A2CB4B}  0x00000000                0x05 The command completed successfully. C:perflogstrace>logman stop testtrace -ets The command completed successfully. C:perflogstrace>cscript dumptracereqs.js testtrace.etl > testtrace.log C:perflogstrace> C:Program FilesIIS ResourcesLog Parser 2.2>LogParser -i:ETW "SELECT * FROM c: perflogstracetesttrace.etl" -o:DataGrid Statistics:

Elements processed: 600 Elements output:    600 Execution time:     61.22 seconds (00:01:1.22)

EXAMPLE 2: With IIS: WWW Server provider's flag set to 0xFFFFFFFF RESULT   : URL filter seems to be turned on, but DumpTraceReqs does not work. LogParser returns empty.

C:perflogstrace>logman start testtrace -pf providers.txt -ets Name:                      testtrace Age Limit:                 15 Buffer Size:               64 Buffers Written:           1 Clock Type:                System Events Lost:               0 Flush Timer:               0 Buffers Free:              2 Buffers Lost:              0 File Mode:                 Sequential File Name:                 C:perflogstracetesttrace.etl Logger Id:                 4 Logger Thread Id:          412 Maximum Buffers:           32 Maximum File Size:         0 Minimum Buffers:           10 Number of buffers:         10 Real Time Buffers Lost:    0 Provider                                  Flags                     Level

  • "IIS: WWW Server"                       (UseUrlFilter,IISAuthentication,IISSec urity,IISFilter,IISStaticFile,IISCGI,IISCompression,IISCache,IISAll)  0x05  {3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}  0xffffffff                0x05
  • "IIS: Active Server Pages (ASP)"        0x00000000                0x05  {06B94D9A-B15E-456E-A4EF-37C984A2CB4B}  0x00000000                0x05 The command completed successfully. C:perflogstrace>logman stop testtrace -ets The command completed successfully. C:perflogstrace>cscript dumptracereqs.js testtrace.etl > testtrace.log C:perflogstracedumptracereqs.js(35, 1) CLogQueryClass: Error parsing query: S ELECT clause: Syntax Error: unknown field 'ContextID' [Record field does not exi st.] C:perflogstrace> C:Program FilesIIS ResourcesLog Parser 2.2>LogParser -i:ETW "SELECT * FROM c: perflogstracetesttrace.etl" -o:DataGrid Statistics:

Elements processed: 0 Elements output:    0 Execution time:     0.02 seconds

EXAMPLE 3: With IIS: WWW Server provider's flag set to 1 RESULT   : URL filter seems to be turned on, but DumpTraceReqs does not work. LogParser returns empty.

C:perflogstrace>logman start testtrace -pf providers.txt -ets Name:                      testtrace Age Limit:                 15 Buffer Size:               64 Buffers Written:           1 Clock Type:                System Events Lost:               0 Flush Timer:               0 Buffers Free:              2 Buffers Lost:              0 File Mode:                 Sequential File Name:                 C:perflogstracetesttrace.etl Logger Id:                 4 Logger Thread Id:          2140 Maximum Buffers:           32 Maximum File Size:         0 Minimum Buffers:           10 Number of buffers:         10 Real Time Buffers Lost:    0 Provider                                  Flags                     Level

  • "IIS: WWW Server"                       (UseUrlFilter)            0x05  {3A2A4E84-4C21-4981-AE10-3FDA0D9B0F83}  0x00000001                0x05
  • "IIS: Active Server Pages (ASP)"        0x00000000                0x05  {06B94D9A-B15E-456E-A4EF-37C984A2CB4B}  0x00000000                0x05 The command completed successfully. C:perflogstrace>logman stop testtrace -ets The command completed successfully. C:perflogstrace>cscript dumptracereqs.js testtrace.etl > testtrace.log C:perflogstracedumptracereqs.js(35, 1) CLogQueryClass: Error parsing query: S ELECT clause: Syntax Error: unknown field 'ContextID' [Record field does not exi st.] C:Program FilesIIS ResourcesLog Parser 2.2>LogParser -i:ETW "SELECT * FROM c: perflogstracetesttrace.etl" -o:DataGrid Statistics:

Elements processed: 0 Elements output:    0 Execution time:     0.02 seconds

  • Anonymous
    September 02, 2009
    Erkin, I tested this today and it didn't work for me either on 2 machines. What is the page that is having the performance problem? If its an ASPX page, then you can turn on ASP.net tracing in web.config Sudeep