[Из песочницы] Использование 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 являются провайдер — приложение осуществляющее запись событий, контроллер — осуществляет контроль отладочной сессии и консьюмер — форматирование информации сессии в читаемый формат. Рисунок внизу наглядно показывает взаимодействие компонентов.
Перейдем от слов к практике. В качестве примера для модификации возьмем официальный пример сервиса от MS — CppWindowsService и, используя следующие 6 пунктов, рассмотрим usecase WPP Tracing.
0. Если вы добавляете WPP в драйвер, то начинайте читать с 1 пункта, так как новый WDK имеет в шаблонах проекта надстройки для WPP, параметры которых доступны по ссылке. Копируем из репозитория файл свойств WppTracingSettings.props и подключаем его в проект вручную, добавляя новый Import тэг перед закрытием project:
#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 = 0×00000001 */ \ WPP_DEFINE_BIT (FLAG_TEST) /* bit 1 = 0×00000002 */ \ WPP_DEFINE_BIT (FLAG_OTHER) /* bit 2 = 0×00000004 */ \ WPP_DEFINE_BIT (FLAG_SERVICE) /* bit 3 = 0×00000008 */ \ /* 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 файлы фалы, cгенерированные 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 = { 0×4460b943, 0xd39, 0×4627, { 0xb5, 0×3d, 0×53, 0×29, 0xe4, 0×70, 0xbe, 0×86 } };
// 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 на рисунке внизу.
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 доступны тут.Счастливой охоты отладки.
