Sunday, March 11, 2012

Reading up on WinDbg and XPerf

I like to share some interesting articles I found this week. The first article is "How Understanding Assembly Language Helps Debug .NET Applications". It was published by Sasha Goldshtein on Codeplex. Also checkout his blog it contains lots of useful information on .NET.

Another nice post by Roberto Alexis Farah discusses WinDbg and how to display the COM reference held by a RCW. So for those of you who use COM from a managed app this can be helpful when debugging problems.

Then there was a post on the NTDebugging Blog about Global Atom Table leaks. This blog entry guides you through a debug session to debug this kind of problems.

Mark B. Friedman a veteran in the field of performance shares some of his insight on Processor utilization and Xperf on his Performance by Design blog. Mark describes in his October post the details how the ETW CSwitch kernel event should be interpreted. Here is a reference to the MSDN library describing the CSwitch event.

Sunday, February 26, 2012

Event Tracing For Windows Resources

One of the great things about Windows 7 (2008/Vista) is Event Tracing for Windows (ETW). This blog entry contains a collection of pointers to websites and blogs that get you started using ETW.

Overview and Concepts
The NTDebugging blog gives a nice introduction to ETW and its tools. You can find the the first of three articles here: ETW Introduction and overview  .

MSDN Magazine also has a number of publication that are worthwhile reading:
- Improve Debugging And Performance Tuning With ETW

Here are some other good resources on ETW:
- Bruce Dawson (Random Ascii) has a nice intro on ETW traces
- Ashley Whetter has a blog with several pointers

Concepts (see also the Programmers Guide to Eventing):
Providers - Providers: applications that contain event tracing. There are 2 types: manifest-based providers and classing providers.
Events - event/action of interest that can be logged.
Channels - Providers can publish events to channels. Channels are targeted at different roles. Admin and Operational channels target IT professionals and Administrators and are enabled by default, while Analytic and Debug Channels are more in depth, and not usually enabled by default.
Consumers -  display/process events generated by a provider
Controller -  a component to control ETW e.g. enable of disable tracing of events
Keywords (Flags) - specify functional sub-components (HTTP, COOKIES, CONNECTION). Keywords can be used to filter on functions.
Levels - level of detail of the event need to be logged (Error, Informational, Verbose, etc).

Examples
- List all the providers installed on the machine which have 'kernel' in their name:
logman query providers | findstr /i "kernel"

- List all of the user-mode ETW providers for a given process (using its PID). Checkout your own application and you can see which (Microsoft) 'Provider' are available even if you did not instrument your application itself.
logman query providers -pid <PID>

- Show details on a given provider. The example shows the events for this provider including the different keywords and levels.
logman query providers "ntfs" 

- How to find what tracing is available, and its format you can use the wevtutil to get full publishing event and message information
wevtutil get-publisher Microsoft-Windows-WinInet /getevents /getmessage

- Show and enable/disable different providers that are running on your box.
Goto Computer Management => EventViewer => Application and Service logs (user the option Show Analytic and Debug Logs under the view menu). Under "Application and Services logs" you find a list of providers and the different channels they provide. You can enable the events for a channel by clicking the channel and enabling it via the right mouse button.

- Dump the information to a CSV file
tracerpt c:\windows\system32\winevet\logs\Microsoft-Windows-WinINet%4Analytic.etl –of CSV –o c:\temp\Microsoft-Windows-WinINet%4Analytic.csv
You can also use Powershell (v2) see get-help get-winenvent

- Get information on a ETW sessions on the box
logman query -ets

- Get detailed information on a ETW session
logman query -ets <session name>

- Start and stop a kernel trace for data collector set named "NT Kernel Logger" for a given set of keyword, buffer size 1024 MB, 20 buffers in circular mode writing to kernel.etl (max file size 20 MB
logman start "NT Kernel Logger" -p "Windows Kernel Trace" (process,thread,disk,isr,dpc,net,img,registry,file) -bs 1024 -nb 20 20 -mode Circular -o kernel.etl -ct perf -max 20 -ets
logman stop "NT Kernel Logger" -ets
- Starting and stopping a kernel session using Xperf (xperf -providers kernel gives an overview of the predefined kernel groups).
xperf -providers kernel
xperf -on DiagEasy
xperf -d kernel.etl 

- Information on how to configure and start an event tracing session programmatic ally can be found here: Configuring and starting and Event Tracing Session
Instrumenting your application
At this point you are hopefully convinced that ETW rocks. You might even consider to add ETW instrumentation to your own application. If so then keep on reading. Here are some pointers information that I found usefull.

To get started take a look at this article: Improve Debugging And Performance Tuning With ETW

First step to instrumenting the code is to write a manifest. How you do this can be found her:
Writing an instrumentation manifest

The MC.EXE tool (part of the SDK) can be used to converts the manifest into a C# wrapper class (can also generate C++ code). You can instrument you code by calling methods on this class. Check out the following guide Programmers Guide to Eventing

You should name the event providers by using the following convention (see Programmers Guide to Eventing):

       <company_name>-<product_name>-<component_name>


The name forms the path in the EventViewer (under Applications and Services Logs). For Debug and Analytic channels you need to enable (view => Show Analytics and Debug Logs). So when using this name convention and defining channels in you manifest an entry in the EventViewer will show up. From there you can enable/disable the log. Cyclic logs however still seem to have some issues (see kb2488055).

After you have instrumented you code you might want to do automatic analysis (e.g. gather statistics). For this there is a library which can be used to parse the ETL file. It comes with the PerfMonitor tool (see my previous post). You can find the library here: TraceEvent. The steps to do some basic etl file parsing are:
- Create an instance of the ETWTraceEventSource class
- Register a callback for a trace event
- Invoke the Process method

You can also dump the etl content to e.g. an XML file using the tracerpt tool. For example:

tracerpt <myetlfile.etl> -import <mymanifest> -y


The tracerpt tool will write a the etl content to (by default) dumpfile.xml and use the manifest to decode any custom event data.


Analyzing ETW files

ETW files can be read using the Windows API
The APIs that are available are documented in the Event Tracing Reference part of the MSDN library.

ETW and Debugging

ETW and Process Dumps
The ETW information is available in a dump. You can for example dump the content of the "Circular Kernel Session" to a file usign WinDbg. To do this issue the following command.
!wmitrace.strdump
!wmitrace.logsave <session> <filename>

For more info: WPP Tracing with !wmitrace and the Debugger

Memory (heap) Problems
ETW lets you trace the memory allocation done within a process. Combining this with the ability to log stack frames (xperf -stackwalk) enables you to debug memory problems. More on this can be found here:

Part 3: ETW Methods of Tracing
TraceLog


Resources
Network Tracing in Windows 7
GPUView