«Проводник тратит 700 мс на то, чтобы открыть контекстное меню панели задач. 75% этого времени он выполняет 114 801 операцию считывания из одного файла, средний объём считываемых данных 68 байт.
Мне стоит написать пост об этом, или достаточно саркастичного твита?»
За компьютером я работаю быстро, и поэтому меня раздражает, когда приходится ждать завершения операции, которая должна выполняться мгновенно. Постоянной помехой на моём сверхмощном домашнем ноутбуке стало медленное закрывание окон на панели задач. Я нажимаю правой клавишей на значок, жду, пока откроется меню, а затем выбираю «Закрыть окно». Самым медленным в этом процессе должны быть перемещения мыши, но выясняется, что наиболее долгим компонентом оказывается задержка перед появлением меню.
Это напрягало меня уже давно, но я проявлял нехарактерный мне самоконтроль и удерживался от раздражения. Так было до сегодняшнего дня, когда я наконец сорвался и схватился за трассировщик ETW.
Этот пост написан как проверка скоростного блогинга. От момента нахождения проблемы и саркастичного твита о ней до публикации поста прошло примерно 90 минут.
Трассировщик ETW фиксировал, как я нажимаю правой клавишей мыши на панели задач и закрываю два окна «Проводника». Я использовал функцию UIforETW Tracing to file с опциями по умолчанию, получив в результате лог диагностики на 20,9 МБ.
Иногда самое трудное в анализе трассировки заключается в поиске места возникновения проблемы, но в данном случае эта часть анализа оказалась тривиальной. Было три недвусмысленных сигнала, указывавших на нужное место, и болезненно очевидный виновник преступления.
Первым сигналом были события ввода. UIforETW содержит интегрированный логгер ввода (достаточно анонимизированный, чтобы я случайно не украл пароли или личную информацию), поэтому мне достаточно было подробно изучить события MouseUp и Button Type со значением 2, соответствующим правой клавише мыши. При этом на временной шкале WPA появляются отметки моментов, когда происходят эти события — см. вертикальные линии на скриншоте:
Это дало мне понять, что когда я отпускаю правую клавишу мыши, то спустя 600 мс происходит смена фокуса окна, что, по моей догадке, соответствует моменту отображения меню. Кроме того, в RuntimeBroker.exe присутствует чёткий блок активности ЦП между событиями отпускания клавиши мыши и смены фокуса окна.
Не доказано, что смена фокуса окна и активность ЦП связаны, но сделав измерения при помощи приложения записи экрана, я увидел, что на отображение меню тратится примерно 660 мс, поэтому я склонен этому доверять.
Следующим шагом будет изучение того, чем занят RuntimeBroker.exe. Хотя CPU Usage (Precise) отлично помогает увидеть, сколько времени ЦП использует процесс, и почему он простаивает, подходящим инструментом для выяснения того, на что тратится время ЦП, является таблица CPU Usage (Sampled). Я внимательно её изучил и быстро обнаружил, что 264 сэмпла приходится на KernelBase.dll!ReadFile:
Поискав ещё немного, я нашёл другие стеки вызовов, которые тоже затрагивали эту функцию, поэтому я нажал правой клавишей мыши и выбрал View Callers-> By Function. Включившийся при этом режим (с инвертированными стеками) показал, что из 899 сэмплов этого процесса 628 сэмплов, или 70%, из разных стеков вызовов проходили через эту функцию:
271 сэмпла в этом потоке не проходили через функцию, а оставшиеся сэмплы (не показаны) находились в других потоках.
Заметьте, что 899 сэмплов в потоке 10 252 обозначают два щелчка мыши, то есть примерно 450 сэмплов или 450 мс (при стандартной частоте сэмплирования 1 кГц) на один щелчок мыши.
Иногда файловый ввод-вывод — это время ЦП
CPU Usage (Sampled) показывает время ЦП, поэтому дисковый ввод-вывод здесь обычно не отображается, ведь в эти моменты поток засыпает и ждёт диск. То, что операции ввода-вывода отображаются как время ЦП, означает, что все считывания пришлись на кэш системы и время ЦП было лишними ресурсами ядра (см. ntoskrnl.exe в первом сэмплированном стеке вызовов), потраченными на получение данных из кэша.
Теперь, когда под подозрение попал файловый ввод-вывод, нам необходимо перейти в Graph Explorer-> Storage-> File I/O. Немного настроив внешний вид столбцов, мы получили следующий впечатляющий результат:
Он сообщает нам, что в потоке 10 252 за два щелчка мыши RuntimeBroker.exe создал 229 604 вызова ReadFile, считав в сумме 15 686 586 байт. То есть в среднем каждый раз считывалось по 68 байт.
Задумайтесь об этом на секунду.
Не забывайте, что это вызовы к операционной системе — вызовы ядра. Это значит, что между RuntimeBroker.exe и этим файлом отсутствует кэширование. На самом деле сам файл имеет длину всего 4 027 904 байт, то есть каждый раз, когда я нажимаю на значок проводника в панели задач, файл считывается 1,9 раза самым медленным из возможных способов.
Подстрекаемый своими читателями, я решил удалить этот файл и теперь меню списка переходов проводника появляются почти мгновенно. Я не рекомендую этого делать, но удаление файла может помочь и вам (ценой потери истории проводника):
%appdata%\Microsoft\Windows\Recent\AutomaticDestinations\f01b4d95cf55d32a.automaticDestinations-msВыигрыш от удаления файла показан на этом скриншоте WPA. Тонкие вертикальные линии — это нажатия правой клавиши мыши, а прямоугольники в нижней строке обозначают момент отображения меню. Я удалил файл после первых двух кликов и при последних двух кликах задержка значительно снизилась:
Или же «можно воспользоваться официальным прибамбасом из „Параметров“, чтобы очистить (нажать дважды) или отключить (нажать один раз) списки переходов в меню „Пуск“/панели задач. Чтобы ещё больше повысить скорость, отключите также анимации». Спасибо, Рафаэль!
Похоже, что эту проблему можно решить. Снизив задержку отображения меню панели задач проводника, было бы здорово рассмотреть способы устранения других задержек, чтобы все меню панели задач появлялись мгновенно, а не спустя сотни миллисекунд.
Подведём итог
- Не вызывайте ReadFile, чтобы прочитать 68 байт. Или, по крайней мере, не делайте это сотню тысяч раз. Меня бесит, когда базы данных выполняют считывание по 4 кибибайта, но этот случай просто удивителен.
- Надеюсь, кто-нибудь устранит эту проблему, но пока у меня есть обходное решение — удаление проблемного файла.
- Надеюсь, кто-нибудь возьмётся за исследование и выяснит, почему вообще тормозят контекстные меню. Эй, я ведь даже поделился трассировкой ETW и всем остальным!
- Отчёт по официальным каналам передан в https://aka.ms/AA60dfg
- Если вы хотите научиться проводить подобный анализ, тогда скачайте мой инструмент UIforETW и прочитайте туториалы, ссылки на которые выложены здесь
- Не забывайте, что можно открыть контекстное меню гораздо быстрее (это проще, чем стандартное меню списка переходов), нажав shift+правой клавишей мыши на значки. Я буду пользоваться этим трюком, когда нужно будет закрывать много окон.
- Обсуждение на Hacker news находится здесь
- Обсуждение на Reddit находится здесь
- Темы в Twitter находятся здесь и здесь
