Задержки панели задач Windows и вызовы к ядру

Эта статья — перевод статьи Брюса Доусона Taskbar Latency and Kernel Calls, в которой он профилирует системные приложения Windows с помощью созданного им приложения UIforETW.

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

Это раздражало меня довольно долго, но я проявлял несвойственную мне выдержку и удерживал себя от того, чтобы отвлекаться. До тех пор, пока сегодня меня это наконец не достало и я не записал ETW-трейс.

Эта статья — эксперимент в скоростном блоггинге. Время от нахождения проблемы и написания саркастического твита на эту тему до написания этой статьи составило примерно 90 минут.

В трейсе ETW я записал, как я нажимаю правой кнопкой мыши, чтобы закрыть два окна Проводника. Я использовал UIforETW в режиме трейсинга в файл с настройками по умолчанию и получил трейс на 20,9 МБ.

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

Первым сигналом были события ввода. В UIforETW встроен логгер ввода (достаточно анонимизирующий, чтобы я ненароком не украл пароли или персональную информацию), так что я просто развернул события MouseUp с номером кнопки 2, который обозначает правую кнопку мыши. Так я и получил таймлайн WPA, показывающий, когда это события произошли — см. вертикальные линии:

Здесь показано, когда я отпустил правую кнопку мыши, и показано любопытное изменение фокуса окна, которое произошло на 600 мс позже. А между событием мыши и изменением фокуса — заметная активность ЦП в RuntimeBroker.exe.

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

Следующий шаг — определить, чем занимался RuntimeBroker.exe. CPU Usage (Precise) (таблица точной активности ЦП) хорошо подходит для того, чтобы понять, сколько времени ЦП уходит на тот или иной процесс и почему он простаивает, но для того, чтобы понять, куда конкретно уходит процессорное время, нужно использовать CPU Usage (Sampled) (таблицу выборочной активности ЦП). Я развернул эту таблицу и увидел, что 264 выборки попали в KernelBase.dll!ReadFile:

Покопавшись немного, я увидел другие стэки, которые попадали в эту функцию, поэтому я нажал на неё правой кнопкой мыши и кликнул View Callers -> By Function (Показать вызывающих -> По функциям). Теперь я увидел другую таблицу (где стэки уже были перевёрнуты), которая показывала, что всего через все стэки в эту функцию попало 628 выборок, что составляло 70% от всех 899 выборок в этом процессе:

271 выборка в этом потоке не прошла через эту функцию, а оставшиеся выборки (не показаны) были в других потоках.

Замечу, что 899 выборок в треде с ID 10252 соответствуют двум нажатиям правой кнопки мыши, так что на одно нажатие пришлось около 450 выборок или 450 мс (используя стандартную частоту выборки 1 КГц).

Иногда файловый ввод/вывод — это процессорное время

Таблица выборочной активности ЦП показывает процессорное время, так что ввод/вывод диска там обычно не показывается, так как поток просто уходит в сон и ожидает диска. Если он обозначился как процессорное время, это означает, что все случаи чтения попадали в системный кэш, и процессорное время обозначает оверхед ядра (обратите внимание на ntoskrnl.exe в первом увиденном стэке вызовов) на получение данных из кэша.

Теперь, когда наше подозрение упало на ввод/вывод, нужно заглянуть в Graph Explorer -> Storage -> File I/O (Просмотр графов -> Накопители -> Файловый ввод/вывод), и после небольшой перетасовки колонок мы получаем поразительный результат:

Здесь показано, что во время двух нажатий правой кнопкой мыши RuntimeBroker.exe, поток 10252, совершил 229 604 вызовов ReadFile к одному файлу, всего прочитав 15 686 586 байтов. То есть в среднем, каждый раз читалось 68 байтов.

Просто задумайтесь об этом на секунду.

Помните, что это вызовы к операционной системе — вызовы к ядру. То есть, никакого кэширования между RuntimeBroker.exe и этим файлом не было. И вообще, сам файл занимает только 4 027 904 байта, так что каждый раз, когда я нажимаю на иконку Проводника в панели задач, этот файл перечитывается 3,9 раз самым неэффективным способом.

После некоторого ободрения от моих подписчиков я решил удалить этот файл, и теперь мои меню выскакивают практически мгновенно. Я не советую удалять этот файл, но вам тоже это может помочь (ценой потери истории Проводника):

%appdata%\Microsoft\Windows\Recent\AutomaticDestinations\f01b4d95cf55d32a.automaticDestinations-ms

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

Или же "можете использовать галочку в Настройках, чтобы удалить (перелючите её два раза) или отключить (один раз) списки недавно используемого в меню Пуск и панели задач. Не забудьте отключить анимации, чтобы ещё выиграть ещё немного скорости". Спасибо, Рафаэль!

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

Итоги

• Не надо вызывать ReadFile, чтобы прочитать 68 байтов. Или хотя бы не делайте это сотни тысяч раз! Меня передёргивает, когда базы данных делают чтения по 4 КБ, но это — просто поразительно.
• Надеюсь, кто-нибудь это исправит. А пока не исправят, у меня есть воркэраунд — удалить проблемный файл.
• Надеюсь, кто-нибудь займётся проблемой медленных контекстных меню в принципе. Я ведь расшарил ETW-трейс, и вообще.
• Я оставил отзыв на официальном сервисе: https://aka.ms/AA60dfg
• Если вам интересен такой тип анализа, скачайте моё приложение UIforETW и прочтите мои туториалы, ссылка тут.
• Кстати, вы можете вызвать контекстное меню (проще, чем обычное меню последнего используемого), которое будет быстрее, нажав Shift+правая кнопка мыши. Я буду так делать, чтобы закрыть много окон.
• Обсуждение на Hacker News тут.
• Обсуждение на Reddit тут.
• Мои треды в Твиттере тут и тут.