WPP Tracing in Visual C++ 2010 Projects

A developer's troubleshooting tool chest should contain as many tools as possible to help isolate hard-to-diagnose issues. Often, when our tools are not effective in pinpointing the issue, we rely on instrumentation in the form of debug tracing to gain insight on what is happening. However, timing of events is usually critical in reproducing some issues, and introducing trace output to the debugger, a file, or a console window drastically affects the timing. In those cases, we need a tracing mechanism that is fast enough so that it does not alter timing significantly or degrade system performance. Enter the Windows software trace preprocessor (WPP).

WPP software tracing was introduced with Windows 2000. In some documentation, you may see it referred to as legacy Event Tracing for Windows (ETW) tracing, but that does not imply that you should avoid it. Starting with Windows Vista, the ETW API was enhanced and ETW was integrated with the event viewer, allowing components to log administrative, operational, and analytic events, which are defined in manifests. WPP tracing, on the other hand, allows a more free-form style of tracing germane to debugging and diagnostic support. WPP tracing has the following benefits:

WPP ETW tracing falls under the umbrella of Windows Management Instrumentation (WMI). Unfortunately, WPP tracing is not documented clearly in the Windows SDK. Instead it is targeted for driver use and is documented in the Windows Driver Kit (WDK), although it is perfectly usable from user mode applications. In fact, one can build user mode applications using the WDK; however, the facilities for doing so are severely limited when compared to Visual Studio.

Inserting WPP Tracing into Your Application
I've created an empty MDI MFC application named TraceWppSample using the wizard in Visual Studio 2010 to show how you can use WPP to trace Windows messages passing through the application class's message pump. ETW consists of three main components: providers, controllers, and consumers. TraceWppSample contains a provider, which is identified by a GUID. To declare a new provider within TraceWppSample, I added a new header to the project named TraceDefs.h that contains the macro shown in Figure 1, which is documented in the WDK.

Figure 1: Declaring a new provider in the TraceWppSample application

#define WPP_CONTROL_GUIDS 
    WPP_DEFINE_CONTROL_GUID(CtlGuid,(28EE579B, CF67, 43b6, 9D19, 8930E7AAA131),  
        WPP_DEFINE_BIT(WINDOWS_MESSAGE) )

This defines both the GUID for the provider, and the valid flags that can be enabled when collecting traces from this provider. In this case, I have only one flag, named WINDOWS_MESSAGE.

To capture the messages, probably the easiest way is to override the PreTranslateMessage method in CTraceWppSampleApp. Within this method, I have the opportunity to trace the message before it is sent to TranslateMessage and DispatchMessage.

Figure 2 shows my implementation of PreTranslateMessage.

Figure 2: The PreTranslateMessage method

BOOL CTraceWppSampleApp::PreTranslateMessage( MSG* pMsg )
\{
    DoTraceMessage( WINDOWS_MESSAGE, "Windows Message => HWND: 0x%p, MSG: 0x%X, WParam: 0x%p, lParam: 0x%p",
        pMsg->hwnd, pMsg->message, (void*) pMsg->wParam, (void*) pMsg->lParam );

    return CWinAppEx::PreTranslateMessage( pMsg );
\}

The call to DoTraceMessage is what logs the WPP message. Notice that the message text is free-form and similar to printf syntax, which is certainly desired for diagnostic tracing. Also, notice the lack of #ifdef DEBUG phrases since this diagnostic logging gets built into release builds. Finally, notice that I am passing the WINDOWS_MESSAGE flag while logging this trace message.  If I had defined multiple flags for this provider, I could have passed any one of the defined flags.

Next, I have to #include the necessary headers near the top of TraceWppSample.cpp, as follows:

#include "TraceDefs.h"
#include "TraceWppSample.tmh"

The first line includes the header containing the defined previously provider. The second line is generated by the WPP processor, which I will cover in the next section.

Finally, I must invoke WPP_INIT_TRACING at the top of CTraceWppSampleApp::InitInstance and WPP_CLEANUP near the end of CTraceWppSampleApp::ExitInstance. These are necessary to initialize the provider. Although the WPP_INIT_TRACING documentation in the WDK shows WPP_INIT_TRACING taking two parameters when used in drivers, it only requires a single string parameter when invoked from a user mode application, as in the following example:

WPP_INIT_TRACING( L"TraceWppSample" );

