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

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

Основная тема — исследование ЦП и времени отклика. Постоянно растущая память рассмотрена в «Telling GC Pauses Apart from Memory Leaks in .NET», а аварийные завершения — в «Reading Crash Dumps with WinDbg + SOS».

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

• Есть два вида «медленной работы»: CPU-bound, когда ЦП загружен полностью, и blocked, когда ЦП свободен, но приложение чего-то ждёт. Для первого нужны выборки ЦП, для второго — ThreadTime (переключения контекста); обычный сбор ЦП не покажет причину второго. ¹
• При сомнениях начните с dotnet-trace. Это кроссплатформенный инструмент на базе EventPipe; если вы тот же пользователь, который запустил целевой процесс, сбор возможен без прав администратора. ² Файлы .nettrace открываются в PerfView или Visual Studio. ³
• PerfView нужен, когда требуется увидеть всю машину, нативный код или время блокировки. Благодаря ETW он обрабатывает события ядра и нативные стеки, но запуск сеанса ETW требует прав администратора. ³
• По умолчанию выборка ЦП выполняется раз в миллисекунду (на процессор). Считайте выборку примерно 1 мс времени ЦП и соберите минимум 1 000, лучше около 5 000 выборок, прежде чем делать выводы: при малом числе лидеры могут быть случайны. ¹
• Интерпретация начинается с различия inclusive (сама функция плюс всё вызванное) и exclusive (только сама функция). Большое exclusive — место, действительно потребляющее ЦП; большое inclusive — признак того, что ниже по дереву вызовов есть тяжёлая работа.
• До измерения сведите «медленно» к одной конкретной операции. Сбор при «в целом вялом» приложении плохо читается. Сначала зафиксируйте операцию и момент, например «этот отчёт создаётся 40 секунд», затем собирайте данные. Полезен и подход до/после из «How to Correctly Compare Program Speed Across Versions on Windows».

Таблица выбора первого шага по симптому:

2. Как связаны инструменты — ETW и EventPipe

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

• ETW (Event Tracing for Windows): инфраструктура трассировки для всей ОС. Она может записывать ядро и приложение на одной временной шкале, но запуск и остановка сеанса требуют прав администратора; ETW доступен только в 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 постоянно растёт» подсказывает следующую трассу — ориентированную на выделения либо на блокировки. Тенденции памяти подробно разобраны в «Telling GC Pauses Apart from Memory Leaks in .NET».

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 и помогает интуитивно увидеть, «куда ушло время и под деревом вызовов какой функции». Для строгого поиска до конкретной функции мощнее Stack Viewer PerfView.

5. Исследование ЦП в PerfView — как читать Stack Viewer

PerfView — бесплатный инструмент исследования производительности, публикуемый Microsoft; достаточно загрузить один файл PerfView.exe со страницы релизов GitHub, установка не нужна. ⁶

5.1 Сбор

В GUI откройте «Collect > Collect», нажмите Start Collection, воспроизведите целевую операцию и нажмите Stop Collection. В командной строке это выглядит так; запускать нужно от администратора, поскольку начинается сеанс ETW ³.

PerfView collect /nogui /acceptEULA /maxCollectSec:30

Сбор по умолчанию включает выборку ЦП с интервалом 1 мс и стеком вызовов на каждом процессоре, а также основные события CLR. ¹ Накладные расходы в настройке по умолчанию обычно составляют несколько процентов. ⁷

5.2 Чтение CPU Stacks

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

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

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

Также критически важно само число выборок. Поскольку выборки ЦП — статистика с интервалом 1 мс, при малом числе результат случаен. До выводов соберите не менее 1 000, лучше около 5 000 выборок; если их мало, продлите сбор, повторив целевую операцию. ¹

Если имя функции из вашего модуля показано лишь адресом, её символы (PDB) не разрешились. Наличие PDB артефактов сборки само по себе делает расследование возможным. Подробнее: «What Is a PDB (Program Database)?».

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

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

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

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

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

Когда замирает интерфейс, почти всегда заблокирован UI-поток. После того как ThreadTime выявит, что его блокирует, постоянное исправление — перепроектировать синхронное ожидание на асинхронное. Проектирование этого рассмотрено в «A One-Page Cheat Sheet for async and the UI Thread in WPF/WinForms».

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

7. Сочетание с EventSource — анализ «какой участок медленный» в терминах бизнеса

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

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

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

Итог

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

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

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

• Введение в журнал событий Windows и ETW — как вести журналы бизнес-приложения через стандартный механизм ОС
• Telling GC Pauses Apart from Memory Leaks in .NET — Practical Steps for Observing, Comparing, and Proving Growing Memory
• Reading Crash Dumps with WinDbg + SOS — A Practical Introduction to Analysis After Collection
• An Introduction to Collecting Windows Crash Dumps — WER/ProcDump/WinDbg
• What Is a PDB (Program Database)? — Understanding Debug Info, Symbols, and Source Link
• How to Correctly Compare Program Speed Across Versions on Windows
• A One-Page Cheat Sheet for async and the UI Thread in WPF/WinForms

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

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

Источники

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Где здесь WPR/WPA?

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

Об авторе

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

Го Комура

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

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