Как найти причину «тормозов» с PerfView и dotnet-trace — практика анализа производительности .NET

В предыдущей статье «Журнал событий Windows и ETW» разбиралось, что такое ETW и как через EventSource задать свои события; разбор в PerfView там был вынесен «за рамки». Эта статья — продолжение. Она показывает, как с помощью PerfView и dotnet-trace дойти до конкретной функции, когда бизнес-приложение «тормозит», «ЦП постоянно на максимуме» или «иногда зависает».

Тема статьи — ЦП и время отклика. Как отличить рост памяти от утечки — в «.NET: как отличить ожидание GC от утечки памяти», аварийные завершения — в «Как читать аварийные дампы в WinDbg + SOS».

1. Сначала выводы

• «Тормоза» бывают двух видов: ЦП загружен полностью (CPU-bound) или ЦП свободен, но поток чего-то ждёт (блокировка). Для первого нужно сэмплирование ЦП, для второго — сбор ThreadTime (переключения контекста). Обычный сбор ЦП причину второго не покажет.¹
• Если сомневаетесь, начните с dotnet-trace. Это кроссплатформенный инструмент на базе EventPipe: если вы тот же пользователь, от которого запущен целевой процесс, собрать трассу можно без прав администратора.² Файл .nettrace открывается в PerfView или Visual Studio.³
• PerfView нужен, когда требуется картина по всей машине, нативный код или время блокировки. В основе — ETW, поэтому видны события ядра и нативные стеки. Зато для старта сеанса ETW нужны права администратора.³
• Сэмплирование ЦП по умолчанию идёт раз в миллисекунду (на процессор). Читайте одну выборку как примерно 1 мс времени ЦП и не делайте выводов, пока не наберётся не меньше 1000 выборок, лучше около 5000. Пока выборок мало, функции наверху списка могут оказаться случайностью.¹
• Интерпретация цифр всегда начинается с inclusive (сама функция плюс всё, что она вызвала) и exclusive (только сама функция). Большое exclusive — место, которое реально потребляет ЦП. Большое inclusive — признак, что тяжесть сидит где-то ниже по дереву вызовов.
• До сбора сведите «медленно» к одной конкретной операции. Снимать трассу на фоне «в целом тяжело» почти бесполезно. Сначала закрепите действие и длительность — например, «этот отчёт формируется 40 секунд» — и только потом собирайте. Как сравнивать до и после, разобрано в «Как правильно сравнивать скорость разных версий программы в Windows».

Вход по симптому — в таблице.

На схеме сплошная линия обозначает отношение, которое выполняется всегда, а пунктирная — условное отношение (условия указаны в пояснении к каждому отношению на странице сведений). Полный список отношений (всего 20, с доказательствами и степенью уверенности) и определения основных понятий собраны на странице сведений карты знаний (на японском). Данные: JSON-LD / Turtle

2. Связь инструментов — ETW и EventPipe

Инструментов кажется много, но опорных механизмов два.

• ETW (Event Tracing for Windows): инфраструктура трассировки на всю ОС. Ядро и приложение пишутся на одной шкале времени, зато старт и останов сеанса требуют прав администратора, и это только Windows.³
• EventPipe: механизм трассировки внутри runtime .NET. Права администратора не нужны, на всех ОС ведёт себя одинаково. Видно только управляемый код и runtime: события ядра и нативные стеки он не снимает.²

Когда эта карта ясна, рабочий порядок складывается сам: сначала лёгкий сбор через dotnet-trace, а если его не хватает — полный ETW-сбор в PerfView.

3. Перед сбором трассы — 10 минут на dotnet-counters

Сразу снимать трассу чаще всего рано: быстрее сначала посмотреть основные метрики runtime через dotnet-counters.⁴

dotnet tool install --global dotnet-counters
dotnet-counters ps
dotnet-counters monitor --process-id <PID> --counters System.Runtime

Смотрите загрузку ЦП, размер кучи GC и число сборок, длину очереди и число потоков ThreadPool, число исключений. Уже на этом шаге тенденции вроде «GC запускается несколько раз в секунду» или «очередь ThreadPool всё растёт» подсказывают, какую трассу снимать дальше — на выделения или на блокировки.

Но тому, кто измеряет впервые, не видно, «аномально это или нет». Самый надёжный ориентир — те же команды на своём приложении в нормальном режиме. Пока такой базы нет, ниже — практический взгляд на цифры как первое приближение.⁵

