Уважаемый читатель,
в своем проекте ты наверняка написал инструмент логирования и с успехом применяешь его для анализа трудно-диагностируемых багов. Но ты всегда сталкивался с ситуацией:
- когда запись в файл — консоль драматически сказывалось на воспроизодимости бага;
- когда мульти(процессорное/поточное) приложение часто обращается к драйверу и ты не можешь сопоставить временные метки и потоки;
- когда баг воспроизводится на стороне кастомера, сеанс 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:
<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)WppTracingtracewpp.EXE -dll -func:TraceEvents(LEVEL,FLAGS,MSG,...) -p:$(ProjectName) -cfgdir:$(BranchRoot)WppTracingwppconfigrev1 -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 на рисунке внизу.
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:UsersuserDesktopwppsampleWppTracingdefault.tmf for message formats, 3 found.
Searching for TMF files on path: C:UsersuserDesktopwppscriptstmh
[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: ..ReleaseCppWindowsService.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: ..ReleaseCppWindowsService.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 доступны тут.
Счастливой охоты отладки.
Автор: antoxar
