Прежде чем перейти к статье, хочу вам представить, экономическую онлайн игру Brave Knights, в которой вы можете играть и зарабатывать. Регистируйтесь, играйте и зарабатывайте!
Обычно я запускаю большинство программ на своём ноутбуке с Windows 10, нажимая клавишу <Win>, после чего ввожу несколько букв имени программы, а затем жму Enter. На моём мощном ноутбуке (SSD и 32 ГБ ОЗУ) этот процесс обычно занимает лишь время, необходимое мне для ввода символов, то есть считанные доли секунды.
Обычно.
Однако иногда он занимает больше, намного больше. Порядка десятков секунд. Торможения непредсказуемы, но недавно мне удалось записать трассировку Event Tracing for Windows (ETW) одной из таких задержек. При помощи людей в Twitter я смог проанализировать трассировку и понять, почему на запуск «Блокнота» требуется примерно минута.
Прежде чем приступать к описанию анализа, мне нужно сделать два заявления: 1) у меня есть достаточное понимание проблемы, но нет решения, и 2) если вы наблюдаете аналогичные симптомы, это не значит, что их причина та же, но я дам советы о том, как понять, в ней ли дело.
Мой анализ трассировки (трассировка выложена здесь, установщик инструментов анализа находится здесь, туториалы по анализу — тут, можете повторять за моими действиями) начался с изучения событий ввода и графика Window in Focus в Windows Performance Analyzer (WPA); и то, и другое показано ниже (для максимальных подробностей изображение увеличено):
Первый самородок в строке Multi-Input появился, когда я нажал клавишу Windows, а вскоре после этого были сгруппированы вместе несколько последовательных нажатий клавиш (в том числе и нажатие на Enter). На оси X отложены секунды, то есть мы видим, что весь ввод занял примерно 3/4 секунды.
События ввода инъецируются в трассировку моим инструментом записи трассировок UIforETW. Эти события ввода — одна из причин, по которым я предпочитаю UIforETW инструментам записи трассировок Microsoft. Я скрыл табличный вид, однако в нём перечисляются нажатые клавиши, в то же время анонимизируя буквы и цифры, чтобы UIforETW не мог работать кейлоггером. События ввода могут быть критически важным инструментом при разборе того, что и когда смотреть в трассировках, чтобы понять происходящее.
События ввода помогают установить контекст, однако главную информацию дают события Window in Focus. Мы видим, что SearchApp (меню «Пуск»?) получает фокус сразу же после нажатия на клавишу <Win>, однако тринадцать с лишним секунд больше ничего не происходит. Это и есть наглядное проявление проблемы.
Но почему?
Дальше нам нужно посмотреть, что вызывает задержку. Изучение графиков CPU Usage (Precise) и Disk Usage показало нам, что CPU и диск простаивают почти на 100%, то есть меню «Пуск», должно быть, ожидает чего-то другого:
Если процесс простаивает, когда он должен выполнять работу, то наша задача разобраться, чего же он ждёт. Я изучил события переключения контекста в CPU Usage (Precise). Некоторые из потоков SearchApp имели имена (ура!), но не все, и я не мог найти основной поток, чтобы увидеть, чего же он ждёт, поэтому я просто тыкался в надежде, что ситуация немного прояснится. Я увеличил увеличил отображение графика скачка активности CPU перед непосредственным запуском «Блокнота» и заметил, что WerFault.exe и wermgr.exe стали очень загруженными. «После» не значит «вследствие», но это определённо подозрительно.
WER расшифровывается как Windows Error Reporting — это система, отправляющая аварийные дампы в Microsoft для анализа с целью повышения надёжности ПО.
Изучение таблицы Processes показало мне, что командная строка для WerFault.exe имела вид C:\WINDOWS\system32\WerFault.exe -u -p 17804 -s 2124. Это даёт нам понять, что Windows Error Reporting должна была записать информацию о вылетевшем процессе 17804. Когда я поискал в таблице Processes этот Process ID (PID), то нашёл RuntimeBroker.exe <Microsoft.Windows.Search> (17804). Хм, похоже, это имя относится к делу.
Изучение всех «переходных» («Transient») процессов (тех, которые запускались или завершались во временном интервале трассировки) открыло мне глаза:
WerFault.exe и RuntimeBroker.exe (17804) (два верхних процесса RuntimeBroker.exe) работали, когда я начал запись трассировки, и завершились примерно одновременно, а WerFault.exe обрабатывал вылет RuntimeBroker.exe. Обратите также внимание, что после закрытия старой копии RuntimeBroker.exe запускается новая. Итак, у нас начинает появляться объяснение:
- RuntimeBroker.exe аварийно завершается
- WerFault.exe обрабатывает сбой, сохраняя процесс RuntimeBroker.exe открытым
- Затем запускается новый RuntimeBroker.exe и предоставляет то, что нужно SearchApp.exe
Теперь у нас появился новый вопрос: почему WerFault.exe простаивает так долго?
Я посмотрел на данные CPU Usage (Precise) и увидел, что WerFault.exe имеет не менее тринадцати потоков, но ни у одного из них нет имени (да ладно, Microsoft, имена потоков очень полезны!), однако основной поток найти легко, именно он потребляет больше всего времени CPU. Затем я выполнил сортировку по Time Since Last и заметил, что в один момент основной поток ждал 15,572 с, чтобы заработать. На самом деле, он, возможно, ждал ещё дольше, но начало его ожидания было ещё до начала трассировки. Подробнее прочитать о том, как выполнять анализ простоев, можно здесь.
Ниже показан стек, в котором основной поток WerFault.exe ожидал в течение 15,572 с:
В итоге оказалось, что ожидание происходило внутри UploadReport.
Итак, теперь мы разобрались в проблеме. RuntimeBroker.exe аварийно завершился (согласно показанному выше стеку вызовов аварийного дампа RuntimeBroker.exe, из-за повреждения кучи), и для загрузки на сервер аварийного дампа потребовалось более 15 секунд; вероятно, из-за ненадёжного WiFi в моём отеле. В течение этого времени с моим меню «Пуск» невозможно было работать.
Это стоит повторить. Меню «Пуск» зависло из-за сочетания повреждения кучи и того, что WerFault.exe принял решение о необходимости загрузки на сервер аварийного дампа до освобождения старого процесса, а запуск нового процесса возможен только после этого.
Чтобы произошло это зависание, потребовались два бага (повреждение кучи и загрузка дампа перед перезапуском), но они возникли.
Мы можем двинуться ещё глубже. Функция UploadReport была заблокирована в течение 15,567 с, а в Readying Process/Readying Thread Id показано, кто же в конечном итоге разблокировал функцию. Оказалось, что это ещё один поток WerFault.exe, который, как показано ниже, был заблокирован в каких-то функциях. Это не сильно расширяет понимание проблемы, но демонстрирует, как можно оттрасировать зависание обратно сквозь множество процессов и потоков.
Выслеживаем эту проблему
В общем случае, если вы хотите понять, почему компьютер плохо работает, то нужно записать и проанализировать трассировку. Однако если вы хотите увидеть, действительно ли возникает конкретно эта проблема, то можно выполнить более простые действия.
Первым делом нужно сконфигурировать локальную запись аварийных дампов. Это в целом является хорошей идеей, потому что позволяет отслеживать стабильность компьютера в процессе вашей работы.
Тогда если после записи аварийного дампа вы увидите, что меню «Пуск» тормозит, вы можете просто заглянуть в %localappdata%\crashdumps и поискать, есть ли там недавний сбой RuntimeBroker.exe. Если есть, то, предположительно, вы наблюдаете именно этот баг.
Ожидание загрузки на сервер
Рэймонд Чен привёл множество причин того, почему Windows Error Reporting не перезапускает вылетевшие процессы до загрузки отчёта на сервер (в 2012 году), но мне эти причины не кажутся особо убедительными, особенно в случае меню «Пуск». Если убивать старый процесс перед запуском нового и отвечать на вопросы о версии DLL из аварийного дампа, то большинство приведённых Рэймондом проблем можно избежать. С остальным позволяет справиться экспоненциальная задержка при перезапусках процессов. И, как мы видели, последствием такого ожидания могут быть зависания меню «Пуск» произвольной длительности с полным отсутствием указания на то, что проблема была в сбое. Кроме того, есть некоторая путаница в связи с поведением; возможно, за последние десять лет архитектура изменилась.
Устраняем сбой
Баги повреждения кучи бывают очень сложными в поиске и устранении, но, похоже, с нашим всё может быть просто. Я включил pageheap для RuntimeBroker.exe, убил соответствующую версию, чтобы заставить его перезапуститься, и применил параметры pageheap, после чего он начал вылетать каждый раз, когда я открывал меню «Пуск». Я настроил WER так, чтобы она сохраняла полные аварийные дампы и вскоре у меня на руках было с полдесятка дампов с полной информацией о том, что происходит.
Вылеты обычно происходят в этом стеке вызовов:
При включенном pageheap вылет происходит в очень похожем стеке вызовов, но чуть раньше. Вылет происходит раньше (и надёжнее), потому что при освобождении памяти с запущенным pageheap она становится неотображаемой, поэтому её разыменование стабильно вызывает вылет, а не чтение из освобождённой памяти:
Вылет происходит при разыменовании [rcx], поэтому я пропустил его значение через команду !heap (подробности см. в моём посте про pageheap) и получил следующий стек вызовов:
Единственная сложность заключается в том, что это не происходит на всех машинах с Windows 10. Похоже, существует какое-то обязательное состояние, приводящее к этому, и я не знаю, какое оно. От себя добавлю, что с радостью поделюсь своими аварийными дампами с любым человеком из Microsoft, который захочет провести исследование.
Я не знаю кода и не понимаю, что происходит, но я имел дело с достаточным количеством багов use-after-free, чтобы сказать, что, скорее всего, при помощи аварийных дампов проблему легко выявить и устранить. Впрочем, у меня получилась пара разных стеков вызовов, так что багов может быть несколько.
Выводы
Свой изначальный пост в Twitter я завершил словами о том, что эти зависания меня бесили и я задавался вопросом, не превратилась ли Windows 10 в abandonware. Позже мне сказали, что у некоторых людей зависания меню «Пуск» происходят и в Windows 11, но это может быть и какая-то другая проблема.
Внесу ясность: у Microsoft есть технология для записи трассировок зависаний меню «Пуск» на клиентских машинах. В этих трассировках будет примерно то же, что и в моей. Также компания получает аварийные дампы с клиентских машин. Возможно, у компании даже есть способ установить между ними корреляцию (а если нет, такой способ стоит внедрить). И компания создала pageheap, упрощающий исследование вылетов use-after-free.
Почему же эту проблему не решили? На своём ноутбуке я вижу, что в среднем RuntimeBroker.exe в этом году вылетал через день. На мой взгляд, как-то слишком часто для зависания меню «Пуск». Я не знаю, как долго это происходит, возможно, исправление уже в пути; если это так, то я был бы рад это услышать. Если же не так, то меня продолжит это бесить; надеюсь, ситуация послужит хорошим напоминанием о важности использования всей этой сложной телеметрии для решения подобных проблем.
Или, возможно, мне просто не повезло, и я стал одним из тех немногих (но не единственным), кто столкнулся с этим сбоем.
Если вкратце, мне очень нравятся созданные и выпущенные Microsoft инструменты, позволяющие анализировать подобные проблемы с производительностью. Однако мне бы хотелось, чтобы не приходилось использовать их так часто для анализа самой Windows.
