Детальный взгляд на логирование переключение контекста с помощью Event Tracing API для Windows.

В ответ на пост прошлой недели, я получил следущее электронное письмо:

Может быть, я немножко опоздал с вопросом по поводу Вашего недавнего поста, но, на всякий случай, спрошу: Вы имеете какие-либо методы (стратегии) работы с внешней библиотекой, от которой Вы не можете избавиться, и которая нарушает некоторые (или все) принципы написания дизайна API (скорее всего, имеются в виду принципы, рекомендации, которые описаны в предыдущей статье автора. Прим. перев.)? Может, есть какие-то истории? Это расплывчатый вопрос, но я просто спрашиваю о любом опыте (как пользователя) использования API, который действительно запомнился.

— Michael Bartnett

Это напомнило мне то, что, действительно, я всегда хотел детально описать шаги, необходимые для использования плохого API — просто чтобы подчеркнуть насколько ужасно это может быть для разработчика. Я не думаю, что люди, которые разрабатывают API, действительно понимают насколько важно сделать его правильно и насколько много ненужной работы проделывают сотни, тысячи, а иногда и миллионы других разработчиков при неправильной, ошибочной разработке API. Итак, я почувствовал, что достаточно важно написать статью, которая покажет насколько много ненужной работы написанный API может вызвать.

Наверное, это была бы неплохая статья в цикле еженедельного разбора плохих API. Но, поскольку у меня нет времени на что-то подобное и есть возможность разобрать только один API, то возникает наиболее ВАЖНЫЙ вопрос — какой именно API я должен выбрать?

Event Tracing API для Windows

Сейчас отличное время в истории вычислительной техники для написания статьи о плохом API (с другой стороны, можно сказать, что это — самое ужасное время для зарабатывания на жизнь с помощью программирования). Сейчас так много плохого API, что я могу наугад выбрать один API и, скорее всего, найду достаточно проблем, чтобы написать статью из 3000 слов. Но если бы я собирался выбрать одну, отдельную операцию в одном API, то мой выбор кажется разумным среди всех API, которые я когда-либо использовал.

В настоящее время существует очень много API, которые прилагают немало усилий, чтобы попасть в топ-рейтинг «худшие API». Например, CSS, при появлении новой версии, может занять половину мест в рейтинге топ-10 за год. Во времена своей популярности DirectShow, безусловно, доминировал в рейтинге своей эпохи. B новом-же поколении такие новички, как Android SDK, вместе со средствами разработки — демонстрируют реальный потенциал в своей запутанности, так что качество API, при вызове из C++-кода — последняя вещь о которой Вы беспокоитесь.

Но когда я долго и упорно размышлял о том, кто же победитель в «тяжёлой категории плохого API» — нашёлся один настоящий — Event Tracing API для Windows.

Event Tracing API для Windows — это API, который делает что-то очень простое: позволяет любому компоненту системы (включая обычные приложения) уведомлять о «событиях», которые могут быть получены («поглощены») любым другим компонентом. Это система логирования, которая используется для записи производительности и отладочной информации любого компонента, начиная с ядра системы.

Сейчас же, обычно, для разработчиков игр нет причин использовать Event Tracing API для Windows напрямую. Можно использовать такие утилиты как PerfMon для просмотра информации о Вашей игре, такой, например, как сколько рабочих наборов (working set) она использует или насколько интенсивно работает с диском. Но есть одна специфическая вещь, которую предоставляет только прямой доступ к Event Tracing API: возможность отслеживания времени переключения контекста.

Да, если вы имеете достаточно свежую версию Windows (например, 7 или 8), ядро ОС будет логировать все контекстные переключения, включая в них время ЦПУ (CPU timestamp). Вы, фактически, можете соотнести их со своим собственным профилированием в игре. Это невероятно полезная информация (из разряда информации, которую можно получить только напрямую от «железа»). Это причина по которой такие утилиты как RAD, Telemetry могут показывать Вам когда запущенные Вами потоки были прерваны и должны дожидаться, пока потоки самой системы сделают свою работу; что-то, что может быть критически важно для отладки странных проблем с производительностью.

Звучит очень даже неплохо. Я имею в виду, что время переключения контекста — очень значимая информация и даже если API не лучшего качества — это, всё же, очень круто, не правда ли?

Не правда ли?

В первую очередь — напишите пример использования API

Перед тем, как мы взглянем на настоящий Event Tracing API для Windows, я хочу пошагово сделать то, о чём я говорил на лекции на прошлой неделе: сначала написать пример использования. Всякий раз, когда Вы оцениваете качество API, или создаёте новый API, вы всегда, всегда, ВСЕГДА должны начать с написания некоторого кода так, как будто Вы пользователь, который пытается делать вещи, для которых предназначен Ваш API. Если никаких ограничений нет, это единственный способ получить хороший и чистый взгляд на будущее того, как API будет работать. Это было бы «волшебно». И тогда, когда у Вас есть некоторые примеры использования, Можете двигаться вперёд и начать думать о практических проблемах и о лучшем для Вас способе реализаци.

