OSRLogo
OSRLogoOSRLogoOSRLogo x Seminar Ad
OSRLogo
x

Everything Windows Driver Development

x
x
x
GoToHomePage xLoginx
 
 

    Tue, 17 Oct 2017     115080 members

   Login
   Join


 
 
Contents
  Online Dump Analyzer
OSR Dev Blog
The NT Insider
Downloads
ListServer / Forum
Driver Jobs
  Express Links
  · The NT Insider Digital Edition - May-June 2016 Now Available!
  · Windows 8.1 Update: VS Express Now Supported
  · HCK Client install on Windows N versions
  · There's a WDFSTRING?
  · When CAN You Call WdfIoQueueP...ously

Without A Trace? Event Tracing in Windows


D
id 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:

extern “C” {
                  #include “myfile.tmh”
           
}

Step 3: Initialize tracing in your DriverEntry function, and de-initialize tracing in your Unload function.  These statements do not actually start your driver sending trace messages.  They just make it possible for your driver to send trace messages.

 

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:

 

RUN_WPP=$(SOURCES) \

            -km -dll\

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

 

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:

 

D:\>tracelog -start fred -kd -flag 0xFFFF -ft 2 -rt -guid x.ctl -noproceess -nothread -nodisk -nonet

 

Note that "fred" is the tracer name, the value 0xFFFF are the flags you want to enable, and x.ctl is the name of the control file with your GUID.  The -ft 2 sets the tracing flush timer to 2 seconds, which gives you near real-time output.

 

There’s a debugging extension that ships with the WinDbg package.  This is wmitrace.dll – To load this extension in WinDbg, use the following command from the WinDbg command line:

           

            !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.

 

WMI Tracing Kernel Debugger Extensions

    logdump  [] - Dump the in-memory portion of a log file

    logsave      - Save the in-memory portion of a log file in binary form

    strdump []                   - Dump the Wmi Trace Event Structures

    searchpath                       - Set the trace format search path

    guidfile                     - Set the guid file name (default is 'default.tmf')
    dynamicprint <0|1>                     - Turn live tracing msgs on (1) or off (0). Default on.
 

Figure 3 – Help for wmitrace Debugger Extension

 

Note that using this debugger extension DLL, you can examine and store information from an in-memory log.  This is useful after the system has crashed – You’ll always be able to get your trace data, even the data that didn’t get written to your binary log file.

 

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)

Related Articles
Tracing Update -- New Tracing Features for Windows

User Comments
Rate this article and give us feedback. Do you find anything missing? Share your opinion with the community!
Post Your Comment

"send trace output to the debugger"
the -kd option is not included in the latest tracelog but from reading the generated .tmh files I realized that if you want to write the trace also to the debuger all you have to do is #define WPP_DEBUG KdPrint

the wpp trace function is defined in a way that it sends the log both to WmiTraceMessage and both to WPP_DEBUG if it is defined. I didn't find any documentation for this feature.

very helpfull article, some things are not even documented by microsoft - for example what you have to do in order to make wpp work in c++ drivers.

Rating:
10-Aug-04, Shaha Talmi


Post Your Comments.
Print this article.
Email this article.

Writing WDF Drivers I: Core Concepts
LAB

Nashua (Amherst), NH
15-19 May 2017

Writing WDF Drivers II: Advanced Implementation Techniques
LAB

Nashua (Amherst), NH
23-26 May 2017

Kernel Debugging and Crash Analysis
LAB

Dulles (Sterling), VA
26-30 Jun 2017

Windows Internals and Software Driver Development
LAB

Nashua (Amherst), NH
24-28 Jul 2017

 
 
 
 
x
LetUsHelp
 

Need to develop a Windows file system solution?

We've got a kit for that.

Need Windows internals or kernel driver expertise?

Bring us your most challenging project - we can help!

System hangs/crashes?

We've got a special diagnostic team that's standing by.

Visit the OSR Corporate Web site for more information about how OSR can help!

 
bottom nav links