Я обычно запускаю большинство программ на своем ноутбуке с 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 не стал регистратором клавиш. События ввода могут быть важным инструментом, помогающим понять, где/когда искать в трассировках, чтобы понять, что происходит.
События ввода помогают установить контекст, но события ” Windows in Focus” действительно рассказывают историю. Мы видим, что SearchApp (стартовое меню?) получает фокус, как только я нажимаю клавишу <Win>, но затем ничего больше не происходит в течение более чем тринадцати секунд. Вот в чем проблема, визуализированная.
Но почему?
Следующий шаг – посмотреть, что вызывает задержку. Быстрый взгляд на графики CPU Usage (Precise) и Disk Usage показал, что CPU и диск простаивают почти на 100%, поэтому меню “Пуск” должно ждать чего-то другого:
Когда процесс простаивает в течение некоторого времени, когда вам хочется, чтобы он выполнял работу, возникает задача выяснить, чего он ждал. Я просмотрел события переключения контекста в CPU Usage (Precise). Некоторые из потоков SearchApp были идентифицированы (ура!), но не все, и я не мог найти главный поток, чтобы посмотреть, чего он ждет, поэтому мне пришлось пошарить вокруг и надеяться, что что-то станет очевидным. Я увеличил масштаб всплеска активности процессора непосредственно перед запуском блокнота и заметил, что WerFault.exe и wermgr.exe оба начали работать. Корреляция – не причинно-следственная связь, но это, конечно, подозрительно.
Обратите внимание, что WER означает Windows Error Reporting – система, которая отправляет дампы ошибок обратно в Microsoft для анализа, чтобы повысить надежность программного обеспечения.
Просмотр таблицы процессов показал, что командная строка для WerFault.exe была “C:\WINDOWS\system32\WerFault.exe -u -p 17804 -s 2124”. Это говорит о том, что Windows Error Reporting было предложено записать информацию для аварийного процесса 17804, и когда я искал в таблице Processes этот идентификатор процесса (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 – имена потоков очень помогают!), но главный поток легко определить как тот, который использует больше всего процессорного времени. Затем я произвел сортировку по 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, который был заблокирован в некоторых функциях CHttpRequest, как показано выше. Это не добавляет существенного понимания проблемы, но наглядно демонстрирует, как можно проследить зависание в обратном направлении через несколько процессов и потоков.
Наблюдение за проблемой
Как правило, если вы хотите понять, почему ваш компьютер работает плохо, вам необходимо записать и проанализировать трассировку. Однако если вы хотите проверить, не столкнулись ли вы с этой конкретной проблемой, есть более простые шаги, которые вы можете выполнить.
Первым шагом является настройка локальной записи дампов аварий. Это хорошая идея в целом, поскольку позволяет отслеживать стабильность работы компьютера в течение времени.
Затем, записав дампы аварий, если вы видите зависание меню “Пуск”, вы можете просто заглянуть в %localappdata%\crashdumps и посмотреть, есть ли там недавний сбой RuntimeBroker.exe. Если да, то, предположительно, вы наблюдаете эту ошибку.
Ожидание загрузки
Раймонд Чен приводит несколько причин, по которым Windows Error Reporting не перезапускает сбойные процессы перед загрузкой отчета (примерно 2012 год), но я не нахожу эти причины полностью убедительными, особенно в случае с меню “Пуск”. Пока вы убиваете старый процесс перед запуском нового – и отвечаете на вопросы о DLL-версии из аварийного дампа – большинство проблем, на которые он указывает, можно избежать. Экспоненциальный откат при перезапуске процессов может решить остальные. А последствиями ожидания, как мы видели, могут быть произвольно долгие зависания меню запуска без каких-либо признаков того, что проблема заключается в сбое. Существует также некоторая путаница в поведении – возможно, дизайн изменился за последние десять лет.
Устранение сбоя
Ошибки повреждения кучи бывает крайне сложно найти и исправить, но эта, похоже, может быть проще. Я включил pageheap в RuntimeBroker.exe, убил соответствующую версию, чтобы заставить ее перезапуститься и применить настройки pageheap, и она начала падать каждый раз, когда я открывал меню “Пуск”. Я настроил WER на сохранение полных дампов аварий и вскоре получил полдюжины дампов аварий с подробным описанием происходящего.
Сбои обычно происходят на этом стеке вызовов:
При включенной страничной куче крах происходит на очень похожем стеке вызовов, но немного раньше. Сбой происходит раньше (и более надежно), потому что при использовании страничной кучи при освобождении памяти она не отображается, поэтому разыменование ее надежно вызывает сбой, вместо того чтобы читать из освобожденной памяти:
Сбой происходит при разыменовании [rcx], поэтому я прогнал его значение через команду !heap и получил такой стек вызовов:
Единственная сложность заключается в том, что это происходит не на всех машинах с Windows 10. Похоже, есть какое-то требуемое состояние, которое заставляет это происходить или нет, и я не знаю, что именно. Скажу, что я с радостью поделюсь дампами аварийных ситуаций с любым сотрудником Microsoft, который захочет провести расследование.
Я не знаю кода и не понимаю, что происходит, но я имел дело с достаточным количеством ошибок use-after-free, чтобы сказать, что это, вероятно, легко исследовать и исправить, используя дампы аварий. Хотя я получил несколько разных стеков аварийных вызовов, так что ошибок может быть несколько.
Выводы
В конце своей первоначальной темы в Twitter я сказал, что эти зависания меня раздражают и заставляют задуматься о том, не является ли Windows 10 заброшенной ОС. С тех пор мне сказали, что люди, похоже, наблюдают зависания меню “Пуск” в Windows 11, но это не обязательно та же проблема.
Для ясности, у Microsoft есть технология для записи трассировки зависаний меню “Пуск” на клиентских машинах. Эти данные показывают примерно то же самое, что и мои трассировки. Они также получают дампы аварий с клиентских машин. Возможно, у них даже есть способ сопоставить их (если нет, то они должны это сделать). Кроме того, они создали pageheap, который позволяет легко исследовать сбои, не связанные с использованием.
Почему же это до сих пор не решено? На моем ноутбуке я вижу, что RuntimeBroker.exe падает в среднем каждый второй день в этом году. На мой взгляд, это слишком частое зависание в меню “Пуск”. Я не знаю, как давно это происходит, так что, возможно, исправление уже на подходе – если да, то было бы здорово услышать. Если нет, то я буду продолжать раздражаться и надеюсь, что это послужит хорошим напоминанием о важности использования всей этой фантастической телеметрии для решения подобных проблем.
Или, может быть, мне просто не повезло, и я один из немногих (не единственный), кто сталкивается с этим сбоем.
Короче говоря, я очень доволен инструментами, которые Microsoft создала и выпустила, чтобы позволить мне анализировать проблемы производительности, подобные этим. Однако я хотел бы, чтобы мне не приходилось так часто использовать их в самой Windows.
