Почему для открытия меню Windows читает один файл сто тысяч раз?

«Проводник тратит 700 мс на то, чтобы открыть контекстное меню панели задач. 75% этого времени он выполняет 114 801 операцию считывания из одного файла, средний объём считываемых данных 68 байт.

Мне стоит написать пост об этом, или достаточно саркастичного твита?»

За компьютером я работаю быстро, и поэтому меня раздражает, когда приходится ждать завершения операции, которая должна выполняться мгновенно. Постоянной помехой на моём сверхмощном домашнем ноутбуке стало медленное закрывание окон на панели задач. Я нажимаю правой клавишей на значок, жду, пока откроется меню, а затем выбираю «Закрыть окно». Самым медленным в этом процессе должны быть перемещения мыши, но выясняется, что наиболее долгим компонентом оказывается задержка перед появлением меню.

Это напрягало меня уже давно, но я проявлял нехарактерный мне самоконтроль и удерживался от раздражения. Так было до сегодняшнего дня, когда я наконец сорвался и схватился за трассировщик ETW ^[1].

Этот пост написан как проверка скоростного блогинга. От момента нахождения проблемы и саркастичного твита ^[2] о ней до публикации поста прошло примерно 90 минут.

Трассировщик ETW фиксировал, как я нажимаю правой клавишей мыши на панели задач и закрываю два окна «Проводника». Я использовал функцию UIforETW ^[3] Tracing to file с опциями по умолчанию, получив в результате лог диагностики на 20,9 МБ ^[4].

Иногда самое трудное в анализе трассировки заключается в поиске места возникновения проблемы, но в данном случае эта часть анализа оказалась тривиальной. Было три недвусмысленных сигнала, указывавших на нужное место, и болезненно очевидный виновник преступления.

Первым сигналом были события ввода. UIforETW содержит интегрированный логгер ввода ^[5] (достаточно анонимизированный, чтобы я случайно не украл пароли или личную информацию), поэтому мне достаточно было подробно изучить события MouseUp и Button Type со значением 2, соответствующим правой клавише мыши. При этом на временной шкале WPA ^[6] появляются отметки моментов, когда происходят эти события — см. вертикальные линии на скриншоте:

Это дало мне понять, что когда я отпускаю правую клавишу мыши, то спустя 600 мс происходит смена фокуса окна, что, по моей догадке, соответствует моменту отображения меню. Кроме того, в RuntimeBroker.exe присутствует чёткий блок активности ЦП между событиями отпускания клавиши мыши и смены фокуса окна.

Не доказано, что смена фокуса окна и активность ЦП связаны, но сделав измерения при помощи приложения записи экрана, я увидел, что на отображение меню тратится примерно 660 мс, поэтому я склонен этому доверять.

Следующим шагом будет изучение того, чем занят RuntimeBroker.exe. Хотя CPU Usage (Precise) ^[7] отлично помогает увидеть, сколько времени ЦП использует процесс, и почему он простаивает, подходящим инструментом для выяснения того, на что тратится время ЦП, является таблица CPU Usage (Sampled) ^[8]. Я внимательно её изучил и быстро обнаружил, что 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%MicrosoftWindowsRecentAutomaticDestinationsf01b4d95cf55d32a.automaticDestinations-ms

Выигрыш от удаления файла показан на этом скриншоте WPA. Тонкие вертикальные линии — это нажатия правой клавиши мыши, а прямоугольники в нижней строке обозначают момент отображения меню. Я удалил файл после первых двух кликов и при последних двух кликах задержка значительно снизилась:

Или же «можно воспользоваться официальным прибамбасом из „Параметров“, чтобы очистить (нажать дважды) или отключить (нажать один раз) списки переходов в меню „Пуск“/панели задач. Чтобы ещё больше повысить скорость, отключите также анимации». Спасибо, Рафаэль ^[9]!

Похоже, что эту проблему можно решить. Снизив задержку отображения меню панели задач проводника, было бы здорово рассмотреть способы устранения других задержек, чтобы все меню панели задач появлялись мгновенно, а не спустя сотни миллисекунд.

Подведём итог

• Не вызывайте ReadFile, чтобы прочитать 68 байт. Или, по крайней мере, не делайте это сотню тысяч раз. Меня бесит, когда базы данных выполняют считывание по 4 кибибайта ^[10], но этот случай просто удивителен.
• Надеюсь, кто-нибудь устранит эту проблему, но пока у меня есть обходное решение — удаление проблемного файла.
• Надеюсь, кто-нибудь возьмётся за исследование и выяснит, почему вообще тормозят контекстные меню. Эй, я ведь даже поделился трассировкой ETW ^[4] и всем остальным!
• Отчёт по официальным каналам передан в https://aka.ms/AA60dfg ^[11]
• Если вы хотите научиться проводить подобный анализ, тогда скачайте мой инструмент UIforETW ^[3] и прочитайте туториалы, ссылки на которые выложены здесь ^[1]
• Не забывайте, что можно открыть контекстное меню гораздо быстрее (это проще, чем стандартное меню списка переходов), нажав shift+правой клавишей мыши на значки ^[12]. Я буду пользоваться этим трюком, когда нужно будет закрывать много окон.
• Обсуждение на Hacker news находится здесь ^[13]
• Обсуждение на Reddit находится здесь ^[14]
• Темы в Twitter находятся здесь ^[2] и здесь ^[15]

Автор: PatientZero

Источник ^[16]