Использование 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 файлы фалы, 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 =
    { 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 доступны тут.

Счастливой охоты отладки.
Поделиться публикацией
Комментарии 5
    0
    Все прекрасно с этой технологией, очень граммотно продумана система системных буферов и тд, но вот фронтэнд ужасен… мы долго с ним воевали, в итоге родился вот такой проект
    habrahabr.ru/post/156817/
    Правда работодатель сделал стойку (о ужас это же Opensource !!!) и проект сейчас в летаргическом сне по целому ряду причин.
      0
      Я наткнулся на твой проект, когда писал пост. TraceView конечно очень кривая утилита, интересно было бы узнать как разработчики драйверов в MS используют WPP. Я хотел посмотреть может ли ваш Baical с локальными etl работать…
      У вас интересно получилось, но отправлять TMF файлы и следить за их обновлением мне не нравится. Я бы искал pdb файл на стороне сервера, а по сети пересылал бы etl данные. Так можно бы разные версии клиентов разруливать.

        0
        Байкал не работает с etl файлами всилу сбойности движка их пищущих (иногда может пропасть хэдер и привет hexeditor).
        Мы пошли по другому пути — Ангара открывает сессию ETW и читает данные прямо из памяти (на лету их сортируя эти данные, т.к. в памяти и внутри etl они не сортированы) на локальном компьютере, далее эти данные могут быть переданы по сети уже куда угодно в живом времени, для отладки когда может упасть система целиком — очень подходящее решение, так же подходит когда отлаживаются/тестируются несколько устройств/программ — централизированный сбор информации.
        На счет TMF-ок — все просто, в пост билд шаг включена автоматическая их геренация и руками ничего делать не нужно, все складывается в нужном месте.
        В итоге мы пошли дальше и заменили ETW там где могли на P7 — скорости сопоставимые, но последний кроссплатформен
          0
          Битые ETL это весомый аргумент. Но в основном на XP такая засада.

          А вы не пробовали воспользоватся возможностью Windows Event Collector перенаправлять данные на удаленную машину?
            0
            К сожалению не дошли руки, все завертелось вокруг кросс-платформенности и уже было не до этого, встал вопрос как сделать очень быстрые трейсы для очень медленных устройств :-) в итоге ETW остался только внутри высоконагруженных драйверов под Windows, а все остальное переехало на P7.
            Почитал немного про Windows Event Collector
            Похоже это для админов технология (EventLog) и высокие нагрузки/скорость не входит в приоритеты при ее разработке, хотя могу и ошибаться.
            Битые ETL это весомый аргумент. Но в основном на XP такая засада.

            Могу ошибаться конечно, но кажется мы с этой бедой и под 7-кой сталкивались, нужно было только слать на 500 сообщений в сек., а скажем тысяч 50… давно уже это было :-)

    Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

    Самое читаемое