Производительность .NET

Диагностика производительности приложений .NET с помощью ETW

Субраманиан Рамасвами

Загрузить образец кода

Вы написали управляемое приложение, и оно медленно работает. С функциональной точки зрения, оно корректно, но его производительность оставляет желать много лучшего. Вы хотели бы диагностировать проблемы с производительностью и устранить их, но ваше приложение выполняется в производственной среде, где нельзя устанавливать средства профилирования и вообще что-либо прерывать. Или, наоборот, ваше приложение используется не настолько широко, чтобы стоило покупать Visual Studio Profiler для профилирования использования процессора.

К счастью, Event Tracing for Windows (ETW) снимает остроту подобного рода проблем. Это мощная технология мониторинга и протоколирования, встроенная во многие части инфраструктуры Windows, и она используется в Microsoft .NET Framework 4 CLR для упрощения профилирования управляемых приложений. ETW собирает общесистемные данные и профилирует все ресурсы (процессор, диск, сеть и память), что делает ее крайне полезной для получения целостной картины. Более того, экосистему ETW можно настроить так, чтобы она создавала минимальные издержки, и благодаря этому она подходит для диагностики в производственных средах.

Цель этой статьи — дать вам представление об эффективности применения ETW для профилирования ваших управляемых приложений. Я не намерен охватить все — целый ряд системных диагностических событий и событий CLR ETW останется за бортом. Но вы увидите главное:как с помощью экосистемы ETW можно кардинально повысить производительность и улучшить функциональность управляемого приложения. В качестве отправной точки для диагностики управляемого кода на основе ETW я продемонстрирую пример анализа, используя свободно доступную ETW-утилиту PerfMonitor; ее можно скачать по ссылке bcl.codeplex.com/releases/view/49601.

PerfMonitor

PerfMonitor позволяет легко и быстро собирать ETW-данные по производительности и генерировать полезные отчеты. Она не является заменой инструментам для более глубокого анализа, таким как Visual Studio Profiler; скорее она предоставляет вам обзор параметров производительности приложения и позволяет выполнять их быстрый анализ.

Есть и другая бесплатная утилита для ETW-диагностики — XPerf, которая доступна в Windows Performance Toolkit. Однако, хотя XPerf является отличным средством для профилирования неуправляемого кода в Windows, в нем все же нет особой поддержки профилирования управляемого кода. PerfMonitor, с другой стороны, обеспечивает все возможности для профилирования управляемого кода с применением ETW. PerfMonitor позволяет собирать информацию о символах, сопоставленных с кодом исполняющей среды .NET Framework, что делает ее ценной для анализа производительности .NET Framework, хоть и не поддерживает столь глубокого анализа как XPerf.

PerfMonitor — самодостаточная утилита; ее вполне достаточно для профилирования и диагностики управляемого приложения. Единственное требование заключается в том, что вы должны работать, как минимум, в Windows Vista или Windows Server 2008. PerfMonitor является утилитой командной строки, и, набрав PerfMonitor.exe usersGuide, вы получите обзорную справку. Если у вас есть заказчик, программу которого вам нужно диагностировать в производственных условиях (например, на производственном сервере), то от вас потребуется лишь скопировать файл утилиты на эту машину — и все, вы готовы к сбору профилей. Профили можно анализировать в автономном режиме.

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

PerfMonitor помогает быстро получить «снимок» всего, кроме масштабируемости, а также дает достаточно информации для более глубокого анализа с помощью других, более специализированных инструментов. Например, для диагностики проблем с GC-кучей в CLR лучше подходит CLRProfiler. Однако PerfMonitor почти моментально информирует о наличии проблемы, а дальше вы можете использовать другие средства. В некоторых случаях, как вы вскоре увидите, PerfMonitor сам указывает на причину проблемы и содержит всю информацию, необходимую для устранения ошибки. Прочитайте статью «Memory Usage Auditing for .NET Applications» из рубрики «CLR с изнанки» (msdn.microsoft.com/magazine/dd882521), в которой обсуждается важность аудита использования памяти вашим приложением и планирование производительности. Расширяя эту философию, PerfMonitor позволяет быстро проводить аудит многих аспектов производительности управляемой программы — не только памяти.