Итак, если бы я был разработчиком без какого либо знания Event Tracing API для Windows, как бы я хотел получить список переключений контекста? Что ж, в голову приходит 2 способа.

Самый простой подход был бы наподобие:

// В начале программы
etw_event_trace Trace = ETWBeginTrace();
ETWAddEventType(Trace, ETWType_ContextSwitch);

// Для каждого кадра
event EventBuffer[4096];
int EventCount;
while(EventCount = ETWGetEvents(Trace, sizeof(EventBuffer), EventBuffer))
{
    {for(int EventIndex = 0;
        EventIndex < EventCount;
        ++EventIndex)
    {
        assert(EventBuffer[EventIndex].Type == ETWType_ContextSwitch);
        // обработать EventBuffer[EventIndex].ContextSwitch
    }}
}

// В конце программы
ETWEndTrace(Trace);

что приведёт к API, который будет выглядеть, например, так:

enum etw_event_type
{
    ETWType_None,

    ETWType_ContextSwitch,
    ...

    ETWType_Count,
};
struct etw_event_context_switch
{
    int64_t TimeStamp;
    uint32_t ProcessID;
    uint32_t FromThreadID;
    uint32_t ToThreadID;
};
struct etw_event
{
    uint32_t Type; // event_type
    union
    {
        etw_event_context_switch ContextSwitch;
        ...
    };
};

struct etw_event_trace
{
    void *Internal;
};

event_trace ETWBeginTrace(void);
void ETWAddEventType(event_trace Trace, event_type);
int ETWGetEvents(event_trace Trace, size_t BufferSize, void *Buffer);
void ETWEndTrace(event_trace Trace);

Это один способ сделать это. Очень простой, элементарный для понимания. Достаточно тяжело ошибиться. Если бы кто-то прошёлся отладчиком, то увидел бы в точности, что происходит и Вы достаточно просто могли бы сказать, что пошло не так.

Однако, я могу представить ситуацию, где критический по производительности код не хотел бы платить за копирование из буфера ядра в Ваш буфер — то что требует этот API (ETWGetEvents должна скопировать события с некоторого внутреннего буфера ОС, так как их нужно взять откуда-то). Версия немножко посложнее будет брать некую отображаемую память с помощью API, которую Вы используете как буфер для чтения:

// В начале программы
etw_event_trace Trace = ETWBeginTrace(4096*sizeof(etw_event));
ETWAddEventType(Trace, ETWType_ContextSwitch);

// Для каждого кадра
etw_event_range Range;
while(ETWBeginEventRead(Trace, &Range))
{
    {for(etw_event *Event = Range.First;
        Event != Range.OnePastLast;
        ++Event)
    {
        assert(Event->Type == ETWType_ContextSwitch);
        // обработать Event->ContextSwitch
    }}
    ETWEndEventRead(Trace, &Range);
}

// В конце программы
ETWEndTrace(Trace);

Всё, что я сделал здесь — это изменил механизм возврата: вместо копирования — указатель на некий блок («ranged pointer» — указатель на некий диапазон. В общем, указатель, который знает, где заканчиваются данные, на которые он указывает. Прим. перев.). В ETWBeginTrace, пользователь передаёт максимальное количество событий, что влияет на размер буфера и ядро выделяет область памяти (в адресном пространстве пользователя), достаточную для указанного колличества событий. Потом система, если она может, пишет напрямую в выделенный буфер и, тем самым, избегает ненужного копирования. Когда пользователь вызывает ETWBeginEventRead(), возвращаются указатели на начало и конец некоторой части памяти для событий. Так как буфер будет обрабатываться как кольцевой буфер, то пользователь ожидает иметь возможность пройтись в цикле по всем полученым событиям в случае, когда событий больше одного. Я добавил вызов «конец чтения», так как некоторые реализации могут требовать от ядра знание о том, какую часть буфера пользователь просматривает, что позволит избежать записи в память, которая активно считывается. Я, на самом деле, не знаю, нужны ли такие вещи вообще, но если Вы хотите получить базовую информацию и дать ядру максимум гибкости для реализации, эта версия, точно, поддерживает больше возможных реализаций, чем версия с ETWGetEvents().

API будет обновлён, например, так:

struct etw_event_range
{
    etw_event *First;
    etw_event *OnePastLast;
};

event_trace ETWBeginTrace(size_t BufferSize);
int ETWBeginEventRead(event_trace Trace, etw_event_range *Range);
void ETWEndEventRead(event_trace Trace, etw_event_range *Range);

