Один из этапов обработки заявки от пользователя в нашей службе поддержки — воспроизведение проблемы. Сложности с воспроизведением возникают по разным причинам: пользователь не всегда может предоставить пример приложения, на котором проявляется некорректное поведение кода, или проблема может быть специфична для конкретного окружения. Сегодня используется огромное количество программных, аппаратных конфигураций и виртуальных сред, в которых работают программы, написанные с нашими компонентами. Ширина экрана в пикселах может различаться в пять раз (от 800 до 4к). А еще конфигурации могут отличаться другими параметрами: объемом памяти, количеством дисплеев, DPI, настройками безопасности, видеокартой и ее драйверами. Это разнообразие обеспечивает стабильный поток заявок от клиентов, специфичных для какой-то конфигурации. Например, проблема воспроизводится только на определенной версии Windows или только на определенных установках DPI или если у пользователя три монитора. Для решения этой проблемы уже несколько лет наша служба поддержки использует утилиту Microsoft PerfView. Если все остальные способы воспроизвести проблему исчерпаны, мы отдаем пользователю простую инструкцию, как запустить трассировку и прислать нам результирующий файл. Трассировочная информация помогает понять, что именно вызывает проблему.
В этой статье будут рассмотрены возможности применения PerfView в службе технической поддержки и ограничения этой утилиты.
Изначально PerfView была создана для внутреннего использования и применялась Microsoft при оптимизации производительности Windows, .NET CLR и Visual Studio. В утилите используется инструмент ядра Windows — ETW (event tracing for windows)
Чтобы правильно интерпретировать результаты трассировки, важно понимать, как работает эта утилита. Любую программу можно представить в виде ориентированного графа, вершинами которого будут методы. Тогда кол стек программы в любой момент времени будет представлять собой путь от метода main() до метода, который выполняется в текущий момент.
В идеальном случае для анализа работы этой программы необходимо иметь информацию о ее состоянии в каждый момент времени. Например, такую информацию дает отладка. Но, во-первых, отладчик оказывает влияние на отлаживаемый процесс и полученные данные могут оказаться недостоверными. Во-вторых, все большее распространение получают асинхронные вызовы, которые отладчики анализируют недостаточно хорошо. Для многих задач нет необходимости в информации о состоянии анализируемой программы в каждый момент времени. Можно делать снимки состояния программы через определенные промежутки времени. На рисунке показана временная диаграмма работы простой программы в один поток. Временная ось внизу диаграммы разбита на равные отрезки времени, кратные длине такта процессора. Для серых отрезков кол стеки недоступны, для зеленых – доступны.
На основе этой идеи и был создан профайлер PerfView. Через определенные, достаточно короткие промежутки времени делается снимок кол стеков всех процессов на машине. PerfView умеет загружать символы из интернета, имеет маленький размер и переносится на другую машину простым копированием. Это делает PerfView мощным инструментом для анализа работы любых программ на любой машине с Windows. Помимо кол стеков сохраняются системные события, события .NET и много чего еще. Эта информация часто помогает разобраться в сути проблемы и найти решение.
Рассмотрим типичные ситуации, когда PerfView может быть полезен службе технической поддержки:
1. Приложение зависает у пользователя. Это самое простое что может быть. Кол стек, приводящий к зависанию, гарантированно будет содержаться в трассировке.
2. Приложение прекращает работу с ошибкой. При этом Windows приостанавливает проблемный процесс и вызывает отладочный процесс dwwin.exe для него. На этот вызов тратится время значительно превышающее время между снимками, поэтому можно с уверенностью утверждать, что кол стек падения тоже попадет в трассировку.
3. Приложение работает не так, как ожидается. Например, на некоторых конфигурациях приложение может неприятно мерцать при изменении размеров окна. В этой ситуации необходимо сравнивать результаты трассировок с “хорошей” и с “плохой” конфигурации.
4. Низкая производительность приложения на машине пользователя. PerfView изначально создавался именно как performance profiler. В данном случае утилита используется по прямому назначению.
Разумеется, PerfView не будет полезен в ситуациях, когда проблемный код проявляется на время, которое короче интервала между снимками и не повторяется.
Пример
Предлагается проанализировать работу простого WPF приложения которое рисует линии на экране, когда по нему водят пальцем, так же поддерживается рисование мышкой. Готовое приложение было взято отсюда
Так выглядит анализируемое приложение:
Задача: оценить время задержки от ввода до отображения линии на экране, исследовать время задержки для следующих сценариев
1. Приложение запускается планшете Acer Iconia W3 810. Используется сенсорный ввод.
2. Удаленный запуск приложения на Acer Iconia W3 810 и используется мышиный ввод вместо сенсорного.
Дешевый и слабый планшет от Acer выбран не случайно. Он достаточно медленный и у него мало памяти для того чтобы запускать какой-то другой, более требовательный к ресурсам софт разработчика.
Начинаем со сбора данных для анализа. В главном окне PerfView надо нажать Alt+C. Появится диалог.
Оставляем опции как есть, нажимаем Start Collection. Чтобы не анализировать лишнее, желательно сократить количество действий во время сбора данных. Например, можно запустить анализируемую программу заранее, если не интересует что происходит при ее старте. Рисуем несколько линий и нажимаем Stop Collection. На маленьком экране планшета анализировать не удобно, поэтому переносим получившийся *.etl файл на большой компьютер. Для анализа трассировки необходимы pdb файлы для сборок, которые поднимались на машине в момент трассировки. PerfView помещает их в архив вместе с etl файлом если выполнить Collect->Merge. Последняя версия утилиты делает это сама по умолчанию, в более ранних версиях необходимо было помнить про это. Открываем полученный файл.
Много, о чем можно рассказать тут, но сейчас выбираем CPU Stacks и видим все процессы, работавшие на планшете в момент трассировки.
Можно посмотреть любой из них. Это делает PerfView полезным инструментом для анализа меж процессных взаимодействий. Третий сверху процесс – наш. Выбираем его, получаем.
В столбце When отображаются числа на временной оси. Чем меньше число, тем меньше ресурсов процессора расходовалось. Прочерк в этом столбце означает, что кол стеки с таким методом не попадали в трассировку в соответствующие моменты времени. Видно пять всплесков активности. При трассировке нарисовали пять линий. GroupPats лучше выставить в значение Group class entries. В этом режиме строчка таблицы будет соответствовать методу.
PerfView показывает несколько сотен методов в таблице, хотя их намного больше. Поэтому, чтобы увидеть более полную картину, важно сокращать временной интервал при анализе трассировочных данных. Как уже догадались, всплески активности на временной оси соответствует рисованию линий. Выберем второй всплеск; для этого надо выделить символы в столбце When, и PerfView подскажет начало и конец интервала, которые надо вбить в поля Start и End. Следующий вид соответствует началу рисования линии. В начале временного отрезка процесс приложения ничего не делал. Если упорядочить методы по столбцу When, то получим:
На этом скриншоте видно, что процесс рисования начинается с обработки события сенсорного ввода PresentationCore.ni!PenThreadWorker.ThreadProc. Это произошло спустя 3 735 миллисекунд от начала трассировки. Событие сенсорного ввода будет обработано в программе и должно вызвать перерисовку. Поскольку методы упорядочены по времени вызова, достаточно листать таблицу вниз и искать вызовы, связанные с перерисовкой.
Вызовы в wpfgfx встречаются спустя примерно три миллисекунды, но это не то, что мы искали, потому что в этом временном интервале не работал код нашего приложения. Похоже, что мы случайно сделали небольшое открытие – в WPF есть своя визуализация сенсорного ввода. Даже если приложение не обрабатывает события сенсорного ввода, его окно все равно будет перерисовываться, когда приходят такие события. Окончанием перерисовки будем считать вызов d3d9!CSwapChain::Present. Первая перерисовка(не наша) произошла на 3 740 миллисекунде. Двигаемся дальше по временной оси. Событие сенсорного ввода было обработано пользовательским кодом спустя еще 4 миллисекунды. Ниже показан полный кол стек обработки события.
Следующий вызов метода d3d9!CSwapChain::Present произошел на 3 767 миллисекунде.
Таким образом, от события сенсорного ввода до перерисовки, вызванной работой пользовательского кода прошло около 32 миллисекунд. При скорости движения пальца один дюйм в секунду запаздывание визуализации составит около трех пикселов.
В случае удаленного подключения к планшету время задержки будет складываться из: задержки на передачу пользовательского ввода на удаленную машину, задержки на формирования кадра на удаленной машине, задержки на получение и отрисовку кадра в Remote Desktop. Для оценки этих задержек достаточно выполнить трассировку на машине с которой запускают Remote Desktop. Приведем здесь только результаты анализа и интересные находки. Анализировать будем процесс mstsc.exe. Пренебрегая временем которое тратится на обработку сообщения ввода, время задержки будем считать от вызова mstscax!CTSProtocolHandlerBase::SendBuffer до вызова mstscax!COP::PresentContentGDI. Передача пользовательского ввода на удаленную машину произошла на 14 348 миллисекунде.
После этого получение графических данных с удаленной машины и перерисовка окна приложения Remote Desktop произошла на 15 139 миллисекунде.
Задержка составила 791миллисекунду. При скорости движения пальца один дюйм в секунду запаздывание визуализации составит около 75 пикселов.
Надеемся, что после ознакомления со статьей станет меньше неуловимых багов, и разного рода «чудес» и непонятных моментов, связанных с работой программ.