Note: It's important that all the pieces I've just discussed be in place before you invoke the tracewpp.exe processor. If the source files are changed in any way, tracewpp.exe must process them again.

The Tracewpp.exe Processor
You can see from the previous section that adding WPP tracing to an application's code is fairly easy. However, getting it to work as expected requires some extra steps. The first order of business is to generate the Trace Message Header (TMH) files using the tracewpp.exe processor provided with the WDK. To do so, you must have the WDK (which you can download here) installed alongside Visual Studio. On my 64-bit machine, the tracewpp.exe tool is located in C:WinDDK7600.16385.0toolstracingamd64.

The tracewpp.exe application requires a few parameters, one of which is the non-trivial configuration file location. In the Windows 7 WDK on my machine, that location is C:WinDDK7600.16385.0binwppconfigrev1. This directory contains complicated and loosely documented WPP configuration information that is essential, but it is not necessary for us to understand exactly how it works. So, to generate the TraceWppSample.tmh file from the project directory containing TraceWppSample.cpp, I can simply execute the command shown in Figure 3.

Figure 3: Command that generates the TraceWppSample.tmh file

C:WinDDK7600.16385.0binx86tracewpp.EXE -cfgdir:C:WinDDK7600.16385.0binwppconfigrev1 -odir:. TraceWppSample.cpp

Later, I will show you how you can automate this into the Visual C++ 2010 build environment.

Now that I have the TMH file, I can continue to build the application normally. In my case, I chose to build the x64 Release target. This produces TraceWppSample.exe and the matching TraceWppSample.pdb symbol file, which contains the private symbols and the trace messages from the DoTraceMessage calls in the code. How does this magic work?

If you take a look at the TMH file, you'll see that it is full of generated macros, among other things. Buried deep inside of the file, you will find usage of an undocumented compiler intrinsic __annotation. By using this intrinsic, one can annotate specific locations of the code, and those annotations end up in the PDB file after the link phase.

Collecting a Trace
Now that I have my TraceWppSample.exe application and the matching PDB, I want to trace some messages. The first thing you must do is process the PDB using tracepdb.exe, which is also included in the WDK. Therefore, I went to my x64Release subdirectory in my project and executed the following command:

tracepdb.exe -f TraceWppSample.pdb

This produced two files: a Managed Object Format (MOF) file and a Trace Message Format (TMF) file. The MOF file must be registered with the WMI subsystem so that an ETW controller can start a trace collection. I registered it using the MOF Compiler (mofcomp.exe), as follows:

mofcomp.exe TraceWppSample.mof

The TMF file is the file containing all the extracted messages from the annotations stored in the PDB. You will need the TMF file to translate the resultant ETL files collected during tracing. If you are a library writer and third parties consume your library, you can release the TMF for troubleshooting purposes without having to release your private symbols.

There are quite a few ETW controllers available, and you can even write your own. Some of the more popular ones include tracelog.exe, logman.exe, and xperf.exe. In this example, I will use tracelog.exe provided with the WDK. Each tool comes with its own command-line options and documentation. But in general, you will always need to create an event log session and tell the session which providers you're interested in listening to.

To start a tracing session, I used the command shown in Figure 4.

Figure 4: Starting a tracing session

tracelog.exe -start MyTrace -guid #28EE579B-CF67-43b6-9D19-8930E7AAA131 -f MyTrace.etl -flags 0xffff

This creates a new logging session named MyTrace listening for messages from the provider identified by the GUID shown in Figure 4, which is the same GUID given in the WPP_DEFINE_CONTROL_GUID declaration in the TraceDefs.h file. The resulting trace is stored in MyTrace.etl, and even though the provider definition declares only one flag bit, I have asked the session to log 16 flags to demonstrate how to do so.

Once the trace session is active, simply run the TraceWppSample.exe application for a little while to generate some activity. It is important to note that you can start the trace session at any time whether or not the application is already running. At any time, either before or after closing the TraceWppSample.exe application, I can stop the trace session using the following command:

tracelog.exe -stop MyTrace

After doing so, I will then see an ETL file named MyTrace.etl. Now I am ready to post-process it to generate a human-readable trace. To do that, I use the tracefmt.exe tool and point it at the ETL file as follows:

tracefmt.exe -f MyTrace.etl -o MyTrace.txt

