- Перевод
«Что не так с компьютером — в нём установлен накопитель nvme, но открытие проводника, если этого давно не делали, занимает примерно 10 секунд, открытие файла .zip на рабочем столе занимает примерно минуту, а при нажатии клавиши „Пуск“ реакции нужно ждать примерно 20 секунд?»
Примерно в конце января мне показали пост в Twitter, в котором пользовательница Windows с мощной машиной рассказывает о произвольных зависаниях в Проводнике. Было предложено множество ненаучных теорий. Обычно я не занимаюсь анализом проблем производительности у незнакомых людей, но этот случай показался интересным, поэтому я решил изучить его.
Фрейя отправила мне трассировку ETW того, что происходит с её машиной и я исследовал её с помощью Windows Performance Analyzer (WPA). Первым делом я заметил, что график UI Delays показывает, как и можно было догадаться, что потоку explorer.exe 7888 не удавалось проверить сообщения в течение 20,531 секунд. Он завис.
У explorer.exe есть много UI-потоков, поэтому это не значит, что повис весь процесс, однако, одно из его окон определённо зависло и вызывало зависания повсюду, а это плохо.
Если потоку не удаётся перекачивать сообщения, то это значит, что он или занят чем-то другим (потребляет ресурсы ЦП), или ожидает чего-то другого (ЦП простаивает). Изучив более детально период времени 20,531 секунд MsgCheck Delay, я проверил данные CPU Usage (Precise) (взятые из инструментария переключения контекста) и увидел, что поток 9228 был запущен в течение 99,2% времени — он потреблял много ресурсов ЦП.
Далее надо было выяснить, что происходит. Данные CPU Usage (Sampled) (получаемые от профилировщика с сэмплированием 1 кГц) сообщили мне, что поток 9228 тратит примерно 99,7% своего времени (26994 из 27074 сэмплов) в деструкторе BatchPositionChangesHelper (строка 21) и его дочерних задачах (строки 23-25). Это очень затратный деструктор.
У меня нет доступа к этому исходному коду, но я немного поизучал стеки и они намекают, что explorer.exe тратил больше 20 секунд, выполняя множество задач, связанных… с выравниванием положения значков.
Ага, именно так
Выстраивание значков на Рабочем столе — довольно простая задача. Нужно просто выровнять их в столбцы, перейти к следующему столбцу и завершить работу, когда экраны заполнены. Поэтому 20 секунд на выстраивание значков не показалось мне реалистичным временем, и я предположил, что первопричиной может быть какое-нибудь странное расширение оболочки или другое стороннее ПО, но потом попробовал воспроизвести баг самым простым способом. Я подумал, что просто создам на Рабочем столе тысячу копий крошечного изображения .jpg и проверю, не будет ли explorer.exe тормозить. Этот эксперимент был слишком тупым, чтобы оказаться достаточным, но тем не менее:
Я запустил этот простой скрипт со значением file_count, равным 1000, и внезапно explorer.exe начал безумно тормозить более двадцати секунд. Всё действительно оказалось так просто.
Но почему?
Компьютеры сегодня очень быстры. Процессор Фрейи работает с частотой 4,6 ГГц, а на её Рабочем столе находится примерно 950 файлов GIF. За 20 секунд её ЦП должен выполнить 92 миллиарда тактов или по 97 миллионов тактов на каждое изображение. А это много.
Я предположил, что проблема была связана с наблюдением, которое я для себя назвал первым законом вычислений Доусона: O(n^2) — оптимальное время для плохо масштабируемых алгоритмов — достаточно быстро, чтобы попасть в продакшен, но достаточно медленно, чтобы ломать всё, после того, как он туда попал.
То есть наиболее вероятное объяснение того, почему выстраивание значков занимает так много времени, заключается в том, что код перестроения порядка значков использует O(n^2) (он же квадратичный) алгоритм, то есть при удвоении количества значков время на их выстраивание возрастает в четыре раза. При таком масштабировании производительности алгоритм, хорошо работающий с десятью элементами, может тормозить всего с тысячей элементов.
Хорошая теория, но как её доказать?
Научно!
Я начал с написания скрипта, который заполнит мой Рабочий стол заданным количеством изображений. Я многократно запускал его со всё большими количествами изображений и записал трассировку ETW, чтобы можно было замерить производительность. Также я отслеживал explorer.exe с помощью Диспетчера задач, чтобы можно было понять, когда он закончил одну задачу и готов к следующей.
Мой первый тест дал хаотичные результаты, они выглядели как нелинейный рост, но любые попытки сопоставления с линией больше походили бы на веру, чем на соответствие данным. Чтобы качественнее протестировать мою теорию, мне нужно было понять, что происходит.
Изучая трассировки, я понял, что деструктор BatchPositionChangesHelper выполнялся бОльшую часть времени (синяя область), но не всё время работы explorer (зелёная область):
Я осознал, что, помимо прочего, работа по выстраиванию прерывается работой по отображению, после чего понял причину такой вариативности.
Когда мой скрипт на Python начинал создавать изображения, процесс explorer.exe замечал это и сразу же начинал пытаться разместить значки. В процессе создания изображений он мог делать это несколько раз, что давало непредсказуемые результаты. Это была ситуация гонки, из-за которой постоянство общих затрат оказывалось нарушенным. Так как у меня не было доступа к исходному коду explorer.exe, мне нужно было придумать способ заставить его ждать завершения создания всех изображений, а потом уже выполнять выстраивание. Я реализовал это с помощью библиотеки psutil, позволившей приостановить процесс explorer.exe, пока создавались изображения. Затем, когда я возобновлял процесс, он проделывал всю работу. Код выглядит примерно так:
Сделав это, я запустил свой тестовый пакетный файл, параллельно записывая трассировку ETW. Для минимизации шума и размера трассировки я отключил стеки вызовов переключения контекста (необязательные) и выключил индексирование папки Рабочего стола. Я отслеживал загрузку ЦП процессом explorer.exe с помощью Диспетчера задач и нажимал на Enter, чтобы перейти к следующему тесту, когда загрузка падала до нуля. Так я получил очень красивый график загрузки ЦП процессом explorer.exe:
Отдельные блоки обозначают загрузку ЦП для 100, 200, 300 и так далее изображений вплоть до 1000. Если вы внимательны, то заметите, что загрузка ЦП увеличивается быстрее, чем линейно, но медленнее, чем квадратично. То есть изначальные данные позволяют предположить, что алгоритм выстраивания не-совсем-O(n^2).
Однако explorer занимается не только выстраиванием. Если некоторые из задач O(n), то есть линейны, то они ослабят влияние задач O(n^2). При увеличении n задачи O(n^2) постепенно начнут доминировать, но я не хотел, чтобы моя тестовая программа работала даже дольше 160 секунд, которых требует её выполнение.
Изолирование
Значит, следующей задачей будет изолирование времени, потраченного на деструктор BatchPositionChangesHelper. В моей тестовой трассировке оно составило 78,4% времени, потраченного в explorer.exe, и 92,3% времени, потраченного в занятом потоке, и если я смогу доказать, что оно было квадратичным, то докажу, что при увеличении n оно будет доминировать навсегда.
Для этого я посмотрел на данные CPU Usage (Sampled) и отфильтровал их, чтобы отображались сэмплы только в деструкторе BatchPositionChangesHelper и его дочерних задачах. Затем я рассмотрел десять разных областей графика и составил график количества сэмплов. Кривая настолько плавная, что выглядит подделкой, но это именно настоящие данные.
Если взглянуть на ключевые точки графика, например, где количество изображений равно 500, а потом 1000, то можно увидеть, что масштабирование производительности происходит немного хуже, чем O(n^2). То есть для выстраивания 1000 значков требуется в четыре с лишним раза больше времени, чем на выстраивание 500 значков.
Решающий удар
Обычно у меня на Рабочем столе мало значков, поэтому я практически неуязвим для этого бага. Однако я видел людей, Рабочий стол которых полностью заполнен значками. У них, вероятно, он проявляется, но в менее серьёзной форме.
Фрейя использовала свой Рабочий стол для хранения файлов GIF. Она обращалась с ним, как с папкой (чем он собственно и является), в которой можно удобно хранить изображения. Она редко пользовалась значками с Рабочего стола. Поэтому когда количество значков со временем стало избыточным, она решила снять флажок «Show desktop icons» («Отображать значки рабочего стола»), чтобы было меньше неразберихи. Значки скрылись и она могла продолжать сохранять изображения в эту папку.
Но тем не менее…
Испытываемые ею зависания, при которых explorer тратил 20 с лишним секунд на выстраивание значков на Рабочем столе, тратя 92 миллиарда тактов ЦП на правильное размещение значков, происходили… тогда, когда значки были скрыты.
Это какой-то новый уровень удивительности.
Выстраивание значков в сетку изначально должно быть линейной операцией, но каким-то образом её написали квадратичной и она выполнялась вне зависимости от того, показываются значки, или нет.
Вот и всё. Если вы пишете код, который будут запускать другие, то убедитесь, что он достаточно хорошо масштабируется для обработки любого возможного множества данных, вне зависимости от его разумности. Квадратичные алгоритмы обычно проваливают эту проверку.
Ловушки
Похоже, что этот баг связан с изменением схем использования нескольких мониторов (как мне сказали, такая необходимость часто возникает у стримеров), поэтому какое-то время я проводил тесты, подключая и отключая свой внешний монитор. Это плохо подходит для эффективного тестирования, к тому же, похоже, я испортил разъём для внешнего монитора у своего личного ноутбука. Больше он не видит внешний монитор. Упс.
Да, с символами
Когда я анализировал трассировку Фрейи, я просто загрузил её в Windows Performance Analyzer (WPA) и подождал. Мне не нужно было проверять версию Windows, на которой она работала, и знать, какие патчи у неё установлены. WPA просто изучал отладочную информацию всех EXE и файлов PE и скачивал файлы символов с серверов символов Microsoft (и с серверов Chrome, потому что я это разрешил). Серверы символов — это хорошо. Если вы работаете в Windows, то включите использование серверов символов. Если вы не в Windows, то сильно вам сочувствую (жаль, что отладка и профилирование, особенно проблем на машинах других пользователей, для вас гораздо сложнее).
Сообщаем о проблеме
Не знаю, на скольких людей повлиял этот баг (те, у кого 200-300 значков, она касается достаточно слабо, а при большем количестве ситуация постепенно становится хуже), и не имею возможности его устранить. Поэтому я сообщил о нём. Я не питаю особых надежд, что его исправят. Под моим последним багом квадратичного времени в Windows ноль комментариев, несмотря на то, что я опубликовал его несколько месяцев назад.
Сырые измерения из моих тестов сохранены здесь, а сами тесты находятся на github. Этот баг чрезвычайно легко воспроизвести. Если кто-то захочет создать запись Feedback Hub, то это нужно сделать. Рекомендую при зависании Рабочего стола использовать опцию UIforETW Browse Folder — операция будет заблокирована на всё время зависания.
Уроки для разработчиков ПО
За свою карьеру я много раз участвовал в собеседованиях. Часто мне давали задание придумать алгоритм, выполняющий какую-то искусственную задачу. Очевидный алгоритм «грубого перебора» обычно оказывается квадратичным (O(n^2)) или реже экспоненциальным (O(2^n)). Чаще всего это приводит к обсуждению следующих тем:
- Почему квадратичные и экспоненциальные алгоритмы неприемлемо медленны для большинства задач реального мира
- Как усовершенствовать алгоритм, чтобы он был O(n log n) или лучше.
Несмотря на осознание этой проблемы, мы, разработчики, продолжаем писать квадратичный код. Код, который достаточно быстр, чтобы попасть в продакшен, но достаточно медленный, чтобы поломать всё, когда он туда попадёт. См., например, эту, эту, эту, эту и эту статьи. Нам нужно перестать так делать.
Коментарі
Дописати коментар