Важнее порога — как значение движется со временем. То, что растёт и падает вместе с нагрузкой и затем выходит на плато, обычно здорово. То, что не возвращается после снятия нагрузки, — объект расследования. Как читать тенденции по памяти, подробно разобрано в статье про ожидание GC и утечки.

4. Снимаем трассу через dotnet-trace

dotnet-trace — средство сбора на базе EventPipe.⁶ Установка и базовый сбор выглядят так.

dotnet tool install --global dotnet-trace
dotnet-trace ps
dotnet-trace collect --process-id <PID> --duration 00:00:00:30

Без параметров используется профиль по умолчанию: основные события runtime и сэмплирование потоков. Профиль с именем cpu-sampling когда-то существовал и с тех пор снят; сейчас по умолчанию сочетаются dotnet-common и dotnet-sampled-thread-time.⁶ Под задачу можно взять --profile gc-verbose (GC и выборки выделений объектов) или --profile gc-collect (только факты GC, с малой нагрузкой).

Чтобы вместе с остальным снять свой поставщик EventSource из предыдущей статьи, добавьте --providers.

dotnet-trace collect --process-id <PID> --providers KomuraSoft-OrderService

Результат — файл .nettrace. Открыть его можно тремя способами: в Visual Studio, в PerfView или, преобразовав в формат speedscope, в браузере.⁶

dotnet-trace convert trace.nettrace --format Speedscope

Формат speedscope — лёгкий flame graph на speedscope.app. Им удобно интуитивно увидеть, «под какой функцией ушло время».

Чем открывать, проще решать по вопросу кому показывать результат.

Итого: PerfView — для расследования, speedscope — для показа. Точечный разбор до имени функции сильнее получается в Stack Viewer PerfView, поэтому дальше — он.

5. ЦП в PerfView — как читать Stack Viewer

PerfView — бесплатное средство расследования производительности от Microsoft. Достаточно скачать один PerfView.exe со страницы релизов на GitHub, установка не нужна.⁷

5.1 Сбор

Если собирать через GUI, последовательность такая — вплоть до того, куда нажимать.

1. Запустите PerfView.exe от имени администратора (для старта сеанса ETW нужны права администратора³)
2. В меню выберите Collect > Collect (сочетание Alt+C). Откроется диалог сбора и запросит имя создаваемого файла данных¹
3. Состав сбора задают флажки в этом диалоге. Если ничего не менять, пишутся выборки ЦП и основные события CLR. Чтобы смотреть ещё и ожидания, включите флажок Thread Time (глава 6)¹
4. Нажмите Start Collection
5. Воспроизведите операцию, которую измеряете (это и есть объект измерения — лишние действия не вставляйте)
6. Нажмите Stop Collection. После остановки пойдут слияние данных и разрешение символов, и появится .etl.zip с именем из шага 2

То же из командной строки выглядит так (её тоже запускают от администратора³).

PerfView collect /nogui /acceptEULA /maxCollectSec:30

Сбор по умолчанию включает выборки ЦП раз в миллисекунду на каждом процессоре (со стеком вызовов) и основные события CLR.¹ Накладные расходы в этой конфигурации обычно оценивают в несколько процентов.⁸

5.2 Как читать CPU Stacks

Откройте результат (.etl.zip) и в «CPU Stacks» выберите целевой процесс — откроется Stack Viewer.

С первого взгляда элементов много, поэтому сначала сопоставьте, что где лежит. Экран делится на «поля фильтров сверху» и «сетку с вкладками снизу».

Первое, что смотрят, — два столбца на вкладке ByName.

• Exc (exclusive): сколько выборок функция выполнялась сама. Место, которое реально потребляет ЦП.
• Inc (inclusive): сумма выборок функции и всего, что она вызвала. Показывает, что тяжесть сидит где-то ниже по дереву.

Шаблон чтения: идти сверху по Exc и отделять «это мой код или runtime/библиотека». Если высоко в Exc стоит ваш код, цель — алгоритм или цикл этой функции. Если высоко System.String или JSON-сериализатор, через вкладку Callers по Inc дойдите до того, откуда в вашем коде это вызывают так часто.

Второй обязательный шаг — проверить само число выборок. Выборки ЦП — статистика с шагом 1 мс, при малом числе на них влияет случайность. Ориентир: не меньше 1000 в сумме, лучше около 5000. Если не хватает, повторяйте целевую операцию и удлиняйте сбор.¹