Если очень хочется, можно даже поддерживать обе версии чтения событий с помощью одного и того же API — нужно просто разрешить вызов ETWGetEvents(). Также, чтобы дополнить API сообщениями об ошибках, было бы неплохо иметь что-то такое:

bool ETWLastGetEventsOverflowed(event_trace Trace);

чтобы после каждого вызова ETWGetEvents() иметь возможность проверить, а не слишком ли много событий произошло с момента последней проверки?

Каждому своё, но я думаю, что большинство разработчиков не будут иметь никаких проблем с тем API, который я только что предложил. Каждый имеет свои вкусы и я уверен, что каждый заметит что-то, что ему не нравится, но я сомневаюсь, что кто-то скажет, что API — ужасен. API довольно простой и я думаю, что большинство разработчиков смогут легко внедрить этот API в свой код без слишком долгого обдумывания.

Причина, по которой API настолько прост, не в том, что я использовал большой опыт разработки API для того, чтобы утончённо показать своё видение хорошего API. Наоборот. API простой, потому что проблема, для решения которой он предназначен, элементарна. Как переместить данные из одного места в другое, — это, по сути, самая простая проблема для API, которая может возникнуть в системе. Это прославленный memcpy().

Но именно простота задачи позволяет Event Tracing API для Windows сиять. Даже если всё, что нужно сделать — это переместить память из одного места в другое, при использовании этого API возникают все виды сложностей, которые только можно себе представить.

«Запуск» отслеживания

Я не знаю, как кто-либо хочет начать учить, как использовать Event Tracing API для Windows. Может быть, существуют хорошие примеры, обучающие этому, которые я просто никогда не встречал. Мне пришлось соединять кусочки кода, взятые из разнообразных обрывков документации в течении многих часов экспериментов. Каждый раз, когда я выяснял ещё один шаг в общем процессе, я думал: «Подождите, серьёзно ??». И каждый раз Microsoft неявно отвечал: «Серьёзно».

Если я расскажу Вам, как использовать API, то Вы потеряете возможность пережить душещепательный опыт, поэтому я скажу, что если Вы хотите прочувствовать всё сполна — прервите чтение и попытайтесь получить время переключения контекста самостоятельно. Я могу гарантировать, что Вы получите часы безудержного веселья и тревоги. Те из Вас, кто предпочитает сэкономить время, избегая кучи непонятных моментов, — просто читайте дальше.

ХОРОШО, начинаем. Эквивалент моей функции ETWBeginTrace() — это вызов, предложённой Microsoft, StartTrace(). На первый взгляд, она кажется довольно безобидной:

ULONG StartTrace(TRACEHANDLE *SessionHandle, char const *SessionName,
    EVENT_TRACE_PROPERTIES *Properties);

Однако, когда Вы посмотрите на то, что нужно передать на место Properties-параметра, то вещи становятся немножко сложнее. Структура EVENT_TRACE_PROPERTIES, определённая Microsoft-ом, выглядит так:

struct EVENT_TRACE_PROPERTIES
{
    WNODE_HEADER Wnode;
    ULONG BufferSize;
    ULONG MinimumBuffers;
    ULONG MaximumBuffers;
    ULONG MaximumFileSize;
    ULONG LogFileMode;
    ULONG FlushTimer;
    ULONG EnableFlags;
    LONG AgeLimit;
    ULONG NumberOfBuffers;
    ULONG FreeBuffers;
    ULONG EventsLost;
    ULONG BuffersWritten;
    ULONG LogBuffersLost;
    ULONG RealTimeBuffersLost;
    HANDLE LoggerThreadId;
    ULONG LogFileNameOffset;
    ULONG LoggerNameOffset;
};

где, в свою очередь, первый член данных — это также структура, которая разворачивается в следующее:

struct WNODE_HEADER
{
    ULONG BufferSize;
    ULONG ProviderId;
    union
    {
        ULONG64 HistoricalContext;
        struct
        {
            ULONG Version;
            ULONG Linkage;
        };
    };
    union
    {
        HANDLE KernelHandle;
        LARGE_INTEGER TimeStamp;
    };
    GUID Guid;
    ULONG ClientContext;
    ULONG Flags;
};

Беглый взгляд на эту массу странных данных вызывает только вопросы: почему здесь есть такие члены, как "EventsLost" и "BuffersWritten" («количество не записанных событий» и «количество записанных буферов», соответственно, — из документации. Прим. перев.)? Причина в следующем, вместо того, чтобы сделать разные структуры данных для разных операций, которые можно применить для отслеживания событий, Microsoft сгруппировала функции API в несколько групп и все функции в каждой группе совместно используют объединённую структуру для параметров. Поэтому, вместо того, чтобы пользователь получил четкое представление, что подаётся на вход и возвращается из функции, просто смотря на параметры функции — он должен полностью зависеть от MSDN-документации для каждого API, и надеяться, что документация правильно перечисляет, какие именно члены гигантской структуры параметров используются при каждом вызове и когда именно они предназначены для передачи входных и выходных параметров.

