Did you know that Windows includes a low-overhead tracing package that can be used by kernel-mode components?  Well, it does, and it has since Windows 2000.  The package is called Event Tracing for Windows. It’s implemented in kernel-mode by a combination of components including WMI.

Some of the characteristics of this facility, as made available for easy use by driver writers, are:

·                   Tracing can be enabled/disabled dynamically  -- either programmatically from a user-mode program that you develop, or by using supplied utilities;

·                   Very low run-time overhead (one bit test) when not enabled;

·                   When tracing is enabled, trace information is collected in memory buffers and written asynchronously to disk;

·                   Trace output not written to disk before a system crash can be viewed form within a crash dump file via WinDbg;

·                   Trace statements within your driver can be associated with individual flags or levels.  These can be enabled and disabled dynamically;

·                   Trace output can be written to a file in “raw” form or interpreted and viewed in real-time using supplied command line tools.

The inclusion of Event Tracing for Windows may very well be one of the most important features made available to driver writers since DbgPrint.  Let’s see how it can be used in a real driver-development project.

The Old Way

We’ve all written the macro and/or function in our drivers a million times.  You know the one I’m talking about (see Figure 1).

#if dbg

#define DrvDebugPrint(flag, args)           \

              if ( (flag) & DrvDebugLevel) {        \

DbgPrint(args);             \

                      }

#else

     #define DrvDebugPrint(flag, args)

#endif

#define DRV_DBG_PNP             0x00000001

#define DRV_DBG_CREATE_CLOSE    0x00000002

...

Figure 1 – The Old Way

Just about everyone has their own variation of this code. And, while this kind of technique can be very useful for debugging, we all know how slow the driver gets, and how hard it is to wade through the mountains of output, when you turn on too many of those flags.  Ugh!

What’s almost equally frustrating is what happens when there’s a problem at a customer site, and they’re blaming your driver.  You try to debug the problem, but you need information about the details of what the driver’s doing and what paths are being taken.  If you have a technically sophisticated customer or a big support organization, you could always ship them the checked build of your driver, have them hook up the debugger, and cut and paste the output from WinDbg and email it to you.  Of course, there’s the timing issue created by those DbgPrints.  And, of course, the customer will get to read the text of your debug messages (“***DRV: Unknown frobnitz seen value=0x030323, call PeterGV”) and ask you incredibly relevant and “helpful” questions.

There’s got to be a better way.

And, of course, there is.  For ages, devs have built in-memory tracing functions to solve these problems.  Some of these packages have even been sophisticated enough to asynchronously log the trace data to disk.  But, these packages are unique to each driver you write, you have to support them, and – let’s face it – few of us have the time that’s needed to really get these packages fully solid and optimized.  I know.  I’ve written more than one myself.

The New Way

Event Tracing for Windows provides a standard mechanism for doing tracing in your driver.  Tracing can be enabled dynamically, and the run-time overhead when not enabled is very low.  This makes it possible to leave the trace statements in the free build of your driver to facilitate customer problem resolution.

Event Tracing for Windows works through WMI.  Trace data from your driver is collected into memory buffers (the size and number of which are under your control when you enable trace collection) and may be either logged in binary form to disk or interpreted and displayed in “real time.”  Complete documentation for enabling and disabling Event Tracing for Windows for a particular component programmatically is in the SDK.  So, you can write a small user-mode program that allows your customer to turn on logging for a particular path in your driver, and email you the resulting log file.  And, because Event Tracing for Windows separates the data that’s logged from the formatting of that data, log messages are small and do not contain the text of your log messages.  No more risk of exposing secrets through your logging, and no more “helpful” user comments about your log messages.

And, before you ask, it’s trivially added to your drivers in Windows XP and later and can almost as easily be used in a backward compatible way to Windows 2000.

Adding Tracing to Your Driver

There are a number of different ways to utilize Event Tracing for Windows from your driver.  The easiest way is to use what’s called WPP Software Tracing (you can see a brief description of this facility in the DDK under this topic). “WPP” in this case stands for Windows Pre-Processor, because it works with a set of powerful macros and the C-language preprocessor to make adding tracing to your driver exactly as easy as doing a DbgPrint.

Let’s say you’re starting with a driver that uses the DrvDebugPrint macro shown in Figure 1.  You can use WPP Software Tracing facilities in the DDK to turn these statements into trace statements in just four simple steps.  The steps are:

Step 1: Replace the #define’s for DrvDebugPrint and its associated flags with the declaration of a GUID (that will be used to uniquely identify your driver as a source of tracing messages) and various flag bits that you can use to control what trace messages are displayed.  You’ll typically want this definition to appear in the “master” h file for your driver.  See Figure 2 for an example.

#define WPP_CONTROL_GUIDS                                               \

                                                                \

WPP_DEFINE_CONTROL_GUID(DRVGUID,                                \

(E505C68B,05CA,4099,9EFB,1498F39C2285),                 \

                                                                \

WPP_DEFINE_BIT(DRV_DBG_PNP)                  /* 0x00000001 */   \

WPP_DEFINE_BIT(DRV_DBG_CREATE_CLOSE)         /*0x00000002 */    \

...

)

Figure 2 – The New Way

Step 2: In each source file in your project, place an include statement for the “trace message header” (tmh) file that will be generated during the build process.  Place this include after your other includes, such as the include for WDM.H.  So, for example, within your module named DRV_INIT.C, you put the following statement:

