WPP Software Tracing Basics

Software tracing is one of the oldest debugging techniques. It provides a convenient and flexible way to generate detailed information about the behavior of a running driver at key points in its operation. Software tracing creates a running log of the driver's operation. You use trace messages to put a variety of useful information into the trace log, such as:

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

This chapter discusses how to implement WPP tracing in a WDF driver to create a trace log that contains a history of driver events. A related source of trace messages is the KMDF log, which is based on WPP.

Chapter 22, "How to Debug WDF Drivers," provides more information on the KMDF log.

Advantages of WPP Software Tracing

Software tracing can be done in many ways. WPP software tracing provides the following significant advantages over other 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 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 in the order in which they occur.

Ability to View 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 and view them later, perhaps on an entirely different computer.

Rich Information

WPP trace messages can include virtually any useful data, including the current driver configuration 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

WPP trace messages are issued in binary format. Because formatting information is stored separately from the driver binary and usually not shipped with the product, it is difficult for an unauthorized person to obtain intellectual property from trace messages or to use them to reverse-engineer the driver.

Easy Migration from Debug Print Statements

If a driver currently uses debug print statements for tracing, WPP can be instructed to convert the debug print calls to trace messages during the build process. This process converts your existing trace instrumentation to a more efficient form without requiring you to rewrite the code.

Inclusion in Shipped Products

WPP software tracing can be included with both checked and free builds, 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 installed drivers in customer systems.

Minimal Performance Impact

WPP trace message calls are executed only when tracing is explicitly enabled by an external controller. If tracing is not enabled, the tracing code is never called and performance is unaffected. Even when tracing is enabled, the performance impact is minor because trace messages are issued in binary format. A separate application handles the time-consuming task of formatting and display. Tracing is especially useful for investigating bugs-sometimes called "heisenbugs"-whose behavior is very sensitive to system performance. These bugs often disappear when you attempt to observe driver behavior by using techniques such as debug print statements, which can slow the driver significantly.

WPP Software Tracing Components

WPP software tracing involves several components. This section provides a brief description of each component and shows how the components work together in a trace session.

Trace Provider

A trace provider is any application, operating system component, or driver that is instrumented for WPP tracing. To trace specific operations, a driver can be separated into multiple WPP trace providers, even within a single source file. This chapter discusses how to instrument a WDF driver as a trace provider.

Trace Controller

A trace provider generates trace messages only when the provider is enabled by a trace controller, which is an application or tool that manages a trace session. Two commonly used trace controllers-TraceView and TraceLog-are included with 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 has defined 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 can only be enabled for a single session.

 Tip  See "Controlling Event Tracing Sessions" in the Platform SDK for a discussion of how to write your own trace controller by using the ETW API-online at http://go.microsoft.com/fwlink/?LinkId=80062.

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 sooner if the buffers become full. Buffers are also flushed automatically when the trace controller stops the trace session. In addition, a trace controller can explicitly flush the buffers, either on demand or at regular intervals. If the system crashes, the buffers are still available, so trace messages are not lost.

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 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. The trace log interleaves messages from the different providers in the order in which they are received. During a session, the trace controller can query and update properties of the trace session and, finally, stop the session.

Tip 

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.

If a trace session is associated with the Windows kernel logger, the trace log includes predefined system events that the operating system generates, such as disk I/O or page fault events. By adding kernel providers to a session, you can produce a single trace log with interleaved trace messages from both driver and kernel providers. This trace log captures the actions of the Windows kernel in relationship to driver events.

Trace Consumer

A trace consumer is an application or tool that receives, formats, and displays a session's trace log. 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 separate trace message format (.tmf) file. Often, a trace consumer also functions as a trace controller.

Figure 11-1 shows how the consumer interacts with the other trace components on a typical system.

Figure 11-1: Software tracing architecture

You can use a trace consumer to view a trace log in two different ways:

• Direct the trace controller to transfer trace messages from the trace session buffers directly to the trace consumer, and then view them in real time.

• Direct the trace controller to write the messages to an event trace log (.etl) file for that session. The trace consumer can be used to read the messages in the file after the session is over, perhaps on an entirely different computer.

Figure 11-1 shows three active trace sessions:

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

  Consumer 1 receives the interleaved messages from both providers in real time.

• Session 3 has a single provider: C.

  The messages are stored in a trace log file and viewed by Consumer 2 after the session is finished.

WPP and ETW

The underlying architecture of WPP software tracing is based on ETW. ETW tracing can be powerful and flexible, but it is also complex to implement. WPP was introduced to simplify and enhance 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 directly.

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

4. Each source file includes an 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, the operating system provides a unified event format that allows applications to log schematized events to ETW for tools, automatic monitoring, and diagnostics components. A Windows Vista ETW API logs these unified events to ETW. This event format defines events by using 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.

Tip 

WPP does not use the Windows Vista ETW 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 this format is useful to components that use the event logs. Components such as EventLog service and Event Viewer can easily use these schematized events to implement discoverability, querying, and filtering capabilities that allow users to quickly focus on the events of interest. The schematized 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.

 Tip  See "Adding Event Tracing to Kernel-Mode Drivers" in the WDK for a discussion of the Windows Vista ETW API-online at http://go.microsoft.com/fwlink/?LinkId=80610. See also the Evntdrv sample in the WDK for an example of how to implement tracing by using the Windows Vista ETW API. The sample is located at %wdk%\src\general\evntdrv.