The tracefmt.exe tool finds the TMH file in the same directory and uses it to produce the MyTrace.txt file, which contains human-readable traces that look like that shown in Figure 5.

Figure 5: Sample trace output

EventTrace
\[4\]220C.1F14::06/23/2010-16:54:18.179 \[TraceWppSample\]Windows Message => HWND: 0x00000000001D039C, MSG: 0x3F, WParam: 0x0000000000000000, lParam: 0x0000000000000000
\[4\]220C.1F14::06/23/2010-16:54:18.179 \[TraceWppSample\]Windows Message => HWND: 0x0000000000380638, MSG: 0x362, WParam: 0x000000000000E001, lParam: 0x0000000000000000

Automating WPP into Visual C++ 2010
Starting with Visual C++ 2010, the IDE builds projects using the msbuild engine. Msbuild has been around since the release of the .NET Framework and is a highly extensible XML-based build environment. I highly encourage you to dig into the msbuild documentation if you're unfamiliar with msbuild. My goal was to make it extremely easy to add WPP support to Visual C++ projects. To do so required some knowledge of how msbuild works, which unfortunately, I cannot dig into deeply in this article. Essentially, there are two tasks at hand:

The most parametric way to tell the build system where the WDK tools live is via the user properties files, which are consumed by Visual C++ 2010 project files. These are msbuild XML files that reside in the current user's profile. On my machine, they are in the directory C:UserstnashAppDataLocalMicrosoftMSBuildv4.0. You will see one for each platform.

I modified the Win32 and x64 variants on my machine to look like the example shown in Figure 6.

Figure 6: Modified msbuild XML

xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  
    C:WinDDK7600.16385.0     
    c:userstnashdocumentsVisual Studio 2010MsBuildImports
  
 This defines the variable $(WdkDir), which is used later when invoking the WDK tools. You can also see the $(MyTargetsDir) variable defined in Figure 6. I'll have more to say about this shortly. You may have to modify these paths appropriately for your environment.

Now I need now what's called an msbuild target that contains the necessary information on how to build the TMH files. An msbuild target is conceptually similar to an nmake target in that it has dependencies and contains the instructions to execute in order to generate the target's results. I could have simply added the new target to the TraceWppSample.vcxproj file; however, I want it to be reusable. This is where the $(MyTargetsDir) variable comes in. This is a directory in which I like to place reusable msbuild nuggets. In that directory, I created the file Wpp.targets, which looks like the example shown in Figure 7.Figure 7: Wpp.targets file


xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
  
      $(ExtensionsToDeleteOnClean);*.tmh
  
  
      
          *.tmh
     
  
  
    
  
        Outputs="@(TraceWppSources -> '%(Filename).tmh')">

    
    
  

This defines the target named TraceWpp, which is required to execute prior to the ClCompile target that is defined by the Visual C++ build environment. The TraceWpp target's inputs include all the compiled sources—in this case, .cpp files minus stdafx.cpp, and its outputs consist of a TMH file generated for each .cpp file. Additionally, there is information included in Wpp.targets so that the predefined Clean target can clean the files as necessary.

Note: I designed the Wpp.targets file in Figure 7 for the sake of this article in the spirit of being reusable. That said, it has not been tested with larger and more complicated projects and may require some further tweaking.

Finally, all I have to do at this point is import the Wpp.targets file into my vcxproj project file by adding the following line before the closing  tag:


And this is where the $(MyTargetsDir) variable comes into play, since it needs to know where to find my custom .targets files. Once all of this is in place, you can reopen the vcxproj file within Visual Studio and build the project.

Worth the Effort
Although the WPP tracing mechanism has quite a few moving parts, and integrating it into Visual C++ 2010 build projects is challenging, the benefits far outweigh the effort required. Here at Microsoft, just about every component on the platform contains WPP providers that we can use to collect tracing on production systems to help diagnose extremely hard to reproduce problems. I am sure you will agree that WPP tracing is invaluable for those cases where the only reproducible environment is the customer's. Moreover, since the overhead is so low, you can apply these traces liberally throughout your code in a proactive manner such that when a problem rears its ugly head, you are prepared to capture diagnostics. Happy coding!Trey Nash is a senior escalation engineer at Microsoft working on the Windows OSs and various other products. When he is not working feverishly within the bowels of the OS, he is delivering training on .NET platform and kernel mode debugging or playing ice hockey.