Tracing and Diagnosability for WDF Drivers - 1

Tracing and Diagnosability for WDF Drivers - 1

Tracing and Diagnosability for WDF Drivers

October 19, 2008

Abstract

Software tracing for drivers is usually based on Event Tracing for Windows® (ETW), a kernel-level facility that logs trace messages for both kernel-mode and user-mode processes. Because ETW can be somewhat complicated to use, most driver developers use the Windows software trace preprocessor (WPP), which simplifies and enhances the process of instrumenting a driver for ETW tracing. This paper discusses how to implement WPP tracing in a Windows Driver Foundation (WDF)driver.

This information applies for the following operating systems:
Windows Server 2008
Windows Vista®
Windows Server® 2003
Windows XP
Windows 2000

References and resources discussed here are listed at the end of this paper.

For the latest information, see:

The information contained in this document represents the current view of Microsoft Corporation on the issues discussed as of the date of publication. Because Microsoft must respond to changing market conditions, it should not be interpreted to be a commitment on the part of Microsoft, and Microsoft cannot guarantee the accuracy of any information presented after the date of publication.

This White Paper is for informational purposes only. MICROSOFT MAKES NO WARRANTIES, EXPRESS, IMPLIED OR STATUTORY, AS TO THE INFORMATION IN THIS DOCUMENT.

Complying with all applicable copyright laws is the responsibility of the user. Without limiting the rights under copyright, no part of this document may be reproduced, stored in or introduced into a retrieval system, or transmitted in any form or by any means (electronic, mechanical, photocopying, recording, or otherwise), or for any purpose, without the express written permission of Microsoft Corporation.

Microsoft may have patents, patent applications, trademarks, copyrights, or other intellectual property rights covering subject matter in this document. Except as expressly provided in any written license agreement from Microsoft, the furnishing of this document does not give you any license to these patents, trademarks, copyrights, or other intellectual property.

Unless otherwise noted, the example companies, organizations, products, domain names, e-mail addresses, logos, people, places and events depicted herein are fictitious, and no association with any real company, organization, product, domain name, email address, logo, person, place or event is intended or should be inferred.

© 2008 Microsoft Corporation. All rights reserved.

Microsoft, Windows, Windows NT, Windows Server, and Windows Vista are either registered trademarks or trademarks of Microsoft Corporation in the United States and/or other countries.

The names of actual companies and products mentioned herein may be the trademarks of their respective owners.

Contents

WPP Software Tracing Basics

Advantages of WPP Software Tracing

WPP Software Tracing Components

WPP and ETW

ETW in Windows Vista

Trace Message Functions and Macros

DoTraceMessage Macro

Message Conditions

How to Convert Standard Debug Print Statements to ETW

Custom Trace Message Functions

How to Support Software Tracing in a Driver

Modify Sources to Run the WPP Preprocessor

UMDF Example: RUN_WPP for Fx2_Driver

KMDF Example: RUN_WPP for the Osrusbfx2 Sample

Include the TMH File

UMDF Example: Including the TMH File

KMDF Example: Including the TMH File

Define the Control GUID and Trace Flags

UMDF Example: Defining the Control GUID and Trace Flags

KMDF Example: Defining the Control GUID and Trace Flags

Initialize and Clean Up Tracing

Initialize Tracing

UMDF Example: Initialize Tracing in DllMain

KMDF Example: Initializing Tracing in DriverEntry

Clean Up Tracing

UMDF Example: Clean Up Tracing in DllMain

KMDF Example: Cleaning up Tracing in EvtCleanupCallback

Instrument the Driver Code

UMDF Example: Adding Trace Message Calls to Driver Code

KMDF Example: Adding Trace Message Calls to Driver Code

Tools for Software Tracing

How to Run a Software Trace Session

Prepare the Driver

View a Trace Log by Using TraceView

How to Create and View a Trace Log File

How to View a Trace Log in Real Time

View Trace Messages in Real Time with WinDbg

View the Frameworks Trace Log by Using the Core Tracing Tools

Best Practices: Design for Diagnosability

Resources

WPP Software Tracing Basics

Software tracing is one of the oldest debugging techniques and provides a convenient and flexible way to generate detailed information aboutthe behavior of a running driver at key points in its operation. It consists of embedding trace message statements in the driver code to record its behavior at various points.Tracing is typically used to determine the location and cause of bugs, but it can also be used for such tasks as profiling how frequently different routines are called.

Software tracing creates a running log of the driver’s operation. You can use trace messages to put a variety of useful information into the trace log, such as:

