Механизм трассировки событий для Windows

C# и .NET Framework --- Оптимизация приложений .NET Framework --- Механизм трассировки событий для Windows

Механизм трассировки событий для Windows (Event Tracing for Windows, ETW) - это высокопроизводительный фреймворк регистрации событий, встроенный в Windows. По аналогии со счетчиками производительности, многие компоненты системы и инфраструктура поддержки приложений, включая ядро Windows и CLR, определяют механизмы отправки событий - информации о внутреннем состоянии компонентов. В отличие от счетчиков производительности, которые всегда активны, механизм ETW можно включать и выключать во время выполнения, чтобы накладные расходы на сбор и отправку информации оказывали влияние на производительность, только когда это действительно необходимо.

Одним из богатейших источников информации является провайдер ядра (kernel provider), который генерирует события в моменты запуска процессов и потоков, загрузки DLL, распределения блоков памяти, сетевых операций ввода/вывода и при выполнении трассировки стека. В таблице ниже приводится перечень некоторых наиболее интересных событий, сообщаемых ETW-провайдерами ядра и CLR. Механизм ETW можно использовать для исследования общего поведения системы, например, чтобы выяснить, какой из процессов потребляет большую часть вычислительной мощности CPU, проанализировать узкие места в операциях ввода/вывода, получить статистику, касающуюся работы сборщика мусора и использования памяти управляемыми процессами, и во многих других случаях, обсуждаемых далее.

События ETW несут в себе точное время их возникновения, могут содержать дополнительную пользовательскую информацию, а также состояние стека на момент их появления. Информация о состоянии стека может использоваться для выявления источников различных проблем. Например, провайдер CLR может посылать события в начале и в конце каждого цикла сборки мусора. Эти события в комплексе с информацией о состоянии стека вызовов можно использовать для выявления частей программы чаще других вызывающих сборку мусора.

Для доступа к этой детализированной информации требуется специализированный инструмент и приложение, способное читать события ETW и выполнять простейший анализ. На момент написания этих строк существовало два инструмента, способных решать обе задачи: Windows Performance Toolkit (WPT, также известный как XPerf), распространяемый в составе Windows SDK, и PerfMonitor (не путайте с Windows Performance Monitor!) - открытый проект, разрабатываемый командой CLR в Microsoft.

Windows Performance Toolkit (WPT)

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

Чтобы установить WPT, загрузите дистрибутив Windows SDK, запустите мастер установки и выберите только Windows Performance Toolkit (Общие утилиты --> Windows Performance Toolkit):

Если вы устанавливаете WPT в Windows 7, то после установки Windows SDK перейдите в подкаталог Redist\Window Performance Toolkit в каталоге установки SDK и запустите мастер установки для своей аппаратной архитектуры (Xperf_x86.msi - для 32-разрядных систем, Xperf_x64.msi - для 64-разрядных систем). Для Windows 8 эти шаги делать не нужно.

В 64-разрядной версии Windows для поддержки возможности трассировки стека необходимо изменить настройки в реестре, запрещающие выгрузку страниц с кодом из оперативной памяти в файл подкачки (для самого ядра Windows и для всех драйверов). Это может увеличить потребление оперативной памяти системой на несколько мегабайт. Чтобы изменить настройки, найдите в реестре ключ HKLM\System\CurrentControlSet\Control\Session Manager\Memory Management, установите параметр DisablePagingExecutive типа DWORD в значение 0x1 и перезагрузите систему.

Для перехвата и анализа событий ETW используются инструменты XPerf.exe и XPerfView.exe. Оба должны запускаться с привилегиями администратора. Утилита XPerf.exe имеет несколько ключей командной строки, с помощью которых можно указать, какие провайдеры должны включаться, размеры используемых буферов, имя файла для сохранения информации о событиях и множество других параметров. Утилита XPerfView.exe анализирует исходную информацию и генерирует графические отчеты на основе информации в файле журнала.

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

Захват и анализ событий ядра с помощью XPerf

