Using WPP Software Tracing in System Programming
Dear reader,
In your project, you probably wrote a logging tool and successfully use it to analyze hard-to-diagnose bugs. But you always faced the situation:
In this article, I will present a fast, reliable and versatile debugging tool with a minimal overhead analyzer offered by MS for system applications - WPP, discussed in part in the publication “EventTrace for Windows. High-speed transmission of driver debug messages over the network .
Being based on ETW , logging is performed by the operating system, uses event identifiers, does not contain any proprietary information, and automatically adds system tags to the event (time, flow, process, CPU). WPP logging is included in the release build, which allows you to collect information from the customer without the need to rebuild the debug version.
The key terms in ETW are the provider - the application that records events, the controller - controls the debugging session and the consumer - the formatting of the session information in a readable format. The figure below clearly shows the interaction of components.
')
Let's move from words to practice. As an example for modifying, let's take the official example of a service from MS - CppWindowsService and, using the following 6 points, consider the usecase of WPP Tracing.
0. If you add WPP to the driver, then start reading from 1 point, because the new WDK has WPP add-ins in the project templates, the parameters of which are available by reference . Copy the WppTracingSettings.props properties file from the repository and connect it to the project manually by adding a new Import tag before closing the project:
WppTracingSettings.props contains a WPP preprocessor call (by the way, it runs before cl.exe so it wraps func into something else) and determines the project name, the name and parameters of the logging macro, and the list of files - in our case, everything except for stdafx. cpp.
Based on the publication Trey Nash'a .
1. Create tracer.h, where we generate the provider GUID, define debug levels (usually from evntrace.h) and debug flags. In my projects, I use flags to denote modules (initialization, controller procedures, logic, etc.):
2. Including files generated by a WPP preprocessor in cpp, call WPF_INIT_TRACING in DllEntry or main to register the provider in the system and call the trace.
WPP provides several additional format specifiers , and also allows you to create your own .
3. The provider has been created; now it needs to be connected to the debug information session. It is worth noting that a call to TraceEvent will have an overhead of only one conditional transition if the provider does not belong to any session in the system.
Using the controller most suitable for the situation, we create a session using the provider GUID or PDB file. TraceView is intuitive - I won't stop there. And the StartTraceEtl.bat and StopTrace.bat scripts are available in the repository to start the logman controller in the etl file. You can add a second provider to the session by calling logman update:
Events of several providers within one session will be recorded in order, each record corresponds to a Sequence Number. Opening the recorded test.etl session in TraceView in the figure below.
4. logman is only a controller and does not allow formatting logging on the fly, like TraceView. If you need to automate the collection of information, you can use the following sequence: run the logman from launch_wpp_log.bat then tracefmt.exe -rt testlog -display -p tmfpath, after generating tmf files using tracepdb.exe. tracefmt allows you to create a display format yourself through the configuration file. The output from the default configuration file is as follows.
Windbg can also act as a controller using the! Wmitrace extension, but for me this method does not work. Instead, I use the optional TraceView flag -> Windbg Trace.
5. TMF files contain all the string trace constants, and if it is necessary to get data from the user's machine, Tracefmt works fine with modified tmf files.
Source code, scripts and necessary WPP utilities are available here .
Happyhunting debugging.
In your project, you probably wrote a logging tool and successfully use it to analyze hard-to-diagnose bugs. But you always faced the situation:
- when writing to a file, the console dramatically affected the reproducibility of the bug;
- when a multi (processor / stream) application often accesses the driver and you cannot match time stamps and streams;
- when the bug is played on the side of the custom, the teamviewer session is useless, and besides, the version with debugging symbols is private;
- when the system application crashes before the system has time to drop logging to disk;
- or when a macro for logging looks at best as
#define TraceDbg(format, ...) \ printf( "(p %d, t %d) - (%s,%d) %s(): " format, GetCurrentProcessId(), GetCurrentThreadId(), __FILE__, __LINE__,__FUNCTION__, __VA_ARGS__ ); - when you come up with another way to display ipaddr or UUID
In this article, I will present a fast, reliable and versatile debugging tool with a minimal overhead analyzer offered by MS for system applications - WPP, discussed in part in the publication “EventTrace for Windows. High-speed transmission of driver debug messages over the network .
Being based on ETW , logging is performed by the operating system, uses event identifiers, does not contain any proprietary information, and automatically adds system tags to the event (time, flow, process, CPU). WPP logging is included in the release build, which allows you to collect information from the customer without the need to rebuild the debug version.
The key terms in ETW are the provider - the application that records events, the controller - controls the debugging session and the consumer - the formatting of the session information in a readable format. The figure below clearly shows the interaction of components.
')
Let's move from words to practice. As an example for modifying, let's take the official example of a service from MS - CppWindowsService and, using the following 6 points, consider the usecase of WPP Tracing.
0. If you add WPP to the driver, then start reading from 1 point, because the new WDK has WPP add-ins in the project templates, the parameters of which are available by reference . Copy the WppTracingSettings.props properties file from the repository and connect it to the project manually by adding a new Import tag before closing the project:
<Import Project="..\WppTracingSettings.props" /> </Project> WppTracingSettings.props contains a WPP preprocessor call (by the way, it runs before cl.exe so it wraps func into something else) and determines the project name, the name and parameters of the logging macro, and the list of files - in our case, everything except for stdafx. cpp.
<ItemGroup> <TraceWppSources Include="@(ClCompile)" Exclude="stdafx.cpp" /> </ItemGroup> <Target Name="TraceWpp" BeforeTargets="ClCompile" Inputs="@(TraceWppSources)" Outputs="@(TraceWppSources -> '%(Filename).tmh')"> <Exec Command="cd $(ProjectDir)"/> <Exec Command="if not exist tmhs mkdir tmhs"/> <Message Importance="high" Text="Creating tmh"/> <Exec Command="$(BranchRoot)WppTracing\tracewpp.EXE -dll -func:TraceEvents(LEVEL,FLAGS,MSG,...) -p:$(ProjectName) -cfgdir:$(BranchRoot)WppTracing\wppconfig\rev1 -odir:tmhs @(TraceWppSources, ' ')" /> </Target> Based on the publication Trey Nash'a .
1. Create tracer.h, where we generate the provider GUID, define debug levels (usually from evntrace.h) and debug flags. In my projects, I use flags to denote modules (initialization, controller procedures, logic, etc.):
#define WPP_CHECK_FOR_NULL_STRING //to prevent exceptions due to NULL strings #define WPP_CONTROL_GUIDS \ WPP_DEFINE_CONTROL_GUID(SimpleServiceProvider, (c34f5c45, 3569, 896c, ba85, bf8dcc85aa62), \ WPP_DEFINE_BIT(FLAG_INIT) /* bit 0 = 0x00000001 */ \ WPP_DEFINE_BIT(FLAG_TEST) /* bit 1 = 0x00000002 */ \ WPP_DEFINE_BIT(FLAG_OTHER) /* bit 2 = 0x00000004 */ \ WPP_DEFINE_BIT(FLAG_SERVICE) /* bit 3 = 0x00000008 */ \ /* You can have up to 32 defines. If you want more than that,\ you have to provide another trace control GUID */\ ) #define WPP_LEVEL_FLAGS_LOGGER(lvl,flags) WPP_LEVEL_LOGGER(flags) #define WPP_LEVEL_FLAGS_ENABLED(lvl, flags) (WPP_LEVEL_ENABLED(flags) && WPP_CONTROL(WPP_BIT_ ## flags).Level >= lvl) 2. Including files generated by a WPP preprocessor in cpp, call WPF_INIT_TRACING in DllEntry or main to register the provider in the system and call the trace.
#include "tracer.h" #if defined(EVENT_TRACING) #include "tmhs/(I'm a filename).tmh" #endif void Sample(void) { // {4460B943-0D39-4627-B53D-5329E470BE86} static const GUID testGUID = { 0x4460b943, 0xd39, 0x4627, { 0xb5, 0x3d, 0x53, 0x29, 0xe4, 0x70, 0xbe, 0x86 } }; // Perform main service function here... TraceEvents(TRACE_LEVEL_INFORMATION, FLAG_INIT, "Test Fromat String %!GUID!", &testGUID); } int wmain(int argc, wchar_t *argv[]) { WPP_INIT_TRACING(NULL); Sample(); WPP_CLEANUP(); return 0; } WPP provides several additional format specifiers , and also allows you to create your own .
3. The provider has been created; now it needs to be connected to the debug information session. It is worth noting that a call to TraceEvent will have an overhead of only one conditional transition if the provider does not belong to any session in the system.
Using the controller most suitable for the situation, we create a session using the provider GUID or PDB file. TraceView is intuitive - I won't stop there. And the StartTraceEtl.bat and StopTrace.bat scripts are available in the repository to start the logman controller in the etl file. You can add a second provider to the session by calling logman update:
logman update testlog -p "{a34f5c45-3569-896c-ba85-bf8dcc85aa62}" 0xffff 0xff -rt -ets -o test.etl Events of several providers within one session will be recorded in order, each record corresponds to a Sequence Number. Opening the recorded test.etl session in TraceView in the figure below.
4. logman is only a controller and does not allow formatting logging on the fly, like TraceView. If you need to automate the collection of information, you can use the following sequence: run the logman from launch_wpp_log.bat then tracefmt.exe -rt testlog -display -p tmfpath, after generating tmf files using tracepdb.exe. tracefmt allows you to create a display format yourself through the configuration file. The output from the default configuration file is as follows.
Setting RealTime mode for testlog Examining C:\Users\user\Desktop\wpp\sample\WppTracing\default.tmf for message formats, 3 found. Searching for TMF files on path: C:\Users\user\Desktop\wpp\scripts\tmh [0]08FC.0100::10/15/2014-13:52:43.528 [CppWindowsService]CppWindowsService in OnStart [0]08FC.0F9C::10/15/2014-13:52:45.513 [CppWindowsService]Test Fromat String 175ms 4460b943-0d39-4627-b53d-5329e470be86 [0]08FC.0F9C::10/15/2014-13:52:47.525 [CppWindowsService]Test Fromat String 175ms 4460b943-0d39-4627-b53d-5329e470be86 [0]08FC.0F9C::10/15/2014 Windbg can also act as a controller using the! Wmitrace extension, but for me this method does not work. Instead, I use the optional TraceView flag -> Windbg Trace.
5. TMF files contain all the string trace constants, and if it is necessary to get data from the user's machine, Tracefmt works fine with modified tmf files.
// PDB: ..\Release\CppWindowsService.pdb // PDB: Last Updated :2014-10-10:12:12:25:166 (UTC) [tracepdb] 5ed21a20-2754-8ca0-11c6-9b60845d5180 CppWindowsService // SRC=1.cpp MJ= MN= #typev 1_cpp401 17 "%0Service failed to resume." // LEVEL=TRACE_LEVEL_INFORMATION FLAGS=FLAG_INIT FUNC=1::Continue { } // PDB: ..\Release\CppWindowsService.pdb // PDB: Last Updated :2014-10-10:12:12:25:166 (UTC) [tracepdb] 5ed21a20-2754-8ca0-11c6-9b60845d5180 CppWindowsService // SRC=ServiceBase.cpp MJ= MN= #typev servicebase_cpp401 17 "%0Service failed to resume." // LEVEL=TRACE_LEVEL_INFORMATION FLAGS=FLAG_INIT FUNC=CServiceBase::Continue { } Source code, scripts and necessary WPP utilities are available here .
Happy
Source: https://habr.com/ru/post/247173/
All Articles