Конечно, поскольку существует так много разных способов использовать эту структуру, Microsoft требует, чтобы Вы полностью обнулили этого огромного зверя перед использованием:

EVENT_TRACE_PROPERTIES SessionProperties = {0};

Для функции StartTrace(), если Вы просто хотите получать данный напрямую и не будете логировать их в файл, нужно заполнить некоторые члены. Эти два — имеют некоторый смысл:

SessionProperties.EnableFlags = EVENT_TRACE_FLAG_CSWITCH;
SessionProperties.LogFileMode = EVENT_TRACE_REAL_TIME_MODE;

Член EnableFlags говорит, что мы хотим получить. Мы хотим переключения контекста, поэтому и выставляем этот флаг. А теперь посмотрим, что происходит, когда событий от одного провайдера более, чем 32? Я не знаю, но предполагаю, что Microsoft не был особенно обеспокоен этой возможностью. Но я был, именно поэтому использовал enum в своём предложении, так как он поддерживает миллиарды типов событий. Но, постойте, «32 типа событий должно хватить для каждого» — поэтому Microsoft предложила 32-битное поле флагов. Нет проблем, но это точно признак недалёкого мышления, что приводит к вещам наподобие дублирования функций с Ex-приставкой в конце имени («Ex» — от «Extended» — расширенная версия функции. Прим. перев.).

LogFileMode определяет, хотим ли мы получать события напрямую или же хотим, чтобы ядро записывало их на диск. Так как это абсолютно разные операции, я хотел бы разбить их на вызовы разных функций, но, погодите, мы же имеем одну большую структуру для всего — сбрасываем всё туда.

С этим полем вещи становятся немного странными:

SessionProperties.Wnode.ClientContext = 1;

Что эта запись означает? Что ж, ужасно названное "ClientContext" («КонтекстКлиента». Прим. перев.), на самом деле ссылается на то, в каком виде Вы хотите получить время событий. "TimestampType" («ТипМеткиВремени». Прим. перев.) было бы немножко понятней, но не важно. Настоящее потеха — это простая "1" справа.

Оказывается, есть набор значений, которые ClientContext может принимать, но Microsoft не всегда даёт им имена. Таким образом, Вы просто должны прочитать документацию и запомнить, что 1 означает, что время приходит от QueryPerformanceCounter, 2 значает «системное время», а 3 означает количество циклов ЦПУ.

В случае, если это не очевидно, существует множество причин, почему публично доступный API никогда не должен так делать. В скрытой части реализации, время от времени, я буду поступать подобным образом, в ситуациях, когда, скажем, нужно использовать -1 и -2 для какой-то замысловатой схемы индексации. Но для API, которым пользуются, в буквальном смысле, миллионы разработчиков, Вы всегда должны давать имена своим константам.