В этом разделе предлагается выполнить трассировку событий ядра с помощью XPerf.exe и проанализировать полученные результаты с помощью XPerfView.exe. Данный эксперимент планировался для проведения в версии Windows Vista или выше. (Для его проведения требуется также настроить две системные переменные окружения: откройте панель управления и перейдите в меню "Система", щелкните на пункте "Дополнительные параметры системы" в панели слева и в открывшемся диалоге - на кнопке "Переменные среды" внизу.) Проделайте следующие шаги:

1. Создайте системную переменную окружения _NT_SYMBOL_PATH со значением, включающим путь к общедоступному серверу символов и локальному кешу символов, например: srv*C:\Temp\Symbols*http://msdl.microsoft.com/download/symbols.

2. Создайте системную переменную окружения _NT_SYMCACHE_PATH со значением, включающим путь к локальному каталогу на диске - это должен быть другой каталог, отличный от того, что был указан в качестве локального кеша символов в предыдущем пункте.

3. Запустите с правами администратора командную строку и перейдите в каталог установки WPT (например, C:\Program Files\Windows Kits\8.1\Windows Performance Toolkit).

4. Запустите прием событий из группы Base ядра, содержащие флаги из таблицы выше. Для этого выполните команду: xperf -on Base.

5. Сымитируйте некоторую активность в системе: запустите несколько приложений, попереключайтесь между окнами, попробуйте открыть какие-нибудь файлы - хотя бы несколько секунд. (Все это будет приводить к созданию отслеживаемых событий.)

6. Остановите прием событий и сохраните результаты в файл, выполнив команду: xperf -d KernelTrace.etl.

7. Запустите инструмент анализа, выполнив команду: xperfview KernelTrace.etl ("wpa KernelTrace.etl" - для Windows SDK 8.0 и выше)

8. В появившемся окне вы увидите несколько графиков, по одному для каждого события ETW. Выбор графиков для отображения выполняется в панели слева. Обычно флажки, соответствующие графикам нагрузки на процессоры, находятся в самом верху, а ниже - флажки выбора графиков дисковых операций ввода/вывода, использования памяти и других статистик.

9. Щелкните правой кнопкой мыши на графике нагрузки на процессор и выберите пункт контекстного меню Load Symbols (Загрузить символы). Щелкните правой кнопкой мыши на графике еще раз и выберите пункт контекстного меню Simple Summary Table (Простая сводная таблица). В результате должна появиться таблица со списком методов во всех процессах, проявлявших активность в процессе сбора информации. (Загрузка символов с сервера Microsoft в первый раз может занять продолжительное время.)

Последняя версия Windows SDK (8.0 - 8.1) включает два новых инструмента: Windows Performance Recorder (wpr.exe) и Windows Performance Analyzer (wpa.exe), созданные с целью постепенно заменить инструменты XPerf и XPerfView, описанные выше. Например, команда wpr -start CPU является примерным эквивалентом команды xperf -on Diag, а команда wpr -stop reportfile - примерным эквивалентом команды xperf -d reportfile. Пользовательский интерфейс инструмента WPA несколько отличается, но предоставляет практически те же возможности, что и XPerfView. За дополнительной информацией по новым инструментам обращайтесь по адресу: "What's New in the WPT".

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

Инструмент WPT может пригодиться в самых ситуациях, поможет вникнуть в поведение системы и отдельных процессов. Ниже представлено несколько скриншотов и описаний примеров подобных ситуаций:

• WPT может перехватывать все события дисковых операций ввода/вывода в системе и выводить информацию с привязкой к карте физического диска. Это дает возможность выявить наиболее дорогостоящие операции ввода/вывода, в частности операции, требующие значительных перемещений головок жесткого диска.

  

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

  

• WPT может отображать сводные графики событий разных типов, чтобы проще было выявить корреляцию, например, между операциями ввода/вывода, использованием памяти, нагрузкой на процессор и другими характеристиками.

  

• WPT может отображать сводную информацию о состоянии стеков вызовов (когда утилита приема событий запускалась с ключом -stackwalk) - это дает возможность получить полную информацию о стеках вызовов на момент создания определенных событий.

  