Пример анализа: CsvToXml

Программа-пример, которую я буду диагностировать с применением ETW, преобразует CSV-файл в XML-файл. Ее исходный код наряду с пакетом решения (и пример входного CSV-файла, data.csv) можно скачать по ссылке code.msdn.microsoft.com/mag201012ETW. Для запуска программы введите команду CsvToXml.exe data.csv output.xml.

Как и многие программы, CsvToXml была «сшита на скорую руку», и никто не предполагал, что она будет использоваться с большими CSV-файлами. Когда я начал использовать ее на практике, я обнаружил, что она работает слишком медленно. На обработку файла размером 750 Кб уходило целых 15 секунд! Я понимал, что в ней есть какая-то проблема, но без средства профилирования можно было лишь гадать о реальной причине этой проблемы. (Вы в состоянии отловить проблему, просто изучая исходный код?) К счастью, PerfMonitor помогает находить причины проблем.

Трассировка программы и ее просмотр

Первый шаг — быстрый аудит приложения выполнением следующей команды в окне командной строки от имени администратора (ETW собирает общесистемные данные, поэтому нуждается в административных привилегиях):

PerfMonitor runAnalyze CsvToXml.exe data.csv out.xml

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

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

Рис.Анализ производительности для CsvToXml

Отчет показывает, что преобразование формата заняло около 14 секунд, из которых 13,6 секунды были проведены на процессоре со средней нагрузкой на него 99%. Таким образом, проблема завязана на процессор.

Общее время GC и время GC Pause малы, что хорошо; однако максимальная скорость выделения в GC-куче составила 105,1 Мб/с, что избыточно, а значит, нуждается в дальнейшем анализе.

Анализ процессора

Detailed CPU Analysis предоставляет блоки информации по использованию процессора, как показано на рис. 2, и есть три способа чтения данных профиля процессора. Представление Bottom-Up (снизу-вверх) быстро сообщает вам, какие методы расходуют больше всего процессорного времени и должны быть диагностированы первыми. Представление Top Down (сверху-вниз) полезно для понимания того, нуждается ли ваш код в архитектурных или структурных изменениях, и помогает понять общую производительность программы. Представление «вызывающий-вызванный» (caller-callee) указывает зависимости между методами, например, какие методы вызывают другие методы.

Рис. 2. Анализ «снизу-вверх» программы CsvToXml.exe

Как и другие средства профилирования процессора, представления PerfMonitor сообщают вам включающее время (inclusive time) (время, проведенное в конкретном методе с учетом времени в вызываемых им других методах) и исключающее (exclusive time) (время, проведенное в конкретном методе без учета времени в вызываемых им других методах). Если включающее и исключающее время одинаково, работа выполняется внутри данного метода. PerfMonitor также предоставляет график использования процессора (CPU Utilization), который показывает, как использовался процессор данным методом в течение времени. Если задержать курсор мыши над заголовком какой-либо колонки в отчете, то будет показано более подробное ее описание.