Во-первых, это делает код более читаемым. Никто не знает, что такое ClientContext со значением "1", но значение USE_QUERY_PERFORMANCE_COUNTER_TIMESTAMPS — будет кристально ясным. Во-вторых, это делает код доступным для поиска. Никто не сможет нормально поискать «1» в кодовой базе, но USE_QUERY_PERFORMANCE_COUNTER_TIMESTAMPS ищется легко. Возможно, Вы подумаете: «что ж, нет проблем, я поищу ClientContext = 1», но помните, что более сложное использование этого API может включать в себя использование переменных, например, так: ". . .ClientContext = TimestampType;". В-третьих, код не будет компилироваться для последующих версий SDK, где некоторые вещи изменились. Например, если разработчики решили запретить использование USE_QUERY_PERFORMANCE_COUNTER_TIMESTAMPS, они могут удалить определение (#define) этой константы и сделать USE_QUERY_PERFORMANCE_COUNTER_TIMESTAMPS_DEPRECATED. После таких изменений старый код не скомпилируется с новой версией SDK и разработчик посмотрит на новую документацию и, таким образом, увидит, что он должен использовать взамен.

И т.д., и т.д., и т.п.

Возможно, самое раздражающее поле, которое мы должны заполнить:

SessionProperties.Wnode.Guid = SystemTraceControlGuid;

GUID говорит о том, кто пытается отследить события. В нашем случае, мы пытаемся взять данные с лога ядра и SystemTraceControlGuid — глобально определённый GUID, который указывает именно на этот лог. Я уверен, что для этого GUID-а можно было дать название получше, но это незначимая проблема по сравнению с тем фактом, что если Вы попытаетесь собрать эту строчку кода, то увидите, что компоновщик не может найти SystemTraceControlGuid.

Это случается, конечно же, потому что GUID-ы настолько большие, что Microsoft, возможно, не смог найти способ внедрить их в заголовочные файлы (я могу насчитать несколько возможных способов, но, я полагаю, им не понравился ни один из них), итак Microsoft заставляет Вас выбрать один файл в Вашем проекте, в который, заголовочные файлы Windows, внедрят определение GUID-ов. Для того чтобы сделать это, Вы должны написать как-то так:

#define INITGUID  // Заставляет определить SystemTraceControlGuid внутри evntrace.h.
#include <windows.h>
#include <strsafe.h>
#include <wmistr.h>
#include <evntrace.h>
#include <evntcons.h>

Итак, теперь Вы должны осторожно выбрать, где Вы сделаете это — возможно, создадите новый файл в Вашем проекте, где будут находится все GUID-ы — каждый сможет ссылаться на них (или какой-то там ещё бред). В общем, чтобы Вы не смогли определить их дважды.

Но, что бы там ни было, мы почти закончили с заполнением структуры. Всё что нам нужно — это разобраться с параметром SessionName, который мы должны передать как строку, правильно? Так как это просто имя сессии, я предполагаю, что могу просто сделать следующее:

ULONG Status = StartTrace(&SessionHandle,
    "ОтладчикCaseyTownУДИВИТЕЛЬНЫЙДА!!!", &SessionProperties);

потому что это — крутое название сессии, Вы так не считаете?

Но, увы, вещи работают не так. Оказывается, что несмотря на то, что Вы уже указали GUID для SessionProperties, который говорит о том, что ядро является источником событий — Вы, также, должны указать предопределённую константу KERNEL_LOGGER_NAME в качестве имя сессии. Почему? Что ж, это потому что есть маленький сюрприз, который я сохраню для Вас, чтобы Вы могли насладится интригой всего происходящего.

ИТАК, начинаем:

ULONG Status = StartTrace(&SessionHandle, KERNEL_LOGGER_NAME,
    &SessionProperties);

Смотрится неплохо, правильно? НЕПРАВИЛЬНО.

Оказывается, что, несмотря на то, что строка SessionName передаётся вторым параметром — это всего лишь «удобная» особенность. На самом деле, SessionName должна быть внедрена прямо в SessionProperties, но поскольку Microsoft не хочет ограничивать максимальную длину строки-имени, было решено просто идти вперёд и упаковать эту строку после структуры EVENT_TRACE_PROPERTIES. Что означает, что на самом деле, Вы НЕ можете сделать так:

EVENT_TRACE_PROPERTIES SessionProperties = {0};

А должны сделать так:

ULONG BufferSize = sizeof(EVENT_TRACE_PROPERTIES) + sizeof(KERNEL_LOGGER_NAME);
EVENT_TRACE_PROPERTIES *SessionProperties =(EVENT_TRACE_PROPERTIES*) malloc(BufferSize);
ZeroMemory(SessionProperties, BufferSize);
SessionProperties->LoggerNameOffset = sizeof(EVENT_TRACE_PROPERTIES);

Да, всё правильно — каждый пользователь Event Tracing API для Windows должен делать арифметические подсчёты и вручную расположить структуру в упакованном формате. Я соверншенно не представляю, почему имя должно быть упаковано именно таким образом, но уверен, что если Вам нужно, чтобы так делал каждый, то Вы должны предоставить вспомагательный макрос или функцию, которые будут делать правильные вещи для пользователя и уберегут его от понимания Вашей странной логики упаковки данных.

Но, постойте, по крайней мере Вам не нужно копировать имя самостоятельно! Microsoft решила, что функция StartTrace() этого API будет копировать имя в структуру за Вас, так как в конце концов, имя передаётся в качестве второго параметра.

Ну, это красивый жест, но так не принято на практике. Оказывается, что вынужденная передача KERNEL_LOGGER_NAME в качестве SessionName — вместе с GUID-ом — не является, в конце концов, лишней, и это тот сюрпириз о котором я упоминал. Настоящая причина по которой параметр SessionName должен быть выставлен в KERNEL_LOGGER_NAME в том, что Windows разрешает Вам иметь только одну сессию в системе — в общем — сессию, которая читает события из SystemTraceControlGuid. Другие GUID-ы могут иметь несколько сессий, но не SystemTraceControlGuid. Итак, на самом деле, когда Вы передаёте KERNEL_LOGGER_NAME — Вы говорите, что хотите иметь одну, уникальную, сессию, которая может существовать в системе в любое время вместе с SystemTraceControlGuid GUID-ом. Если кто-то уже начал эту сессию — Ваша попытка её запустить — провалится.

Хух, всё становится лучше. Имя сессии — глобально для всей операционной системы и не закрывается автоматически при аварийном завершении процесса, который начал эту сессию. Так, если Вы написали код, который вызывает StartTrace(), но где-то проскочил баг — не важно как — и Ваша программа упала — KERNEL_LOGGER_NAME-сессия будет по-прежнему работать! И, когда Вы попытаетесь запустить Вашу программу снова, возможно после исправления бага, то Ваш попытка вызова StartTrace() завершится с ошибкой ERROR_ALREADY_EXISTS.

Итак, в принципе, вызов StartTrace(), который услужливо скопирует SessionName в структуру за Вас — в редких случаях является первым вызовом, который Вы захотите сделать, в любом случае. Скорее всего, Вы сделаете следующий вызов:

ControlTrace(0, KERNEL_LOGGER_NAME, SessionProperties, EVENT_TRACE_CONTROL_STOP);

Этот вызов завершает любую существующую сессию и последующий вызов StartTrace() будет успешным. Но, конечно же, ControlTrace() не копирует имя сессии так, как это делает StartTrace(), что означает, что, на практике, Вы должны сделать это самостоятельно, так как вызов StartTrace() идёт после вызова ControlTrace()!

StringCbCopy((LPSTR)((char*)pSessionProperties + pSessionProperties->LoggerNameOffset),
    sizeof(KERNEL_LOGGER_NAME), KERNEL_LOGGER_NAME);

Это безумие, но последствия всего этого еще безумнее. Если Вы подумаете о том, что означает иметь только один возможный процесс отслеживания, который который присоеденён к логу ядра, то быстро поймёте, что в игру вступают вопросы безопасности. А что если какой-то другой процесс вызвал StartTrace() для отслеживания лога ядра — как система знает, что наш процесс имеет возможность взять и остановить то отслеживание лога и начать другое с уже нашими настройками?

Ответ смешон — никак. По факту, отслеживание лога ядра полностью доступно для всех — пусть выиграет лучший процесс! Кто-бы ни вызвал StartTrace(), что ж, тот и получает возможность настроить отслеживание лога для себя.

Ну, не совсем. Очевидно, что Вы не хотите, чтобы любой процесс мог украсть отслеживание лога ядра у другого процесса. Поэтому Microsoft решила, что лучшим решением проблемы будет просто запрещение доступа до лога ядра всем процессам, кроме тех, которые имеют права администратора.

Да, именно так — я не преувеличиваю. Если Вы просто хотите получить список переключений контекста, даже если для своего-же процесса, то он должен быть запущен с привелегиями администратора. Все прелести «нажатия-правой-кнопки-запуск-от-имени-администратора». Если Вы так не сделали и просто запустили свой процесс обычным путём, то ваш вызов StartTrace завершится с ошибкой, так как у процесса недостаточно привелегий. (В теории, у Вас есть возможность добавить пользователя в группу «Performance Log Users» и избежать, таким образом, запуск процесса от имени администратора, но я просто говорю это сейчас — на самом деле я не могу вспомнить будет ли это работать для соединений к логу ядра или только для всех остальных типов отслеживания...)

Удивительно, да? Для того, чтобы сделать то, что должно быть эквивалентно вызову 2х обычных функций (ETWBeginTrace() / ETWAddEventType()), мы сделали подсчёт памяти, выделение памяти, освобождение памяти, вычисление отступов, копирование строк, заполнили структуры, использовали не один, а два стиля для глобальных GUID-констант, специально использовали #define перед #include-директивами препроцессора, и требуем, чтобы пользователь запустил наш процесс с полными правами администратора.

Всё это, а мы ещё даже не получили наши события!

«Открытие» отслеживания

Я знаю, что Вы думаете. Вы думаете, что после секции «Запуск отслеживания» должен следовать сбор событий из лога, правильно? Ерунда! Люди, вот в чём суть Event Tracing для Windows. Запуск отслеживания не запускает отслеживание! Оно лишь наполовину запускает отслеживание! Если Вы хотите начать отслеживани по-настоящему, то, все знают, что Вы сначала запускаете его, а потом открываете… с помощью функции OpenTrace():

TRACEHANDLE OpenTrace(EVENT_TRACE_LOGFILE *Logfile);

Что эта функция делает? Ну что ж, оказывется, что «запущеное» отслеживание — это лишь отслеживание, которое собирает события. Оно, на самом деле, не предоставляет никакого способа получить эти события. Если Вы хотите их получить, то Вы должны открыть отслеживание с помощью OpenTrace().

Итак, для того, чтобы вызвать OpenTrace(), мы нуждаемся в EVENT_TRACE_LOGFILE. Конечно, на самом деле, мы не делаем лог-файл, мы просто хотим взять события и то, что мы заполняем что-то с именем «ЛОГФАЙЛ» — немного странно. Но так же, как и для StartTrace(), OpenTrace() — это всё часть семейства функций, которые используют вместе одинаковые параметры-структуры, и, на практике, тот факт, что имя неуместно для наших целей — является наиболее мелкой неприятностью.

Структура EVENT_TRACE_LOGFILE выглядит следующим образом:

struct EVENT_TRACE_LOGFILE
{
    LPTSTR LogFileName;
    LPTSTR LoggerName;
    LONGLONG CurrentTime;
    ULONG BuffersRead;
    union
    {
        ULONG LogFileMode;
        ULONG ProcessTraceMode;
    };
    EVENT_TRACE CurrentEvent;
    TRACE_LOGFILE_HEADER LogfileHeader;
    PEVENT_TRACE_BUFFER_CALLBACK BufferCallback;
    ULONG BufferSize;
    ULONG Filled;
    ULONG EventsLost;
    union
    {
        EVENT_CALLBACK *EventCallback;
        EVENT_RECORD_CALLBACK *EventRecordCallback;
    };
    ULONG IsKernelTrace;
    PVOID Context;
};

Если Вы занервничали, когда увидели слово "Callback" (функция обратного вызова. Прим. перев.) — я также занервничал вместе с Вами. Взятие событий должно быть обычным делом — просто запросить их из памяти. Здесь не долно быть необходимости в функции обратного вызова.

Но, перейдём дальше, EVENT_TRACE_LOGFILE одна из тех гигантских разновидных коллекций-структур и Microsoft просит Вас сначала обнулить её:

EVENT_TRACE_LOGFILE LogFile = {0};

Так как функция OpenTrace() не принимает никаких хендлов, мы должны как-то передать ей способ найти отслеживание, которое мы «запустили» перед этим. Оказывается, это делается обычным сопоставлением строки, поэтому мы передаём имя сессии снова:

LogFile.LoggerName = KERNEL_LOGGER_NAME;

Странно, но на этот раз мы не должны копировать строку в конец структуры. Почему? Кто знает! Разнообразие — это специи жизни, я Вам говорю. Microsoft хочет, чтобы ваша жизнь была острой.

Следующим шагом, мы должны заполнить способ отслеживания, который, на самом деле, является набором флагов:

LogFile.LoggerName = KERNEL_LOGGER_NAME;
LogFile.ProcessTraceMode = (PROCESS_TRACE_MODE_REAL_TIME |
    PROCESS_TRACE_MODE_EVENT_RECORD |
    PROCESS_TRACE_MODE_RAW_TIMESTAMP);

PROCESS_TRACE_MODE_REAL_TIME, насколько я могу сказать, — полностью избыточный флаг, потому что если Вы не укажете имя файла-лога, тогда я не уверен, как Вы сможете получить события. PROCESS_TRACE_MODE_EVENT_RECORD — флаг для совместимости, который говорит Windows, что Вы хотите использовать новую версию EventRecordCallback, а не старую EventCallback (да, верите или нет, этот прекрассный API на самом деле прошёл через несколько ревизий!). И флаг PROCESS_TRACE_MODE_RAW_TIMESTAMP — говорит Windows не перезаписывать настройки ClientContext, которые были переданы в StartTrace(). Я предполагаю, что идея здесь следующая: человек, который запустил отслеживание, возможно, использовал формат времени отличный от "2" и если же Вы хотите "2" — Вы всегда можете иметь "2", когда получаете события. Если же Вы хотели "1" или "3" — что ж… Вам не повезло.

Наконец-то, мы должны указать API нашу функцию, которая будет собирать события:

LogFile.EventRecordCallback = CaseyEventRecordCallback;

И тогда мы, наконец-то, готовы к большому вызову:

TRACEHANDLE ConsumerHandle = OpenTrace(&LogFile);

Перед тем, как мы передвинемся к фактическому получений настоящих событий (Боже упаси!), я хочу, чтобы Вы остановились на минутку и восхитись настоящим великолепием StartTrace() и OpenTrace() функций. Это 2 API, которые являются частью одной и той же системы. Они обе генерируют новый TRACEHANDLE. И каждая из них может завершиться с ошибкой. Они обе принимают имя сессии. Но работают они абсолютно разно. Абсолютно!

Функция StartTrace() возвращает код ошибки типа ULONG и принимает указатель, куда можно записать возвращаемое значение. Функция OpenTrace() напрямую возвращает результат работы, но выставляет его в INVALID_HANDLE_VALUE, если произошла какая-то ошибка. StartTrace() принимает имя сессии в качестве параметра и заставляет Вас выделить память (вместе с параметром-структурой) для того чтобы скопировать переданную строку позже. OpenTrace() принимает указатель на имя сессии и на структуру параметров, но не требует куда-либо копировать переданную строку.

«Обработка» Событий

Мы работали так тяжело и зашли так далеко — было бы неплохо, наконец-то, получить события переключения контекста, не правда ли? Чтобы их получить, мы, конечно же, должны реализовать функцию обратного вызова, которую мы передали в OpenTrace():

static void WINAPI
CaseyEventRecordCallback(EVENT_RECORD *EventRecord)
{
    EVENT_HEADER &Header = EventRecord->EventHeader;

    UCHAR ProcessorNumber = EventRecord->BufferContext.ProcessorNumber;
    ULONG ThreadID = Header.ThreadId;
    int64 CycleTime = Header.TimeStamp.QuadPart;

    // Process event here.
}

К счастью, это всего лишь несколько чтений из структуры и здесь не происходит ничего необычного. События приходят, мы достаём данные и, когда мы хотим что-то делать с ними, — делаем. Но когда эта функция будет вызвана?

Что ж, Windows вызовет её только тогда, когда Вы попытаетесь «обработать» события, которые доступны из открытого уже отслеживания, используя следующий API:

ULONG ProcessTrace(TRACEHANDLE *HandleArray, ULONG HandleCount,
    LPFILETIME StartTime, LPFILETIME EndTime);

Можно использовать эту функцию, передавая хендл уже открытого отслеживания и Windows будет крутить все события, которые она имеет на переданном хендле, вызывая Ваш обработчик для каждого события. Значит, мы закончили? Мы, всего лишь, вызываем эту функцию каждый фрейм нашей игры (или какой-то другой, подходящий, интервал) и собираем урожай событий с помощью нашей функции?

Я боюсь нет, мои друзья, потому что здесь есть маленькая изюминка, которая делает Event Tracing API для Windows более пикантным и ароматным чем его современники: функция ProcessTrace никогда не возвращает управление.

Да, Вы всё верное прочитали. Суть ProcessTrace(), для отслеживания в реальном времени, такова, что она рассылает любые события, которые сейчас доступны, а потом блокирует выполнение и ждёт новых событий. Она блокирует выполнение навечно или пока отслеживание не закроется вручную с помощью CloseTrace(). Это означает, что единственный способ действительно получить события и продолжить выполнение Вашего процесса — создать полностью новый поток, для того чтобы ничего не делать, а просто висеть на ProcessTrace()!

Вы думаете, что я шучу, но я полностью серьёзен. Сначала Вы должны сделать заглушку для потока, который заблочится навсегда при вызове ProcessTrace():

static DWORD WINAPI
Win32TracingThread(LPVOID Parameter)
{
    ProcessTrace(&ConsumerHandle, 1, 0, 0);
    return(0);
}

Потом, после того, как Вы вызвали OpenTrace() — Вы должны запустить этот поток для того, чтобы сделать обработку событий:

DWORD ThreadID;
HANDLE ThreadHandle = CreateThread(0, 0, Win32TracingThread, 0, 0, &ThreadID);
CloseHandle(ThreadHandle);

Это, буквально, единственный способ, который я знаю, для того чтобы получить события фрейм за фреймом для запущенной программы используя Event Tracing API для Windows.

Взгляд на API в целом

Итак, вот оно, дамы и господа: единственный API, который я использовал, который требует повышенных привилегий и преданного пользователя для того лишь, чтобы скопировать блок памяти из ядра к пользователю. Я никогда не видел ничего подобного и никогда больше не увижу. Добавте это к песням о том что-не-нужно-делать вместе с фактическими вызовами API и, я надеюсь — все согласятся, что Event Tracing API для Windows — полностью плохой API сам по себе.

Можно критически оценить этот API, взглянув на принципы, которые я описал на прошлой неделе (ну ладно, 10 лет назад). Например, можно сказать, что требуемый поток и функция обратного вызова для простой передачи памяти — это красный флаг для принципа «Контроль Потока». Можно указать, что здесь нет детализации вовсе и Вы должны делать вызовы функций в точности так, как я описал. Можно сказать о том, что почти все данные и функции собраны в дюжину разных способов, включая такие странности, как требование того, что SessionName должен быть KERNEL_LOGGER_NAME, если GUID — SystemTraceControlGuid.

Но, на самом деле, самый важный урок, который можно вынести с такого плохого API, как этот — «в первую очередь — напишите пример использования API». На лекции я сказал, что это первое и второе правило для дизайна API и я не шутил. Не думая о принципах и погрязнув в детали — обычное упражнение написания того, как API должен выглядеть — всё, что на самом деле нужно было для того, чтобы увидеть все места, где версия от Microsoft-а провалилась. Если Вы оглянетесь и сравните 2 версии (см. часть «В первую очередь — напишите пример использования API». Прим. перев.), то сразу же увидите, насколько усложнённой, подвержённой ошибкам, рассчитаной на использование интуиции разработчика является версия от Microsoft.

От переводчика:
это мой первый опыт перевода статьи — прошу все возмутительные неточности/опечатки/глупости высылать личным сообщением (по возможности).

Так как в жизни получается разрабатывать под Windows, то очень часто слышу, при сравнени API Windows и Linux, что плох только API Windows, а Linux API — почти что идеален — нет никаких проблем. Хотелось бы узнать Ваше мнение. Есть ли такие косяки и в мире Linux API?