So just what is in a trace? Using the xperf trace dumper

There is a lot of information in a typical kernel trace.  While the Performance Analyzer tool is quite powerful and makes it easy to view a trace graphically, sometimes you just need to see what is in the trace directly.  Xperf makes this easy.

First, its important to understand that a trace file (.ETL) is simply just the buffers produced by trace session written to a file.  The data in an ETL file isn't pre-processed, summarized, or otherwise annotated with meta data as it comes out of the OS.  Its is just the raw data that comes from a ETW session.  This is because ETW is designed for log time efficiency - ETW does the absolutely minimal amount of work needed to get the trace data to a file, or other consumer.

This means that all the heavy lifting of post processing trace data happens later. With the xperf tools, there are two places where this occurs:

1. In the merge step, xperf takes the kernel trace and trace files and merges them into a single trace file.  Xperf will merges (adds) meta data to the trace (I've got another post that provides all the detailed on merging in the works...).  The result of merging is a single trace file that can be analyzed by the tools directly on the target machine, or copied to another system for analysis.   Note that the merge step must happen on the system where the trace was taken (the target system).
2. When a trace is processed xperf using actions, or loaded into Performance Analyzer, the core trace processing components do a lot of work on the raw trace data.  This includes things like mapping process IDs (PIDs) to file and process names, mapping addresses to filenames, loading symbols for address, unifying stacks, and handling 64-bit and 32-bit differences.

As you've seen in the other posts, once a trace is merged it can be viewed in the Performance Analyzer.  But, xperf also allows you to see what is in the trace using the dumper action.  This is easy to do:

xperf -i fs.etl -a dmper >fs.csv

The -i fs.etl specified that the input file is FS.ETL.    The -a dumper parameter tells xperf to execute the dumper action.   The output goes to the standard output.

There is a short cut for this as well: the dumper action is the default action so if you only specify an input file then xperf simply dumps it.   For example, the following command does the same thing as the one above:

xperf -i fs.etl >fs.csv

The resulting file is an ANSI text file where each line is one record.   Each record consists of a comma delimited set of fields.  The first field of each line is the name (or type) of the record. 

There are some special lines and sections at the front of the file.   Each record type is described by a header line.   The header lines are delimited by the 'BeginHeader' and 'EndHeader' lines.   Note that the line immediately after the 'EndHeader' line is unique, it doesn't have a header line.  This line describes some of the characteristics of the trace such as its duration, and the pointer size.

The first field of each header line is the name (or type) of the ETW record that the header line describes.  The rest of the fields are the names of each of the fields for the record type.  Here is an example of the process start event header (P-Start) and a P-Start event.

P-Start, TimeStamp, Process Name ( PID), ParentPID, SessionID, UniqueKey, UserSid, Command Line

P-Start, 1017280, fs.exe (3004), 3608, 1, 0x86661508,
S-1-5-21-626881126-397955417-188441333-3225678, c:\coding\fs\Release\fs\fs.exe blflargorg c:\coding\*.cpp *.h -s

This event describes the start of a process.  There is also a corresponding P-End event. For processes that are already running when he trace is begun, the kernel logger includes a pseudo P-Start event. 

This means that every PID seen in other events will have a corresponding P-Start event in the trace before it is seen in an event.

Also note that xperf will dump events that you add to your own applications so long as you include an event manifest in your app.  So, you can add your own events and use xperf to dump them in the context of all the other events you include in the trace.

del.icio.us Tags: performance,xperf,windows