ОС Windows долгое время попрекали за медлительность её файловых операций и медленное создание процессов. А почему бы не попробовать сделать их ещё более медленными? Эта статья покажет способы замедления файловых операций в Windows примерно в 10 раз от их нормальной скорости (или даже больше), причём способы эти практически не поддаются отслеживанию обычным пользователем.А ещё, конечно же, мы научимся подобные ситуации обнаруживать и исправлять. Весь текст написан на основе проблемы, с которой я столкнулся пару месяцев назад, так что всё, написанное ниже, полностью реально.
Что-то пошло не так
Иногда наиболее ценной информацией, которая у вас есть при попытке что-то ускорить, есть само знание того, что это точно можно ускорить. Ну, знаете, как в школе — задача решается потому, что это задача, а значит у неё точно должно быть решение.
Когда дело касается кода, который находится полностью под вашим контролем — здесь проще. Можно сравнить быстродействие различных версий, покопаться, поговорить с его авторами, с какого-то этапа также начинает работать ведомая опытом интуиция.
Когда же речь идёт о «чёрном ящике», каким, например, является реализация файловой системы NTFS от Microsoft, становится сложнее. Но и здесь можно найти кое-какие подсказки:
- Вы замечаете, что некоторые файловые операции, которые раньше работали быстро, вдруг стали работать медленно. Вероятно, их можно снова заставить работать быстро.
- Одни и те же файловые операции иногда работают быстро, а иногда — медленно. Возможно, их можно заставить работать быстро всегда.
- При профилировании своего приложения вы видите хорошую производительность файловых операций в большинстве случаев, кроме нескольких «горячих» мест, где всё почему-то работает значительно хуже среднего. Возможно, вы можете изменить свой код так, чтобы избежать данной проблемы.
В моём случае я заметил сразу все три вышеуказанных подсказки, что дало мне возможность найти причину проблем — она оказалась в одном из используемых мною инструментов, который оказался способен замедлить файловые операции во всей ОС. Вместе с автором данного инструмента нам удалось разобраться в просходящем и выпустить фикс.
Медленное удаление файлов
Снова и снова собирая из исходников Chromium, я заметил, что очистка директории с результатами сборки стала занимать несколько минут — это довольно значительная часть цикла сборки. Я был уверен, что это должно происходить быстрее. Я также заметил, что данной проблемы не случается, если в момент удаления данных файлов не запущена Visual Studio.
Спойлер
Visual Studio оказалась ни в чём не виновата!
Профилирование с помощью ETW не показало явного виновника происходящего, но дало несколько подсказок, которые привели меня к мысли, что дело может быть в VsChromium — расширении для Visual Studio, которое делает работу над проектом Chromium в Visual Studio несколько удобнее. Одной из важных его фич является загрузка всего исходного кода проекта в оперативную память (для дальнейшего быстрого поиска). В случае Chromium это несколько гигабайт RAM, но зато поиск работает за милисекунды. Мне это расширение очень помогает в работе, но десятикратное замедление файловых операций — не та цена, которую я готов за это платить.
Воспроизведение проблемы
Для написания данной статьи я сэмулировал проблему, написав скрипт на Python, который создаёт и удаляет тысячи файлов в папке, которая находится под наблюдением VsChromium. Запустив данный скрипт, я собрал трейс событий с помощью ETW. Вот график использования процессора в WPA (Windows Performance Analyzer) и таблица с временем (в милисекундах). Всего скрипт работал около 5 секунд:
Кажется обоснованным, что процесс python.exe, который выполняет мой скрипт, использует значительную часть ресурсов CPU. Также понятно, что процесс System тоже будет занят кое-какой работой, поскольку мы занимаемся добавлением и удалением файлов. Кроме того, мы видим в таблице работу расширения VsChromium, поскольку оно наблюдает за той самой папкой, в которой мы создаём и удаляем файлы, а значит должно реагировать на это (добавлять и удалять файлы из индекса). Ну и, наконец, SearchIndexer.exe использует немного ресурсов для индексации новых файлов. Вроде бы всё выглядит неплохо. И всё же — мы знаем, что код работает слишком медленно.
Вот, для контраста, график использования процессора в случае создания и удаления файлов в директории, которая не находится под наблюдением VsChromium. Производительность поднялась почти в 10 раз! Понятное дело, что загрузка от VsChromium.Server.exe и devenv.exe исчезла полностью, но на этом всё не заканчивается. Сам python, выполняющий мой скрипт, также стал работать намного быстрее (время выполнения скрипта упало с 4888 мс до 561 мс). Процесс System вообще ускорился с 2604 мс до 42 мс. Что же здесь происходит?
График CPU Usage (Precise), который основывается на информации о переключении контекстов, даёт хорошую возможность сказать, сколько именно процессорных ресурсов использует тот или иной процесс. Но чтобы понять, на что именно процесс тратит время, нужно воспользоваться графиком CPU Usage (Sampled). Он основан на «снимках» стека вызовов функций (по-умолчанию, сделанным с частотой 1000 раз в секунду).
Этот вид представления данных группирует данные по процессам, затем по потокам, затем по модулям и, наконец, по функциям. В данном случае для процесса python.exe мы видим, что в 4637 снимках из 4904 какая-то работа происходила в модуле ntoskrnl.exe. Это намного больше, чем время выполнения кода в python27.dll (им вообще можно пренебречь).
Углубляясь в исследование того, что делал ntoskrnl.exe, мы видим какие именно функции в нём вызывались:
Чаще всего вызывалась функция выделения памяти MiAllocatePagedPoolPages и функции очистки памяти memset, MiCompletePrivateZeroFault, а также ассоциированные с ними отказы страниц. Кажется немного странным, что в тесте работы файловой системы больше всего ресурсов занимают задачи выделения и очистки памяти, правда? Но подождите, это ещё не всё. Вторым по занятости в системе является процесс System, и занят он (чем бы вы думали?) обнулением только что освобождённых страниц памяти. Что же, всё-таки, происходит?
Вернувшись к анализу снимков колстека процесса python.exe, я поискал функцию memset и нашел её где-то на 70 уровней ниже по колстеку (не удивительно, что раньше я её пропустил). Правый клик на ней, выбираем View Callers-> By Function и видим, что общие затраты на её вызов (включая время выполнения «дочерних функций») составляют примерно половину всей загрузки процессора — 2971 снимок из 4904 сделанных.
Вызывающей функцией практически всегда была FsRtlNotifyFilterReportChangeLiteEx. Правый клик на ней, View Callees-> By Function. Это показало мне, что данная функция выделяла память, вызывала memset для неё и потребляла около 83% процессорного времени в процессе python.exe.
В поисках проблемы
В этом месте моего исследования у меня было несколько, как позже оказалось, неверных догадок. Одна из них касалась частых вызовов wcifs.sys!WcGenerateFileName — я подумал, что генерация имён файлов в формате «8.3» работает слишком медленно, но её отключение ничего не изменило. В конце-концов я остановил свои попытки постичь непостижимые колстеки и вместо этого задумался о том, как работает расширение VsChromium. При загрузке оно просто должно прочесть и загрузить в память всё содержимое файлов в контролируемой папке. Но после этого ему нужно всего лишь отслеживать изменения и я предположил, что оно имеет что-то типа монитора изменений файловой системы. Я знал, что расширение недавно получило обновление и в нём автор увеличил буфер, в котором хранились нотификации об изменениях файлов, с 16 KB до 2 MiB. И почему-то операционной системе это очень не понравилось. Я попробовал откатиться к предыдущей версии расширения (с меньшим буфером) — и это действительно исправило проблему.
Данный буфер выделялся с помощью функции ExAllocatePoolWithTag, а затем заполнялся информацией об изменениях в файловой системе. Для избежания утечки данных из ядра ОС, вся неиспользуемая часть буфера обнулялась. Если буфер достаточно большой, а объём пересылаемой информации относительно мал — обнуление будет занимать большую часть времени. Я добавил провайдер данных ALL_FAULTS (который я нашел, просматривая результат вызова “xperf -providers k”) к моей ETW-сессии чтобы увидеть как часто случались отказы страниц. И это было впечатляюще! Случилось 2,544,578 отказов страниц при попытках обнуления данных, что соответствует 9.7 GiB данных или около 4970 раз по буферу в 2 MiB. Это 4.97 буфера на каждую тысячу созданных и удалённых файлов. Мне подсказали, что VsChromium должен создавать около 5 событий на каждый созданный и удалённый файл, а значит большинство буферов с нотификациями будут содержать лишь одну запись. Вот отказы страниц по процессам и типам:
Зачем такой большой буфер?
Документация для FileSystemWatcher рекомендует не использовать большой буфер, но не вдаётся в подробности о том, чем это грозит. На машинах разработчиков Chrome достаточно много оперативной памяти, так что когда однажды очень частые файловые операции (баг в ядре Windows, о котором я писал ранее) привели к переполнению ранее использованного буфера в 16 КВ, его просто значительно увеличили. И это, на первый взгляд, помогло. По крайней мере тогда, для решения той проблемы. Хотя и замедлило файловые операции во много раз.
Когда автор расширения VsChromium узнал о проблеме, он решил уменьшить буфер обратно и обрабатывать ошибки его переполнения более изящно (временно приостанавливая мониторинг).
Ирония данной ситуации состоит в том, что большинство затрат ресурсов здесь (вызовы memset, отказы страниц, обнуление) случаются потому, что две разных части ядра ОС не достаточно хорошо общаются друг с другом. Система нотификаций запрашивает память, получает её (уже обнулённую) и снова пытается её обнулить. Если бы она знала, что память уже обнулена — то не пыталась бы сделать это во второй раз, и не было бы лишних отказов страниц, и жизнь была бы куда лучше. Эй, Microsoft, у меня есть классная идея о том, как сделать систему нотификаций об изменениях файловой системы лучше!
Вооружимся этим знанием
Достаточно просто написать код на С#, который будет мониторить изменения файловой системы для корня всех имеющихся у нас дисков, используя при этом буфер для нотификаций сначала небольшого, а потом существенно большего размера. Мне интересно, каким будет влияние на быстродействие системы при буфере в 10 MiB, и ещё интересно, каким должен быть его размер, чтобы используя эту, казалось бы, невинную возможность пользовательского режима, замедлить Windows до крайне возможной степени?
ETW-трейсы позволяют достаточно просто понять, что буферы для нотификаций являются проблемой — каждый процесс, выполняющий какие-то файловые операции будет показывать крайне много времени, потраченного в ntoskrnl.exe!FsRtlNotifyFilterReportChangeLiteEx. Это показывает, что кто-то использует очень большой буфер для нотификаций, но как нам найти процесса-виновника? Очень просто — поскольку память в нашем случае выделялась с помощью ntoskrnl.exe!ExAllocatePoolWithTag, то освобождаться она будет с помощью ntoskrnl.exe!ExFreePoolWithTag. Мы можем поискать вызовы этой функции в имеющихся у нас коллстеках и найти тот, где их много.
Другие полезные ссылки
Исходный код на С# для FileSystemWatcher можно скачать вот здесь. Он реализован с помощью ReadDirectoryChangesW. Как это всё работает хорошо описано вот здесь.
Увеличение размера буфера в VsChromium случилось вот в этом коммите, который вошел в билд 0.9.26. Обратное уменьшение случилось вот в этом комите, который вошел в версию 0.9.27.
Я рекомендую всем пользователям VsChromium обновиться до последней версии.
ETW-трейсы и упомянутый в статье скрипт на Python можно скачать вот здесь. Он создаёт и удаляет файлы дважды, один раз в директории под наблюдением VsChromium, и второй раз в ненаблюдаемой директории, с полусекундной паузой. Для воспроизведения эксперимента из статьи вам, конечно, понадобиться соответствующая версия VsChromium, настроенная на мониторинг нужной папки.
А в следующей статье я расскажу о том, как Microsoft позволяет вам иногда случайно создать N процессов за O(N^2) времени.