Використання WPP Software Tracing в системному програмуванні

Шановний читач,
у своєму проекті ти напевно написав інструмент логування та з успіхом застосовуєш його для аналізу важко діагностованих багів. Але ти завжди стикався із ситуацією:
  • коли запис в файл — консоль драматично позначилася на воспроизодимости бага;
  • коли мульти(процесорний/потокове) додаток часто звертається до драйвера і ти не можеш порівняти часові мітки і потоки;
  • коли баг відтворюється на стороні кастомера, сеанс teamviewer марний, та до того ж версія з налагоджувальні символами private;
  • коли системне додаток падає до того, як система встигне скинути логування на диск;
  • або коли макрос для логування виглядає в кращому випадку як
    #define TraceDbg(format, ...) \
    printf( "(p %d, t %d) - (%s,%d) %s(): " format, GetCurrentProcessId(), GetCurrentThreadId(), __FILE__, __LINE__,__FUNCTION__, __VA_ARGS__ );
    
  • коли придумуєш черговий спосіб вивести на екран ipaddr або UUID
У статті я представлю швидкий, надійний і універсальний для налагодження з мінімальним оверхедом інструмент діагностики, пропонованої MS для системних додатків — WPP, розглянутий частково в публікації «EventTrace for Windows. Високошвидкісна передача налагоджувальних повідомлень драйвера по мережі».

Будучи заснованим на ETW, логування проводиться операційною системою, використовує ідентифікатори подій, не містить якоїсь пропрієтарної інформації та автоматично додає до події системні мітки(час, потік, процес, CPU). WPP логування включено в релізну складання, що дозволяє збирати інформацію з боку кастомера без необхідності перезбирання налагоджувальної версії.

Ключовими термінами в ETW є провайдер — додаток здійснює запис подій, контролер — здійснює контроль налагоджувальної сесії і консьюмер — форматування інформації сесії в читаний формат. Малюнок внизу наочно показує взаємодію компонентів.

image

Перейдемо від слів до практики. В якості прикладу для модифікації візьмемо офіційний приклад сервісу від MS — CppWindowsService і, використовуючи наступні 6 пунктів, розглянемо usecase WPP Tracing.

0. Якщо ви додаєте WPP в драйвер, то починайте читати з 1 пункту, так як новий WDK має в шаблонах проекту надбудови для WPP, параметри яких доступні за посилання . Копіюємо з репозиторію файл властивостей WppTracingSettings.props і підключаємо його в проект вручну, додаючи новий Import тег перед закриттям project:

<Import Project="..\WppTracingSettings.props" />
</Project>

WppTracingSettings.props містить виклик WPP препроцесора(він до речі запускається перед cl.exe так що обертати func в щось інше не вийде) і визначає ім'я проекту, ім'я та параметри макросу логування, а також список файлів — в нашому випадку все крім крім 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>

За основу взята публікація Trey Nash'a.

1. Створюємо tracer.h, де генеруємо GUID провайдера, визначаємо налагоджувальні рівні(зазвичай з evntrace.h) і прапори налагодження. У своїх проектах прапори я використовую для позначення модулів(ініціалізація, процедури диспетчера, логіка тощо):

#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. Инклудим в cpp файли фали, згенеровані WPP препроцесором, викликаємо DllEntry або main WPP_INIT_TRACING для реєстрації провайдера в системі і викликаємо трейс.

#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 надає кілька додаткових форматних спецификаторов, а також створювати свої .

3. Провайдер створений, тепер його необхідно підключити до сесії налагоджувальної інформації. Варто відзначити, що виклик TraceEvent буде мати оверхед тільки одного умовного переходу якщо провайдер не належить ні до однієї сесії в системі.

Використовуючи найбільш підходящий для ситуації контролер, створюємо сесію, використовуючи GUID провайдера або PDB файл. TraceView інтуїтивно зрозумілий — останавливатся на ньому я не буду. А в репозиторії доступні скрипти StartTraceEtl.bat і StopTrace.bat для запуску контролера logman в etl файл. Додати другий провайдер у сесію можна викликом logman update:

logman update testlog-p "{a34f5c45-3569-896c-ba85-bf8dcc85aa62}" 0xffff 0xff-rt-ets-o test.etl

Події кількох провайдерів всередині однієї сесії будуть записані по порядку, кожного запису відповідає Sequence Number. Відкриття записаної сесії test.etl в TraceView на малюнку внизу.

image

4. logman є тільки контролером і не дозволяє форматувати логування на льоту, як TraceView. Якщо необхідно автоматизувати збирання інформації, то можна використовувати наступну послідовність: запускаємо logman з launch_wpp_log.bat потім tracefmt.exe -rt testlog-display-p tmfpath, попередньо згенерувавши tmf файли за допомогою tracepdb.exe. tracefmt дозволяє самому створювати формат виводу на екран через файл конфігурації. Висновок з файлом конфігурації за замовчуванням виглядає наступним чином.

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, використовуючи розширення !wmitrace, але для мене цей метод не працює. Замість цього я використовую додатковий прапор TraceView ->Windbg Trace.

5. TMF файли містять всі рядкові константи трасування, і у випадку, якщо необхідно отримати дані з машини користувача, то Tracefmt відмінно працює і з модифікованими файли tmf файлами.

// 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
{
}

Вихідний код, скрипти і необхідні утиліти WPP доступні тут.

Щасливою полювання налагодження.

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.