Всё началось, как это часто бывает, когда моя машина стала подтормаживать. На рабочем компьютере 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. В результате анализа мои заметки выглядят примерно так:
Я вынужден был продолжать, потому что большинство процессов отпускали блокировку всего через несколько микросекунд. Но в итоге я нашёл несколько процессов (процессы 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.
Закон Амдала говорит, что если вы распределите свою задачу среди достаточного количества ядер, то суммарное время её выполнения будет равно времени выполнения самого длинного фрагмента, который нельзя распараллелить. Если я интенсивно использовал свой рабочий компьютер в течение нескольких дней, то эта проблема сериализации проявляла себя достаточно явно, когда завершение процессов было значительной частью времени распределённой сборки — и большее количество ядер тут не помогало. Чтобы максимально ускорить сборку (и чтобы курсор начал двигаться во время её проведения), нужно было перезагружать компьютер каждые несколько дней. И даже тогда скорость сборки была не такой высокой, какой должна быть, так что Windows 7 выглядела всё заманчивее.
На самом деле добавление ядер в мою систему замедляло скорость реакции UI. Это потому что система сборки Chrome довольно умная и порождает больше процессов, если у вас больше ядер, так что ещё больше завершающихся процессов борются за глобальную блокировку. Поэтому здесь не просто «24-ядерный CPU, а я не могу сдвинуть курсор», а здесь «24-ядерный CPU, и поэтому я не могу сдвинуть курсор».
О проблеме сообщили в Microsoft, они проводят расследование.
Вот как выглядит моя тестовая программа по созданию и завершению процессов на 24-ядерной машине:
Видите эту маленькую горизонтальную красную линию в правом нижнем углу? Это наглядная иллюстрация закона Амдала, когда 98% ресурсов моей машины простаивают почти две секунды, в то время как процедура завершения процессов заграбастала блокировку, которая мне нужна, чтобы переместить курсор.
Код ProcessCreateTests доступен здесь.
Если вам понравилась эта статья, вам могут понравиться и другие расследования:
«Твой браузер попал в мой компилятор!»
«Завершение работы Windows: расследование и идентификация» (и продолжение)
«Проблема слабой производительности PowerPoint»
«DoS-атака Visual Studio на саму себя через функцию поиска»
Так что я сделал то, что и всегда — записал и проанализировал трассировку событий с помощью 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 на саму себя через функцию поиска»