• Configuration settings.
• The cause of state changes.
• Notification of scavenging or cleanup operations.
• Memory allocations.
• I/O activities, such as request completion or request cancellation.
• Error data.

Software tracing for drivers is usually based on Event Tracing for Windows®bb (ETW), a kernel-level facility that logs trace messages for both kernel-mode and user-mode processes. The messages can be viewed in real time—while the driver is in operation—or retrieved later from log files. Because ETW can be somewhat complicated to use, most driver developers use the Windows software trace preprocessor (WPP), which simplifies and enhances the process of instrumenting a driver for ETW tracing.

This paper discusses how to implement WPP tracing in a WDF driver, using as examples the two WDF drivers for the OSR USB Fx2 learning kit.

• Fx2_Driver is a UMDF version of the driver. It is located under the WDK root folder at: VersionNumber\src\umdf\usb\fx2_driver.
• OsrUsbFx2 is a KMDF version of the driver. It is located under the WDK root folder at: VersionNumber\src\kmdf\osrusbfx2\sys.

Both samples consist of a series of increasingly full-featured versions of the driver, each with its own folder. This paper is based on the final version of the driver, which is located in the “final” folder.

We recommend that you read both sets of examples, even if you are only interested in one of the frameworks. The two samples illustrate somewhat different approaches to implementing WPP tracing, and most of the discussion applies to either framework.

Advantages of WPP Software Tracing

Software tracing can be done in many ways. WPP software tracing provides the following significant advantages over techniques, such as debug print statements:

Dynamic and Flexible Control

You can enable or disable message generation while the driver is running—you are not required to stop and restart the driver or reboot the operating system. You can flag trace messages so that you can choose to observe only a selected subset of the available messages. In addition, you can include messages from multiple sources in the same trace log. For example, you could choose to view messages from a driver plus related operating system components.

Ability to View Messages in Real Time or to Store in a File

In Windows XP and later versions of Windows, you can view WPP trace messages in real time. You can also direct the messages to a trace log file and view them later, perhaps on a different computer.

Rich Information

WPP trace messages can include any data you find useful, such as the current driver configuration, error codes, or the values of key variables. The WPP preprocessor adds the function name, source file name, and line number to each trace message when the project is built. When a trace message is issued, the ETW logging mechanism automatically attaches a time stamp.

Intellectual Property Protection

The driver issues WPP trace messages in binary format. You must have the associated formatting information to make the messages readable. That information is stored separately from the driver binary and is not usually shipped with the product. This feature makes it difficult for an unauthorized person to obtain intellectual property from trace messages or use them to reverse-engineer the driver.

Easy Migration from Debug Print Statements

If a driver currently uses debug print statements for tracing, you can direct WPP to convertthe debug print callsto trace messages during the build process. This process converts your existing trace instrumentation to a more efficient form without rewriting your code.

Inclusion in Shipped Products

WPP software tracing can be included with both checked and free builds of a driver, so product binaries can ship with the tracing code in place. You can use WDK tracing tools in the field to enable and view trace messages on drivers that are installed on customer systems.

Minimal Performance Impact

WPP trace message callsare issued only when tracing is explicitly enabled by an external controller. When the driver is compiled, the WPP preprocessor converts the trace message in your code to the following form:

if (tracing_is_enabled) {

//Call the trace message routine

}

If tracing is not enabled, thetrace message routine is never called and the performance impact is negligible. Even when tracing is enabled, the performance impact on the driver is minor because trace messages are issued in binary format. A separate application handles the time-consuming task of formatting and displaying the messages.

Tracing is especially useful for investigating bugs—sometimes called “heisenbugs”—whose behavior is very sensitive to system performance. These bugsoften disappear when you attempt to observe driver behavior by using techniques, such as debug print statements, which can slow the driver to the point that the bug does not manifest itself.

WPP Software Tracing Components

WPP software tracing involves several components that work together in a trace session:

Trace Provider

A trace provider is an application, operating system component, or driver that is instrumented fortracing. Usually, a driver represents itself as a single trace provider. However, a driver can be separated intomultipleWPP trace providers, even within a single source file.This paper discusses how to instrument a WDF driver as a single trace provider.

Trace Controller

Atrace controller is an application or tool that manages a trace session. A trace provider generates trace messages only if it is enabled by a trace controller. Two commonly used trace controllers—TraceView and Tracelog—are includedwith the WDK tools.