Инструмент XPerfView (или WPA) обладает достаточно широкими возможностями в отображении данных, поставляемых провайдером ядра, в виде удобных графиков и таблиц, но он не обладает столь же широкой поддержкой других провайдеров. Например, мы можем обеспечить трассировку событий от провайдера CLR ETW, но XPerfView не будет создавать графики для различных событий - нам придется самим разбираться в исходных данных трассировки, опираясь на список ключевых слов и событий, перечисленных в документации (полный перечень ключевых слов и событий провайдера CLR ETW).

Если запустить XPerf с провайдером CLR ETW для сбора событий с ключевым словом GCKeyword (0x00000001) и уровнем детализации verbose (0x5), эта утилита послушно будет перехватывать все события, генерируемые провайдером. Сохранив всю полученную информацию в файл CSV или открыв ее с помощью XPerfView, мы сможем (хотя и с трудом) идентифицировать события механизма сборки мусора в нашем приложении.

На рисунке ниже показан пример отчета, созданного утилитой XPerfView, где время между событиями GC /start и GC /stop соответствует протяженности одного цикла работы механизма сборки мусора:

Выделенная строка на этом рисунке - это событие GCAllocationTick_V1, генерируемое после распределения каждых 100 Кбайт памяти. К счастью, этот недостаток был замечен разработчиками базовой библиотеки классов (Base Class Library, BCL) в Microsoft, и они создали открытую библиотеку и инструмент PerfMonitor для анализа трассировочной информации от CLR ETW. Мы рассмотрим этот инструмент далее.

PerfMonitor

PerfMonitor.exe - это открытый инструмент командной строки, созданный командой разработчиков BCL в Microsoft, и доступный на сайте CodePlex. На момент написания этих строк самой последней была версия PerfMonitor 2.01. Главное преимущество PerfMonitor перед WPT заключается в полной поддержке событий CLR и способности выводить информацию о них не только в табличном виде. PerfMonitor способен анализировать события, генерируемые сборщиком мусора и JIT-компилятором, выполнять трассировку управляемого стека и определять нагрузку на процессор, оказываемую различными частями приложения.

Для опытных пользователей в состав PerfMonitor включена библиотека с именем TraceEvent, обеспечивающая программный доступ к событиям CLR ETW и позволяющая автоматизировать анализ событий. Библиотеку TraceEvent можно использовать в собственных приложениях мониторинга для автоматического исследования и регистрации событий, протекающих в ходе эксплуатации системы.

Инструмент PerfMonitor можно использовать для сбора событий ядра или даже событий собственного провайдера ETW (запуская его с ключами /KernelEvents И /Provider), но обычно он применяется для анализа поведения управляемых приложений с использованием встроенных провайдеров CLR. С помощью ключа runAnalyze ему молено указать любое приложение для трассировки, по завершении которого PerfMonitor сгенерирует подробный отчет в формате HTML и откроет его в браузере по умолчанию. (Чтобы создать отчеты, похожие на те, что представлены в этой статье, вам следует ознакомиться с руководством для PerfMonitor - хотя бы с разделом «Quick Start». Для этого выполните команду PerfMonitor usersguide.)

Чтобы произвести запуск PerfMonitor с целью выполнить приложение и сгенерировать отчет, нужно использовать следующую команду (в процессе чтения этой статьи вы можете сами поэкспериментировать с инструментом, запуская с его помощью приложение JackCompiler.exe из папки с исходниками):

perfmonitor runAnalyze perfmonitor JackCompiler.exe

Различные HTML-файлы отчетов, сгенерированные инструментом PerfMonitor, содержат уже обработанную информацию, но вы всегда можете открыть исходные ETL-файлы с помощью XPerfView или любого другого инструмента, способного читать двоичные файлы журналов с событиями ETW. Сводный отчет для примера выше включает следующую информацию (при выполнении эксперимента на вашем компьютере фактические значения могут отличаться):

• статистика использования CPU - на выполнение приложения было потрачено 917 мсек процессорного времени, а средняя нагрузка составила 56.6%. Остальное время было потрачено на ожидание каких-то событий;

• статистика сборщика мусора - общее время работы сборщика мусора составило 20 мсек, максимальный размер кучи сборщика мусора составил 4.5 Мбайт, максимальная скорость выделения памяти составила 1496.1 Мбайт/сек, а средняя пауза между циклами сборки мусора составила 0.1 мсек.