#include “DRV_INIT.TMH”

For drivers written in C++, you'll want to be sure to place the #include (above) with an 'extern "C" block:

Within DriverEntry, you add a statement like the following:

WPP_INIT_TRACING(DriverObject, RegistryPath);

Within your unload function, you add a statement such as:

WPP_CLEANUP(DriverObject);

Step 4: Identify the function that you want WPP to use as the trace statement.  In our example, we had previously used DrvDebugPrint to optionally send output to the debugger.  We’ll have the Windows Software PreProcessor to change those to trace statements.  We do this by adding the following statement to our sources file:

RUN_WPP=$(SOURCES) \

            -km\

            -func:DrvDebugPrint(FLAG,(MSG,...))

Now build your driver like you normally would (using ‘build’).  You’re done!  Note that if your driver is written in C++ (or it's a kernel mode DLL), you'll need to add the "-dll" qualifier to the RUN_WPP statement, as follows:

Your driver has been successfully converted to support Event Tracing for Windows.  You can now enable tracing for any of the flags you defined with WPP_DEFINE_BIT.  Your trace output can be displayed in real-time, written to disk, or even redirected to WinDbg just like your old DbgPrints.

Getting the Output

So, you do you enable tracing and see your output?  Once your driver is installed and running in the usual way, getting understandable trace requires obtaining the trace format information, collecting the trace data, and interpreting and displaying that trace data. 

Separating Format, Collection, and Display

The Windows XP and later versions of the DDK have a set of utilities named tracepdb, tracelog, and tracefmt.  These utilities can be used to control tracing in your driver, and view your trace output in a three step process.  You can find these utilities in the DDK’s \tools\tracing\ directory.  These utilities are described in the DDK documentation, in the WPP Software Tracing section, so I’ll just give you a quick overview of how to use them.  The three steps are:

1.   Getting the trace format information for your driver

2.   Collecting the trace data

3.   Interpreting and displaying the trace data

You might want to separate these three steps, and therefore use these utilities or even a program or two that you’ve custom developed, to collect trace information at a customer site.  In this way, you can have your customer collect the trace data (step 2) without being able to view that trace data in human readable form (which requires steps 1 and 3).

The tracepdb utility is used to extract textual format information from the driver’s PDB file.  The output from tracepdb is a set of Trace Format (tmf) files.  These files are used to interpret the trace data written by your driver.

D:\DRV\objfre_wnet_x86\i386> tracepdb –f DRV.PDB

If you look at the created tmf files, you see that they contain the equivalent of the “format” portion of a DbgPrint message.  By separating this information from your trace data, the amount of data logged is reduced (and your trace information remains secure).

The tracelog utility is used to control driver tracing.  With this utility you can enable tracing for specific bits you have defined, and define where the output is to be sent.  Just in case it’s not obvious, you enable tracing on the system where your driver is running, where you want to collect trace information.  Your driver is identified by the GUID that was previously specified in the WPP_DEFINE_GUIDS statement that appears in your h file. For example, you might enable tracing for the driver’s PnP path (corresponding to our example above) with trace data logged to the c:\windows\ directory as follows:

D:\>tracelog –start MyDrv –guid g.txt –f c:\windows\drv.etl –flags 0x01

In the example above, we have previously stored the GUID value, expressed in “registry format” (hyphen separated fields, but minus the curly braces provided by the guidgen utility), in the file named g.txt.  This keeps us from having to try to type the GUID on the command line.  There are a ton of options available with tracelog.  Check out tracelog –help for a list.

After you’ve put your driver through its paces, you can stop tracing:

D:\>tracelog –stop MyDrv

All that’s left to do is render the trace output file into human-readable format.  This is done using the tracefmt utility.  This utility takes as input the tmf files you generated from your pdb file, and the binary log file created by your driver, and outputs a text file.

The easiest way to run tracefmt is to collect the tmf files generated by tracepdb into a single directory, and then run tracefmt as follows:

D:\>tracefmt –p d:\mytmf –o MyDrv.txt c:\windows\drv.etl

The command above causes tracefmt to read the event trace log file named c:\windows\drv.etl, interpret it using the tmf files stored in the directory d:\mytmf, and output a human readable text file of the trace messages into MyDrv.txt in the current directory.

Tracing and the Debugger

You can send trace output to the debugger, just like with DbgPrint().  To do this, use the command:

            !load wmitrace.dll

You can find out information about the command supported by the debugger extension, by typing the command:

            !wmitrace.help

You’ll get the results shown in Figure 3.

And That’s Just the Beginning

Believe me, folks, we’ve barely even scratched the surface of the capabilities of Event Tracing for Windows in this article.  For example, we haven’t discussed how to create Windows 2000 compatible tracing in your driver (you can… it’s not that hard).  Nor have we discussed how to use some of the more advanced features.  Or how to start tracing at boot time. Or a cool new tool that might be coming in the future to make it even easier to view your trace output [EDITORS: This new tool is TraceView and it shipped in the Windows Server 2003 DDK.  Click here to check out the follow-on article from The NT Insider that describes this tool].  That’ll all have to wait for another issue.  But in the mean time: Happy Tracing!

(The NT Insider is grateful to Rob Green for his comments on C++ tracing resulting in updates)