A trace controller can enable multiple providers for a session, including providers from different drivers or system components. When a session has multiple providers, the messages are interleaved in the trace log in the order in which they are received. If a driver defines multiple providers, the trace controller can be configured to enable messages only from selected providers. However, with WPP tracing, different providers from the same driver cannot be enabled simultaneously in more than one session. A driver can contribute trace messages to only one session at any given time, regardless of the number of providers it defines.

See “Controlling Event Tracing Sessions” in the Platform SDK for a discussion of howto write your own trace controller by using the ETW API.

Trace Buffer

The system maintains a set of buffers to store trace messages for each trace session. A trace controller can configure the size of the buffers for a session. Buffers are automatically flushed to the trace log file or trace consumer at a specified interval or when the buffers become full, whichever happens first. Buffers are flushed automatically when the trace controller stops the trace session. However, the trace controller can also explicitly flush the buffers, either on demand or at regular intervals.

Trace Session

A trace session is a time period during which one or more trace providers have been enabled and generate a series of trace messages that are written to a trace buffer. This series of messages is called a trace log. A trace controller starts and configures the session, enables one or more providers, and associates the providers with the session.During a session, the trace controller can query and update properties of the trace session and, finally, stop the session.

If a trace session is associated with the Windows kernel logger, the trace log includes messages associated with predefined system events, such as disk I/O or page faults. The system trace messages are interleaved with driver messages in the order that they are generated, so the trace log captures the actions of the driver in relation to key Windows kernel events.

With WPP, a trace provider can be associated with only one trace session. If a controller enables that provider in another session, the provider is dropped from the original session.

Trace Consumer

A trace consumer is an application that receives, formats, and displays a session’s trace log, either in real time or from a log file. The trace consumer formats trace messages in human-readable format by using instructions either from the provider’s program database (.pdb) symbol file or from a separatetrace message format (.tmf) file. Some trace consumers also function as a trace controller.

Figure 1 shows how trace consumers interact with the other trace components on a typical system.

Figure 1.Software tracing architecture

Figure 1 shows three active trace sessions and two trace consumers:

• Session 1 has no providers or consumers currently associated with it.

A session can exist without either providers or consumers.

• Session 2 has two associated providers: A and B.

The trace controller transfers trace messages from the trace session buffers directly to Consumer 1, which displays the interleaved messages from both providers in real time.

• Session 3 has a single provider: C.

The trace controller writes the messages to a trace log(.etl)filefor that session. They are displayed by Consumer 2 after the session is finished, perhaps on a different computer.

WPP and ETW

WPP software tracing is essentially an abstraction layer over ETW. It simplifies and enhances ETW tracing, especially for drivers that need only lightweight tracing. WPP works in the following way:

1.A driver includes WPP macros in its source code to configure tracing and to generate trace messages.

2.The project's Sources file directs the Build utility to run the WPP preprocessor before the first compiler pass. The preprocessor converts the WPP macros and template files to the code that is required to implement ETW tracing.

3.The WPP-generated code for each source file is stored in an associatedtrace message header(.tmh)file. This file also contains macros that add instructions for formatting trace messages to the driver's PDB file.

4.Each .c or .cpp file includes its associated TMH file. When the source code is compiled, the code in the TMH file is compiled along with it, just like a conventional header file.

ETW in Windows Vista

Beginning with Windows Vista, Windows supports a unified event format that allows applications to use the Windows Vista ETW API to log schematized events to ETW.The event format uses an extensible markup language (XML) manifest file that is later compiled as a resource and attached to the driver binary. Each event has standard metadata information and a variable payload section that can contain a set of simple types or data structures, such as arrays or structures. This information allows trace message consumers to decode the event after it is logged to ETW.

Note:WPP does not use the Windows VistaETW API, but instead logs events by using the earlier version of the ETW API. To use the new Windows Vista features, you must implement tracing with the Windows Vista ETW API.

Logging events in the Windows Vista format is useful for components that use the event logs. Components, such as the Event Log service and the Event Viewer can easily use the schematized events to implement discoverability, querying, and filtering capabilities that allow users to quickly focus on the events of interest. The format also allows event and other messages to be localized. In addition, “self-healing” components like Windows Diagnostic Infrastructure use the schematized event format to monitor for events associated with specific problems. When such an event occurs, if a resolution module is specified, Windows Diagnostic Infrastructure can automatically fix the problem.

See “Adding Event Tracing to Kernel-Mode Drivers” in the WDK for a discussion of the Windows Vista ETW API. For an example that shows how to implement tracing by using the Windows Vista ETW API, see the Evntdrv sample in the WDK at WinDDK\BuildNumber\src\general\evntdrv.