Если имена функций своих модулей показываются адресами, символы (PDB) не разрешились. Иметь PDB от артефактов сборки под рукой — это и есть возможность расследовать. Подробнее: «Что такое PDB (Program Database)».

6. «Медленно, хотя ЦП свободен» — время блокировки через ThreadTime

Больше половины практических «тормозов» — это не ЦП, а ожидание: захват блокировки, ответ БД или HTTP, файловый I/O, ожидание через Task.Result, близкое к взаимной блокировке. В выборках ЦП это выглядит как время, когда ЦП вообще не работал, поэтому сбор по умолчанию причину не показывает.

В PerfView при сборе включают параметр Thread Time: дополнительно пишутся события переключения контекста, и по каждому потоку можно вместе смотреть «время на ЦП» и «время в блокировке».¹

Включить можно в GUI и в командной строке — результат один.

• В GUI: на шаге 2 из раздела 5.1 откройте диалог Collect > Collect (Alt+C), включите флажок Thread Time и только потом жмите Start Collection. В официальном руководстве прямо сказано: если исследуете wall-clock time, в диалоге сбора нужно включить флажок Thread Time.¹ Первый камень преткновения — собрать с настройками по умолчанию и удивляться, почему времени блокировки нет.
• В командной строке: добавьте ключ /threadTime.

PerfView collect /nogui /acceptEULA /threadTime /maxCollectSec:30

Для разбора откройте представление «Thread Time Stacks». Это тот же Stack Viewer, что у CPU Stacks, но выборки содержат не только время ЦП, но и BLOCKED_TIME (время в блокировке). Сузьте интервал до медленной операции и посмотрите, на каком стеке (каком ожидании) лежит BLOCKED_TIME потока, который вёл работу. Тогда появляется разложение вроде «из 40 секунд 35 ушли на ожидание этого HTTP-вызова».

Если «замирает» интерфейс (после действия несколько секунд нет отклика), почти всегда заблокирован UI-поток. Когда ThreadTime покажет, на чём он стоит, постоянное решение — убрать синхронное ожидание в пользу асинхронного. Как это проектировать, разобрано в «WPF и WinForms: async/await и поток UI».

Осторожно: ThreadTime пишет событие на каждое переключение контекста, объём данных заметно больше, чем при сборе по умолчанию. Держите окно коротким и не снимайте длинные трассы ThreadTime в продакшене.

7. Вместе с EventSource — выделять медленный участок словами бизнеса

И CPU Stacks, и Thread Time — сводки по всему процессу. Если нужно резать по единице бизнес-операции — «где внутри обработки одного заказа ушло время» — работают события Start/Stop EventSource из предыдущей статьи.

Чтобы эту главу можно было пробовать и без предыдущей статьи, ниже — минимальный код своего поставщика. --providers KomuraSoft-OrderService из главы 4 указывает на это Name.

using System.Diagnostics.Tracing;

// [EventSource(Name = ...)] задаёт имя поставщика, которое видят ETW и EventPipe
[EventSource(Name = "KomuraSoft-OrderService")]
public sealed class OrderServiceEventSource : EventSource
{
    public static readonly OrderServiceEventSource Log = new OrderServiceEventSource();

    [Event(1, Level = EventLevel.Informational)]
    public void OrderProcessingStart(string orderId) => WriteEvent(1, orderId);

    [Event(2, Level = EventLevel.Informational)]
    public void OrderProcessingStop(string orderId) => WriteEvent(2, orderId);
}

На вызывающей стороне достаточно обернуть измеряемый участок.

OrderServiceEventSource.Log.OrderProcessingStart(orderId);
try
{
    ProcessOrder(orderId); // бизнес-операция, которую измеряем
}
finally
{
    OrderServiceEventSource.Log.OrderProcessingStop(orderId);
}

Имена методов лучше выровнять как …Start / …Stop, а идентификаторы событий держать подряд: тогда в представлении Events в PerfView их проще читать как парный интервал. Stop обязательно из finally, чтобы прогон, который вышел по исключению, не остался «незаконченным интервалом». Как описывать события подробнее (ограничения на типы аргументов, когда какой EventLevel и Keywords) — в предыдущей статье.

При такой инструментировке расследование идёт в таком порядке.