Большинство исследований производительности начинают с представления «снизу-вверх», которое содержит список методов с указанием включающего времени (рис. 2). Выбрав такое представление, вы видите, что метод System.IO.File.OpenText в mscorlib использует больше всего процессорного времени. Щелкнув ссылку (имя метода) вы откроете представление Caller-Callee для метода OpenText, где обнаружите, что он вызывается из программы методом CsvToXml.CsvFile.get_ColumnNames и что get_ColumnNames поглощает почти 10 секунд процессорного времени ((рис. 3). Более того, этот метод вызывается из CsvToXml.CsvFile.XmlElementForRow в цикле (сам XmlElementForRow вызывается из метода Main).

Рис. 3. Представление «вызывающий-вызываемый» для get_ColumnNames

Таким образом, создается впечатление, что в этих методах что-то упущено. Изучение кода этих методов приведет вас к причине проблемы, подчеркнутой на рис. 4: файл открывается и разбирается внутри цикла на каждой его итерации!

Рис. 4. Метод ColumnNames вызывается методом XmlElementForRow

public string[] ColumnNames
{
  get
  {
    using (var reader = File.OpenText(Filename))
      return Parse(reader.ReadLine());
  }
}

public string XmlElementForRow(string elementName, string[] row)
{
  string ret = "<" + elementName;
  for (int i = 0; i < row.Length; i++)
    ret += " " + ToValidXmlName(ColumnNames[i]) + "=\"" + EscapeXml(row[i]) + "\"";
  ret += "/>";
  return ret;
}

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

В CSV-файле у всех строк один и тот же формат, поэтому разбирать его для каждой строки нет никакой нужды. Вы можете поместить функциональность ColumnNames в конструктор, как на рис. 5, оставив свойство для предоставления кешированных имен столбцов. Это гарантирует, что файл будет прочитан лишь раз.

Рис. 5. Кеширование имен столбцов для большей производительности

public CsvFile(string csvFileName)
{
  Filename = csvFileName;

    using (var reader = File.OpenText(Filename))
      ColumnNames = Parse(reader.ReadLine());
        
}

public string Filename { get; private set; }

public string[] ColumnNames { get; private set;}

После перекомпиляции мы вновь выполняем предыдущую команду и обнаруживаем, что теперь приложение стало гораздо шустрее:время его выполнения сократилось до 2,5 секунд.

Тем не менее, анализируя данные после исправления, вы заметите, что использование процессора по-прежнему является доминирующим фактором. Вновь смотрим, как и кем используется процессорное время, и видим, что теперь самый жадный до процессорного времени метод Regex.Replace и что он вызывается из EscapeXml и ToValidXmlName. Так как EscapeXml является более дорогостоящим методом (330 мс исключающего времени), проверяем его исходный код:

private static string EscapeXml(string str)
{
  str = Regex.Replace(str, "\"", "&quote;");
  str = Regex.Replace(str, "<", "&lt;");
  str = Regex.Replace(str, ">", "&gt;");
  str = Regex.Replace(str, "&", "&amp;");
  return str;
}

EscapeXml также вызывается в цикле в XmlElementForRow, и это потенциально узкое место. Применение регулярных выражений для таких замен — явный перебор, и использование строкового метода Replace было бы куда эффективнее. Поэтому заменяем в EscapeXml следующее:

private static string EscapeXml(string str)
{
  str = str.Replace("\"", "&quote;");
  str = str.Replace("<", "&lt;");
  str = str.Replace(">", "&gt;");
  str = str.Replace("&", "&amp;");
  return str;
}

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

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

Изучение статистики GC

Статистика GC в PerfMonitor — это быстрый обзор профиля памяти. Как вы, вероятно, помните, я настоятельно советую выполнять аудит использования памяти, и информация, предоставляемая через ETW-события GC, дает «снимок» любых проблем с GC-кучей в .NET. Представление с краткой сводкой использования памяти сообщает вам совокупный размер GC-кучи, частоту операций выделения памяти и время пауз GC. Выбрав ссылку GC Time Analysis на вкладке результатов PerfMonitor, вы увидите детали, относящиеся к сборам мусора (GC), в том числе когда они происходили, сколько времени занимали и др.

Эта информация позволяет определить, нужен ли вам углубленный анализ проблем памяти с применением CLRProfiler или других средств профилирования памяти. Подробное описание отладки GC-кучи с помощью CLRProfiler см. в статье «Profiling the .NET Garbage-Collected Heap» (msdn.microsoft.com/magazine/ee309515).

В случае этой программы ничего проблемного в статистике GC не наблюдается. Частота операций выделения памяти высокая; согласно эмпирическому правилу, эту частоту желательно поддерживать на уровне ниже 10 Мб/с. Однако периоды пауз очень малы. Высокие частоты операций выделения памяти прямо связаны с высокой нагрузкой на процессор, что мы ранее и обнаружили. После исправлений в программе частота этих операций так и осталась высокой, а значит, память выделяется очень часто (вы можете исправить это?). Время паузы GC, равное нескольким миллисекундам, — свидетельство самонастройки и эффективности GC, который поддерживается исполняющей средой .NET Framework. Таким образом, GC в .NET Framework автоматически управляет памятью.

Изучение статистики по JIT-компиляции

Чтобы ускорить время запуска, первым делом смотрите на время, которое уходит на JIT-компиляцию методов. Если это время значительно (например, большая часть времени запуска вашего приложения уходит на JIT-компиляцию), приложение может выиграть от генерации неуправляемого образа (NGen) за счет предкомпиляции сборки и ее сохранения на диске. То есть сборка компилируется JIT-компилятором и сохраняется на диске, что исключает потребность в JIT-компиляции при последующих запусках. Но, прежде чем прибегать к NGen, вам стоит подумать об отложенной JIT-компиляции некоторых методов, чтобы она не влияла на время запуска программы. Подробнее на эту тему см. статью «The Performance Benefits of NGen» (msdn.microsoft.com/magazine/cc163610).

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

Более подробное руководство по ускорению запуска программ доступно в других статьях MSDN Magazine, а ETW-события помогут выявить и устранить узкие места. Есть также несколько JIT-событий, в том числе JIT-событий подстановки (inline), которые позволяют разобраться в том, почему не было выполнено подстановки того или иного метода.

ETW-события CLR в .NET Framework 4

Группа CLR написала статью в блоге по отслеживанию операций загрузки DLL и определению того, требуется ли загружать конкретную DLL при запуске приложения. Этот процесс стал проще благодаря ETW-событиям. Используя ETW-события загрузки модулей, доступные в .NET Framework 4, мы можем узнать, какие модули загружаются и почему. Есть также события выгрузки модулей и др.

Кроме того, в .NET Framework 4 есть несколько других событий, резко упрощающих диагностику управляемых приложений. Эти события кратко описаны на рис. 6. Все события, инициируемые при выполнении, можно записывать командой runPrint утилиты PerfMonitor. Группа CLR также предусмотрела события, позволяющие вам подключать и отключать ETW-профилирование, а на будущее планирует по-прежнему добавлять ETW-события, чтобы еще больше упростить процесс отладки управляемых приложений.

Рис. 6. ETW-события в .NET Framework 4

В каталоге выполнения вы найдете два файла с суффиксом «PerfMonitorOutput»; это файлы журналов ETW. Кроме того, вы увидите файлы с суффиксом «kernel», обозначающим, что в этих файлах содержатся события операционной системы. Данные, собранные PerfMonitor, идентичны данным, используемым XPerf, поэтому вы можете собирать данные и выполнять их простой анализ с помощью PerfMonitor, а для более глубокого анализа тех же данных задействовать XPerf. PerfMonitor-команда merge преобразует ETW-файлы в формат, понятный XPerf.

Заключение

Изучение производительности с применением ETW — процесс простой, но эффективный. Для отладки управляемого кода доступны различные бесплатные инструменты на основе ETW. Я лишь поверхностно рассказал о ETW-событиях, поддерживаемых исполняющей средой .NET Framework. Моей целью было подтолкнуть вас к отладке управляемых приложений с использованием ETW-событий и инструментария. Скачайте PerfMonitor и используйте документацию MSDN по ETW-событиям в CLR, а также читайте блог CLR Perf — это позволит вам ускорить анализ ваших управляемых приложений.

Выражаю особую благодарность Вэнсу Моррисону (Vance Morrison), одному из архитекторов в группе CLR Performance, за помощь в написании этой статьи.

Субраманиан Рамасвами (Subramanian Ramaswamy) — менеджер программ в группе CLR Performance в Microsoft. Получил звание кандидата наук на факультете Electrical and Computer Engineering в Технологическом институте Джорджии (Georgia Institute of Technology).