• статистика JIT-компилятора - за время выполнения JIT-компилятором было скомпилировано 159 методов с общим объемом машинного кода 30493 байт.

Погружаясь на более глубокие уровни отчетов можно получить огромное количество полезной информации. В число детальных отчетов использования CPU входят: отчет о методах, на выполнение которых было потрачено больше всего процессорного времени (восходящий анализ), отчет о деревьях вызовов, где было потрачено больше всего процессорного времени (нисходящий анализ), и отдельные отчеты «вызывающий-вызываемый» для каждого метода. Чтобы предотвратить разбухание отчетов, из них исключается информация со значениями ниже определенного порога (1% - для восходящего анализа, и 5% - для нисходящего анализа).

На рисунке ниже представлен пример отчета восходящего анализа, где видно, что тремя наиболее активно используемыми методами являются System.String.Concat(), JackCompiler.Tokenizer.Advance() и System.Linq.Enumerable.Contains():

Здесь колонка «Exc %» - оценка процессорного времени, затраченного только на выполнение данного метода; колонка «Inc %» - оценка процессорного времени, затраченного на выполнение данного метода и всех других методов, которые он вызывает (его поддерево вызовов).

На рисунке ниже представлен пример отчета нисходящего анализа, где видно, что 84.2% процессорного времени было потрачено методом JackCompiler.Parser.Parse(), который вызывает методы ParseClass(), ParseSubDecls(), ParseSubDecl(), ParseSubBody() и так далее:

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

Наконец, отчет о работе JIT-компилятора содержит информацию о времени, затраченном на компиляцию каждого из методов приложения, а также точное время, когда они были скомпилированы. Эта информация может пригодиться, чтобы выяснить, можно ли увеличить скорость запуска приложения - если на этапе запуска приложения значительное время тратится на работу JIT-компилятора, предварительная компиляция приложения (с помощью NGen) может оказаться существенной оптимизацией. Применение NGen и другие стратегии уменьшения времени запуска приложения мы обсудим в одной из следующих статей.

В ходе сбора информации от нескольких провайдеров ETW могут получаться очень большие файлы журналов. Например, в режиме по умолчанию PertMonitor генерирует примерно 5 Мбайт данных в секунду. Если оставить инструмент работать на несколько дней, он наверняка исчерпает дисковое пространство даже на очень большом жестком диске. К счастью, оба инструмента, XPerf и PerfMonitor, поддерживают циклический режим журналирования, когда в журнале сохраняется только последние N Мбайт данных. В PerfMonitor максимальный размер файла журнала можно указать (в мегабайтах) с помощью ключа /Circular, при этом все старые файлы будут автоматически удаляться при превышении указанного порогового значения.

PerfMonitor - очень мощный инструмент, однако богатство параметров командной строки и тот факт, что он генерирует отчеты в формате HTML, несколько осложняют его использование. Следующий инструмент, который мы рассмотрим, обладает очень похожей функциональностью и может использоваться в тех же ситуациях, при этом он имеет более дружественный интерфейс и упрощает некоторые исследования проблем производительности.

PerfView

PerfView - бесплатный инструмент, разрабатываемый в корпорации Microsoft, объединяющий в себе функции сбора информации от провайдеров ETW и ее анализа, по аналогии с PerfMonitor, а также средства анализа динамической памяти, которые будут обсуждаться в следующей статье, во время знакомства с такими инструментами, как CLR Profiler и ANTS Memory Profiler. Загрузить PerfView можно по адресу: PerfView. Обратите внимание, что инструмент PerfView должен запускаться с привилегиями администратора, потому что требует доступа к инфраструктуре ETW.

Чтобы проанализировать информацию, полученную при выполнении определенного процесса, выберите пункт меню Collect --> Run в PerfView (на рисунке ниже показано главное окно программы).

В панели со списком файлов (слева) можно видеть дамп динамической памяти и файл с информацией ETW. Ссылки в центральной области окна ведут к разным командам, поддерживаемым инструментом.

Для нужд анализа распределения динамической памяти, который мы вскоре выполним, в исходниках к этой статье включено приложение MemoryLeak.exe. Это приложение будет запускаться с помощью инструмента PerfView, который сгенерирует отчеты со всей информацией, доступной в PerfMonitor, и не только, включая:

