Всё началось, как это часто бывает, когда моя машина начала подтормаживать. На рабочем компьютере Windows 10 c 24-ядерным процессором (48 потоков) — и они на 50% простаивали. Из 64 ГБ памяти использовалось меньше половины. Быстрый SSD тоже не особо использовался. И всё же, когда я двигал мышкой, курсор реагировал не сразу — иногда с задержкой в несколько секунд.
Так что я сделал то, что всегда делаю — записал трассировку событий с помощью ETW и проанализировал её. В результате я обнаружил баг Windows 10, серьёзно влияющий на производительность завершения процессов.
Трассировка ETW показала, что UI зависает во многих программах. Я решил исследовать 1,125-секундное зависание в Диспетчере задач:
На скриншоте внизу вы можете видеть использование системой CPU во время зависания, сгруппированное по названиям процессов — обратите внимание, что использование CPU редко поднимается выше 50%.
Таблица CPU Usage (Precise) показывает, что поток UI Диспетчера задач постоянно блокировался вызовами к функциями вроде SendMessageW, видимо, ожидающих в критической секции ядра (это версия критических секций в режиме ядра), глубоко в стеке вызовов в win32kbase.sys!EnterCrit (не показано здесь):
Я вручную прошёл по цепочке ожидания через полдесятка процессов, чтобы найти, кто заграбастал ресурсы моего UI. В результате анализа мои заметки выглядят примерно так:
Taskmgr.exe (72392) завис на 1,125 с (MsgCheckDelay) на треде 69,196. Наибольшая задержка была 115,6 мс на win32kbase.sys!EnterCrit, который был подготовлен процессом conhost.exe (16264), тред 2560 на 3.273101862. conhost.exe (16264), 2560 был подготовлен на 3.273077782 после ожидания 115,640.966 мс, процессом mstsc.exe (79392), 71272. mstsc.exe был подготовлен (то же время, та же задержка) процессом TabTip.exe (8284), 8348, который был подготовлен процессом UIforETW.exe (78120), 79584, который был подготовлен процессом conhost.exe (16264), 58696, который был подготовлен процессом gomacc.exe (93668), 59948, который был подготовлен процессом gomacc.exe (95164), 76844.
Я вынужден был идти дальше, потому что большинство процессов отпускали блокировку всего через несколько микросекунд. Но в итоге я нашёл несколько процессов (процессы gomacc.exe), которые как будто держали блокировку несколько сотен микросекунд. Или, по крайней мере, они были подготовлены кем-то, кто удерживал блокировку, а затем через несколько микросекунд они готовили кого-то ещё для её снятия. Все эти процессы снимали блокировку в пределах NtGdiCloseProcess.
Я устал вручную ходить по этим цепочкам ожидания, так что решил посмотреть, как часто встречается такой же стек вызовов. Я сделал это, перетащив колонку Ready Thread Stack налево и поискав там NtGdiCloseProcess. Затем я использовал опцию View Callers -> By Function в WPA, чтобы отобразить все стеки Ready Thread Stacks, которые встречались с этой функцией — в этом окне родительские стеки внизу.
Произошло 5768 контекстных переключений, когда процесс NtGdiCloseProcess был в стеке Ready Thread Stack, и каждый из них означает момент, когда освобождается критическая секция. Потоки на этих стеках вызовов провели в ожидании в общей сложности 63,3 секунды — неплохо для задержки в 1,125 с! И если каждое из этих событий случилось после того, как поток удержал блокировку всего на 200 микросекунд, то 5768 событий будет достаточно, чтобы сложиться в подвисание на 1,125 с.
Я не знаком с этой частью Windows, но сочетание PspExitThread и NtGdiCloseProcess ясно показывает, что такие поведение наблюдается при завершении процесса.
Это происходило во время сборки Chrome, а сборка Chrome порождает много процессов. Я использовал нашу распределённую систему сборки, то есть процессы создавались — и завершались — очень быстро.
Следующим шагом было найти, сколько времени потрачено внутри NtGdiCloseProcess. Так что я перенёс таблицу CPU Usage (Sampled) в WPA и получил граф «бабочка», на этот раз вызовов NtGdiCloseProcess. На скриншоте внизу показано, что из всего времени 1,125 с около 1085 мс было потрачено внутри процесса NtGdiCloseProcess, то есть 96% всего времени:
Очень плохо, если в случае блокировки более 95% времени отнимает одна функция, особенно, если ту же блокировку нужно получить для вызовв GetMessage или обновления положения курсора. Ради эксперимента я написал тестовую программу, которая с максимальной скоростью создаёт 1000 процессов, ждёт 0,5 секунды, а затем командует всем процессам завершиться одновременно. На скриншоте показано использование этой программой CPU на моём четырёхъядерном (восемь потоков) домашнем ноутбуке:
Итак, что мы видим. Создание процессов ограничено по CPU, как и должно быть. А вот закрытие процессов ограничено по CPU только в начале и в конце, а в середине есть длительный промежуток (около секунды), где оно идёт серийно — используя всего один из восьми доступных потоков в системе, поскольку 1000 процессов борются за единственную блокировку внутри NtGdiCloseProcess. Это серьёзная проблема. Данный промежуток представляет собой время, когда программы зависнут, а движения курсора будут задерживаться — а иногда этот серийный промежуток растягивается на несколько секунд.
Я заметил, что проблема как будто усугубляется, когда компьютер работал некоторое время, так что я перезагрузил ноутбук и снова запустил тест после загрузки. Серийность завершения процессов была не такой тяжёлой, но проблема явно присутствовала даже на только что загруженной машине:
Если запустить такой же тест на старом компьютере Windows 7 (Intel Core 2 Q8200, образца 2008 года), то вот результаты:
Создание процессов здесь идёт медленнее, как и можно было ожидать на гораздо более слабом CPU, но завершение процессов настолько же быстрое, как на моём новом ноутбуке, и полностью распараллелено.
Это указывает на то, что сериализация завершения процессов — новая проблема, которая появилась где-то между Windows 7 и Windows 10.
48 потоков, 47 из них простаивают
Закон Амдала говорит, что если вы распределите свою задачу среди достаточного количества ядер, то суммарное время её выполнения будет равно времени выполнения самого длинного фрагмента, который нельзя распараллелить. Если я интенсивно использовал свой рабочий компьютер в течение нескольких дней, то эта проблема сериализации проявляла себя достаточно явно, когда завершение процессов было значительной частью времени распределённой сборки — и большее количество ядер тут не помогало. Чтобы максимально ускорить сборку (и чтобы курсор начал двигаться во время её проведения), нужно было перезагружать компьютер каждые несколько дней. И даже тогда скорость сборки была не такой высокой, какой должна быть, так что Windows 7 выглядела всё заманчивее.
На самом деле добавление ядер в мою систему замедляло скорость реакции UI. Это потому что система сборки Chrome очень умная и порождает больше процессов, если у вас больше ядер, так что ещё больше завершающихся процессов борются за глобальную блокировку. Поэтому здесь не просто «24-ядерный CPU, а я не могу сдвинуть курсор», а здесь «24-ядерный CPU, и поэтому я не могу сдвинуть курсор».
О проблеме сообщили в Microsoft, они проводят расследование.
И ещё кое-что...
Вот как выглядит моя тестовая программа по созданию и завершению процессов на 24-ядерной машине:
Видите эту маленькую горизонтальную красную линию в правом нижнем углу? Это наглядная иллюстрация закона Амдала, когда 98% ресурсов моей машины простаивают почти две секунды, в то время как процедура завершения процессов заграбастала блокировку, которая мне нужна, чтобы переместить курсор.
Материалы
Код ProcessCreateTests доступен здесь.
Если вам понравилась эта статья, вам могут понравиться и другие расследования:
«Твой браузер попал в мой компилятор!»
«Завершение работы Windows: расследование и идентификация» (и продолжение)
«Проблема слабой производительности PowerPoint»
«DoS-атака Visual Studio на саму себя через функцию поиска»
Автор: m1rko