• В приложении заранее выпускают события вроде OrderProcessingStart / OrderProcessingStop (код выше)
• В представлении «Events» PerfView смотрят время этих событий и сужают интервал Stack Viewer фильтрами Start/End до этого окна
• В суженном диапазоне читают разложение ЦП / времени блокировки

Так анализируют именно «тот самый медленный раз», а не тонут в шуме обычной работы. Свои события так же снимает и dotnet-trace, поэтому одну и ту же методику можно применять и на машине разработки, и в продакшене. На практике сложность расследования производительности задаёт не столько владение инструментами, сколько то, есть ли в приложении точки наблюдения.

Итог

• Исходная точка — разделить «тормоза» на CPU-bound и блокировку. Первое видно по сэмплированию ЦП (1 выборка ≈ 1 мс), второе не проявится без сбора ThreadTime.
• Базовое правило: сначала dotnet-trace без прав администратора; PerfView — когда нужны вся машина, нативный код или время блокировки. Снять .nettrace и читать его в PerfView — тоже обычная связка.
• Ядро чтения Stack Viewer — различие exclusive и inclusive; число выборок всегда проверяют.
• Свои события EventSource, которыми режут интервал бизнес-операции, заметно поднимают точность расследования.

Komura Software LLC занимается расследованием проблем производительности Windows-бизнес-приложений — «тормозит», «зависает», «ЦП на максимуме» — и консультациями по инструментированию и проектированию, которые делают приложение проще для измерения. Если есть сценарий воспроизведения и файл трассы, можно заказать и только разбор.

Связанные статьи

• Журнал событий Windows и ETW: как вывести логи бизнес-приложения в стандартные механизмы ОС
• .NET: как отличить ожидание GC от утечки памяти — практические шаги наблюдения, сравнения и доказательства роста памяти
• Как читать аварийные дампы в WinDbg + SOS — практика анализа после сбора
• Сбор дампов сбоев Windows — введение: WER, ProcDump, WinDbg
• Что такое PDB (Program Database) — отладочная информация, символы и Source Link
• Как правильно сравнивать скорость разных версий программы в Windows
• WPF и WinForms: async/await и поток UI

Связанные направления консалтинга

• Расследование сбоев и анализ причин
• Разработка приложений для Windows
• Технические консультации и ревью архитектуры
• Связаться с нами

Источники

Похожие статьи

Недавние статьи с теми же тегами помогут подробнее изучить близкие темы.

Связанные темы

Эти страницы показывают тему статьи в более широком контексте услуг и решений.

Услуги по этой теме

Статья напрямую связана со следующими услугами.

Частые вопросы

Вопросы, которые часто возникают при консультациях по теме статьи.

Что выбрать: PerfView или dotnet-trace?

Начните с dotnet-trace. Он работает без прав администратора, позволяет целиться в один процесс, а вся операция укладывается в одну команду. Но если нужны стеки нативного кода, картина по всей машине (влияние других процессов и ядра) или время блокировки по отдельным переключениям контекста — без PerfView на базе ETW не обойтись. На практике их часто сочетают: собирают .nettrace через dotnet-trace и открывают файл в PerfView.

Как это соотносится с профилировщиком Visual Studio?

Если проблема воспроизводится на машине разработки, инструмент CPU Usage и средства работы с памятью в Visual Studio удобнее, и часто их достаточно. PerfView и dotnet-trace нужны там, где Visual Studio поставить нельзя (проверочная или производственная машина), где сбор и разбор хотят развести по разным машинам, или где в трассу нужно включить события ETW — свои EventSource и события ядра. Visual Studio умеет открывать и файлы .nettrace, которые пишет dotnet-trace.

Можно ли запускать эти инструменты на производственном сервере?

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

Как разделить роли с WPR/WPA?

WPR (Windows Performance Recorder) и WPA (Windows Performance Analyzer) — более «системные» средства на той же ETW. Для детального разбора всей ОС — дисковый I/O, питание, время загрузки — сильнее WPR/WPA. Для ЦП, GC и времени блокировки в .NET-приложении удобнее PerfView: отображение заточено под управляемый код. Если цель — расследование бизнес-приложения, в большинстве случаев хватает PerfView и dotnet-trace.

Об авторе

Страница с профилем автора статьи.

Го Комура

Представитель KomuraSoft LLC

Специализируется на разработке программного обеспечения для Windows, техническом консалтинге и расследовании сбоев, особенно в проектах с унаследованными системами и трудно воспроизводимыми ошибками.