• простой список событий ETW, полученных от разных провайдеров (например, с информацией о конфликтах в CLR, дисковых операциях ввода/вывода, TCP-пакетах и ошибках чтения страниц);

• сгруппированные участки стека вызовов, где приложение провело больше всего времени, с возможностью настройки фильтров и пороговых значений;

• участки стека вызовов, соответствующие операциям загрузки образов (сборок), дисковым операциям ввода/вывода и операциям выделения памяти (для каждых 100 Кбайт);

• статистика сборщика мусора, включая продолжительность каждого цикла сборки мусора и объем освобожденной памяти.

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

На рисунке ниже изображен пример анализа ссылок на объекты класса Schedule, которые занимают в динамической памяти 31 Мбайт. PerfView благополучно обнаружил, что ссылки на объекты Schedule хранятся в экземплярах класса Employee, а экземпляры Employee удерживаются в памяти очередью объектов, готовых к завершению.

Собственные провайдеры ETW

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

До появления версии .NET 4.5, экспортирование информации ETW из управляемых приложений было весьма непростым делом. Необходимо было учитывать массу тонкостей, связанных с определением манифеста провайдера ETW для вашего приложения, созданием его во время выполнения и регистрацией событий. С выходом .NET 4.5, создание собственных провайдеров ETW стало легче некуда. Для этого достаточно унаследовать класс от EventSource из пространства имен System.Diagnostics.Tracing, и вызвать метод WriteEvent() базового класса для вывода событий ETW. Все рутинные операции по регистрации провайдера в системе и форматированию информации в событиях выполняются автоматически.

Ниже приводится пример реализации провайдера ETW в управляемом приложении:

using System;
using System.Diagnostics.Tracing;
using System.IO;
using System.Linq;
using System.Reflection;
using System.Runtime.CompilerServices;
using System.Text;
using System.Threading;
using System.Threading.Tasks;

namespace PerfomanceOptimization
{
    public class CustomEventSource : EventSource
    {
        public class Keywords
        {
            public const EventKeywords Loop = (EventKeywords)1;
            public const EventKeywords Method = (EventKeywords)2;
        }

        [Event(1, Level = EventLevel.Verbose, Keywords = Keywords.Loop, Message = "Цикл {0} шаг {1}")]
        public void LoopIteration(string loopTitle, int iteration)
        {
            WriteEvent(1, loopTitle, iteration);
        }

        [Event(2, Level = EventLevel.Informational, Keywords = Keywords.Loop, Message = "Цикл {0} выполнен")]
        public void LoopDone(string loopTitle)
        {
            WriteEvent(2, loopTitle);
        }

        [Event(3, Level = EventLevel.Informational, Keywords = Keywords.Method, Message = "Метод {0} Выполнен")]
        public void MethodDone([CallerMemberName] string methodName = null)
        {
            WriteEvent(3, methodName);
        }
    }

    public class Program
    {
        static void Main(string[] args)
        {
            CustomEventSource log = new CustomEventSource();

            for (int i = 0; i < 10; ++i)
            {
                Thread.Sleep(50);
                log.LoopIteration("Главный цикл", i);
            }

            log.LoopDone("Главный цикл");
            Thread.Sleep(100);
            log.MethodDone();
        }
    }
}

Для получения информации из такого приложения можно использовать инструмент PerfMonitor. Запустить с его помощью приложение, произвести сбор

perfmonitor monitorDump myApp.exe

Существует еще один инструмент мониторинга производительности и состояния систем, который еще не упоминался: инструментарий управления Windows (Windows Management Instrumentation, WMI). WMI - инфраструктура контроля и управления (command-and-control, C&C), интегрированная в Windows, но ее рассмотрение далеко выходит за рамки этой статьи. Ее можно использовать для получения информации о состоянии системы (например, о версии установленной системы, версии программного обеспечения BIOS или о свободном пространстве на диске), регистрации интересующих событий (таких как запуск и завершение процессов) и вызова управляющих методов, изменяющих состояние системы (таких как создание сетевых разделяемых ресурсов или выгрузка драйверов).