Автор: Брюс Доусон.
Источник: 24-core CPU and I can’t type an email (part one).
Я не искал неприятность. Я не пытался собирать Chrome тысячи раз в неделю, а просто занимался самой обычной задачей 21 века, писал электронное письмо в 10:30. Внезапно gmail "повис". Я продолжал печатать, но несколько секунд на экране не появлялось никаких символов. Затем gmail "ожил", и я продолжил писать очень важное письмо. Потом это повторилось, только в этот раз gmail не подавал признаков жизни дольше. Это забавно…
Мне трудно устоять перед хорошей загадкой производительности, но в этом случае тяга к расследованию была особенно сильной. Я работаю над Chrome для Windows с прицелом на производительность. Расследование этого зависания и было моей работой. После множества фальстартов и значительных усилий я выяснил, как Chrome, gmail, Windows и наше IT-подразделение вместе не давали мне набирать текст письма, а также нашёл способ сэкономить существеный объём памяти для некоторых веб-страниц в Chrome.
В этом расследовании было столько кроличьих нор, что я приберегу некоторые отступления для следующей записи, а сейчас я сосредоточусь исключительно на зависаниях.
Как обычно, у меня фоново работал UIforETW с записью в циклические буферы, поэтому мне понадобилось только нажать Ctrl+Win+R, чтобы данные за последние тридцать секунд активности системы были сохранены на диск. Я загрузил их в Windows Performance Analyzer (WPA), однако не мог найти зависание.
Когда программа для Windows перестаёт обрабатывать сообщения, ETW создаёт события, указывающие, где именно это произошло, так что подобные зависания найти легко. Но Chrome продолжал обрабатывать сообщения. Я искал момент времени, в который ключевые потоки Chrome были заняты или бездействовали, но не нашёл ничего убедительного. Было несколько моментов, когда Chrome главным образом бездействовал, но даже тогда все ключевые потоки продолжали работать, поэтому не было определённости с местом зависания – Chrome бездействовал, потому что ничего не происходило:
UIforETW располагает встроенным средством отслеживания нажатий клавиш, что полезно при определении ключевых моментов. Тем не менее, в целях безопасности по умолчанию каждая цифра заменяется на ‘1’, а каждая буква - на ‘A’. Это осложнило поиск точного момента времени зависания, поэтому я поменял режим отслеживания ввода с “Private” на “Full” и ждал зависания. На следующий день около 10:30 зависание повторилось. Я сохранил содержимое буферов и вставил данные в UIforETW:
Хорошо, но почему Chrome прекратил работать? На иллюстрациях не видно, что в этот момент WmiPrvSE.exe занимал целый поток процессора. Но это не должно иметь значения. У моей машины 24 ядра/48 потоков, так что в случае использования одного потока она простаивает на 98%.
Затем я сделал детализацию периода, когда Chrome бездействовал, и обратил внимание на CrRendererMain в chrome.exe (27368), процессе вкладки gmail.
Это связано с тем, что блокировки Windows спроектированы недостаточно чисто, и если поток освобождает блокировку и затем сразу пытается получить её, то он может, как в данном случае, благополучно получать её каждый раз. Голод. Подробнее в следующий раз.
В каждом случае процессом, который уведомил Chrome о доступности блокировки, был WmiPrvSE.exe:
Преимущество в написании собственной программы было в том, что я мог начать генерировать статистические данные. NtQueryVirtualMemory возвращает данные о каждом диапазоне адресного пространства с указанными атрибутами (все зарезервированные, все выделенные с конкретными настройками безопасности и т.д.). Процессу gmail принадлежало около 26 000 блоков, но я нашёл другой процесс (как оказалось, WPA), у которого было 16 000 блоков памяти, которые сканировались очень быстро.
В какой-то момент я посмотрел на процесс gmail в программе vmmap и заметил, что у него значительное количество памяти (361 836 КБ) и множество отдельных блоков (49 719) в категории Shareable – резерв размером 2 147 483 648 КБ, т.е. 2 ТБ. Что?
Я случайно знал, что 2 ТБ резервируется для защиты потока управления (CFG) и вспомнил, что “CFG” встречалось в стеке вызовов, когда процесс gmail Chrome был в состоянии ожидания – MiCommitVadCfgBits. Может, проблема в большом количестве блоков в области CFG!
Защита потока управления (CFG) используется для борьбы с эксплойтами. Резерв размером 2 ТБ - это разреженный битовый массив, который показывает, какие адреса (в 128 ТБ адресного пространства пользовательского режима) являются допустимыми целями косвенных вызовов. Я добавил в свой сканер виртуальной памяти подсчёт блоков области CFG (простой поиск 2 зарезервированных ТБ) и блоков исполняемой памяти. Поскольку память CFG используется для описания исполняемой памяти, то я ожидал увидеть по одному блоку памяти CFG для каждого блока исполняемой памяти процесса. Вместо этого я увидел 98 блоков исполняемой памяти и 24 866 блоков выделенной памяти CFG. Значительное расхождение:
Scan time, Committed, page tables, committed blocks
Total: 41.763s, 1457.7 MiB, 67.7 MiB, 32112, 98 code blocks
CFG: 41.759s, 353.3 MiB, 59.2 MiB, 24866
К этому моменту я сымитировал фрагментацию CFG, длительное сканирование и зависание. Ура!
Но что если у вас много объектов CodeRange, для которых выделяется и затем освобождается память со случайными адресами? Я сделал конструктор CodeRange, оставил gmail запущенным, и нашёл дымящийся пистолет. Каждую пару минут создавался (и разрушался) новый объект CodeRange. В отладчике было легко найти, что эти объекты выделяет WorkerThread::Start, и вдруг всё стало ясно:
Худшее, из того, что я видел: вкладка gmail была открыта восемь дней и накопила 353,3 МБ памяти CFG и 59,2 МБ страничных таблиц для проецирования памяти, в сумме потеряно 400 МБ. По некоторым причинам большинство людей, в отличие от меня, сталкиваются с более слабыми симптомами либо не видят их.
Большинство моих коллег и наших пользователей не сталкивалось с проблемой. Я заметил её только по следующим причинам:
Кстати, зависание происходило в 10:30, потому что именно в это время наше IT-подразделение запускает сканирование с целью инвентаризации. Для запуска сканирования вручную надо нажать кнопку "Run Now" здесь: Control Panel | Configuration Manager | Actions | Select ‘Hardware Inventory Cycle’.
Обсуждение на Hacker news
Обсуждение на Reddit
Источник: 24-core CPU and I can’t type an email (part one).
Я не искал неприятность. Я не пытался собирать Chrome тысячи раз в неделю, а просто занимался самой обычной задачей 21 века, писал электронное письмо в 10:30. Внезапно gmail "повис". Я продолжал печатать, но несколько секунд на экране не появлялось никаких символов. Затем gmail "ожил", и я продолжил писать очень важное письмо. Потом это повторилось, только в этот раз gmail не подавал признаков жизни дольше. Это забавно…
Мне трудно устоять перед хорошей загадкой производительности, но в этом случае тяга к расследованию была особенно сильной. Я работаю над Chrome для Windows с прицелом на производительность. Расследование этого зависания и было моей работой. После множества фальстартов и значительных усилий я выяснил, как Chrome, gmail, Windows и наше IT-подразделение вместе не давали мне набирать текст письма, а также нашёл способ сэкономить существеный объём памяти для некоторых веб-страниц в Chrome.
В этом расследовании было столько кроличьих нор, что я приберегу некоторые отступления для следующей записи, а сейчас я сосредоточусь исключительно на зависаниях.
Как обычно, у меня фоново работал UIforETW с записью в циклические буферы, поэтому мне понадобилось только нажать Ctrl+Win+R, чтобы данные за последние тридцать секунд активности системы были сохранены на диск. Я загрузил их в Windows Performance Analyzer (WPA), однако не мог найти зависание.
Когда программа для Windows перестаёт обрабатывать сообщения, ETW создаёт события, указывающие, где именно это произошло, так что подобные зависания найти легко. Но Chrome продолжал обрабатывать сообщения. Я искал момент времени, в который ключевые потоки Chrome были заняты или бездействовали, но не нашёл ничего убедительного. Было несколько моментов, когда Chrome главным образом бездействовал, но даже тогда все ключевые потоки продолжали работать, поэтому не было определённости с местом зависания – Chrome бездействовал, потому что ничего не происходило:
UIforETW располагает встроенным средством отслеживания нажатий клавиш, что полезно при определении ключевых моментов. Тем не менее, в целях безопасности по умолчанию каждая цифра заменяется на ‘1’, а каждая буква - на ‘A’. Это осложнило поиск точного момента времени зависания, поэтому я поменял режим отслеживания ввода с “Private” на “Full” и ждал зависания. На следующий день около 10:30 зависание повторилось. Я сохранил содержимое буферов и вставил данные в UIforETW:
Я набирал текст “defer to those with more scuba experience”, и gmail "завис" в конце слова “those” и частично "очнулся" к слову “experience”. Вкладка gmail с PID 27368.Обычное обсуждение способов добираться на работу, гораздо важнее то, что теперь можно найти зависание в трассировке ETW. Я загрузил трассировку, посмотрел на клавиатурные данные в поле Generic Events (события генерируются UIforETW, каждому из них соответствует пурпурный ромб на иллюстрации ниже) и смог точно увидеть, где было зависание, это на 100% коррелировало с провалом в использовании процессора:
Хорошо, но почему Chrome прекратил работать? На иллюстрациях не видно, что в этот момент WmiPrvSE.exe занимал целый поток процессора. Но это не должно иметь значения. У моей машины 24 ядра/48 потоков, так что в случае использования одного потока она простаивает на 98%.
Затем я сделал детализацию периода, когда Chrome бездействовал, и обратил внимание на CrRendererMain в chrome.exe (27368), процессе вкладки gmail.
Я хочу поблагодарить себя за то, что в 2015 году попросил Microsoft улучшить механизмы именования потоков, поблагодарить Microsoft за выполнение всех моих пожеланий – имена потоков в WPA великолепны!Ситуация прояснилась. Во время зависания длительностью 2,81 с этот поток был запланирован и выполнялся 440 раз. Обычно выполнения с интервалом 6 мс достаточно, чтобы сделать программу отзывчивой, но по какой-то причине это не помогло. Я заметил, что при каждом пробуждении стек не менялся. Упрощённо это выглядело так:
chrome_child.dll (stack base)Chrome вызывает функцию VirtualAlloc, которая пытается обновить некие “CfgBits” и получить блокировку. Сначала я предположил, что Chrome вызывал VirtualAlloc 440 раз; это выглядело странно, но в действительности всё было более странным. Chrome вызвал VirtualAlloc один раз и должен был получить блокировку. Chrome получил уведомление о доступности блокировки, но – 439 раз подряд – когда Chrome пробуждался и пытался получить её, она была недоступна. Блокировка был получена процессом, который только что освободил её.
KernelBase.dll!VirtualAlloc
ntoskrnl.exe!MiCommitVadCfgBits
ntoskrnl.exe!MiPopulateCfgBitMap
ntoskrnl.exe!ExAcquirePushLockExclusiveEx
ntoskrnl.exe!KeWaitForSingleObject (stack leaf)
Это связано с тем, что блокировки Windows спроектированы недостаточно чисто, и если поток освобождает блокировку и затем сразу пытается получить её, то он может, как в данном случае, благополучно получать её каждый раз. Голод. Подробнее в следующий раз.
В каждом случае процессом, который уведомил Chrome о доступности блокировки, был WmiPrvSE.exe:
ntoskrnl.exe!KiSystemServiceCopyEnd (stack base)WMI сбил меня с толку (подробнее об этом в следующий раз), но в конечном счёте я написал программу, чтобы воспроизвести поведение WMI. У меня был набор данных, который показал, на что тратил своё время процесс WmiPrvSE.exe (с небольшими правками и упрощениями):
ntoskrnl.exe!NtQueryVirtualMemory
ntoskrnl.exe!MmQueryVirtualMemory
ntoskrnl.exe!MiUnlockAndDereferenceVad
ntoskrnl.exe!ExfTryToWakePushLock (stack leaf)
WmiPerfClass.dll!EnumSelectCounterObjects (stack base)Воспроизвести медленное сканирование по набору данных оказалось довольно легко. Интересной частью вышеприведённого стека является функция NtQueryVirtualMemory, которая используется для сканирования памяти процесса и вызывается функцией с говорящим именем GetProcessVaData, где Va, вероятно означает Virtual Address. Моя программа VirtualScan просто циклически вызывала NtQueryVirtualMemory, чтобы сканировать адресное пространство заданного процесса, код работал, сканирование процесса gmail действительно затянулось (10-15 секунд) и спровоцировало зависание. Но почему?
WmiPerfClass.dll!ConvertCounterPath
pdh.dll!PdhiTranslateCounter
pdh.dll!GetSystemPerfData
KernelBase.dll!blah-blah-blah
advapi32.dll!blah-blah-blah
perfproc.dll!blah-blah-blah
perfproc.dll!GetProcessVaData
ntdll.dll!NtQueryVirtualMemory
ntoskrnl.exe!NtQueryVirtualMemory
ntoskrnl.exe!MmQueryVirtualMemory
ntoskrnl.exe!MiQueryAddressSpan
ntoskrnl.exe!MiQueryAddressState
ntoskrnl.exe!MiGetNextPageTable (stack leaf)
Преимущество в написании собственной программы было в том, что я мог начать генерировать статистические данные. NtQueryVirtualMemory возвращает данные о каждом диапазоне адресного пространства с указанными атрибутами (все зарезервированные, все выделенные с конкретными настройками безопасности и т.д.). Процессу gmail принадлежало около 26 000 блоков, но я нашёл другой процесс (как оказалось, WPA), у которого было 16 000 блоков памяти, которые сканировались очень быстро.
В какой-то момент я посмотрел на процесс gmail в программе vmmap и заметил, что у него значительное количество памяти (361 836 КБ) и множество отдельных блоков (49 719) в категории Shareable – резерв размером 2 147 483 648 КБ, т.е. 2 ТБ. Что?
Я случайно знал, что 2 ТБ резервируется для защиты потока управления (CFG) и вспомнил, что “CFG” встречалось в стеке вызовов, когда процесс gmail Chrome был в состоянии ожидания – MiCommitVadCfgBits. Может, проблема в большом количестве блоков в области CFG!
Защита потока управления (CFG) используется для борьбы с эксплойтами. Резерв размером 2 ТБ - это разреженный битовый массив, который показывает, какие адреса (в 128 ТБ адресного пространства пользовательского режима) являются допустимыми целями косвенных вызовов. Я добавил в свой сканер виртуальной памяти подсчёт блоков области CFG (простой поиск 2 зарезервированных ТБ) и блоков исполняемой памяти. Поскольку память CFG используется для описания исполняемой памяти, то я ожидал увидеть по одному блоку памяти CFG для каждого блока исполняемой памяти процесса. Вместо этого я увидел 98 блоков исполняемой памяти и 24 866 блоков выделенной памяти CFG. Значительное расхождение:
Scan time, Committed, page tables, committed blocks
Total: 41.763s, 1457.7 MiB, 67.7 MiB, 32112, 98 code blocks
CFG: 41.759s, 353.3 MiB, 59.2 MiB, 24866
vmmap показывает зарезервированную и выделенную память как блоки, а мой сканирующий инструмент считает лишь выделенные блоки, поэтому vmmap показывает 49 684 блока, а моя программа - 24 866В ретроспективе это очевидно, но что если битовый массив CFG никогда не очищается? Что если память CFG выделяется при выделении исполняемой памяти, но не освобождается при освобождении исполняемой памяти. Это могло бы объяснить такое поведение.
Воспроизведение от и до
Следующим шагом стало написание программы VAllocStress, которая выделяет и освобождает тысячи блоков исполняемой памяти со случайными адресами. Эта программа должна быть 64-разрядной и поддерживать CFG. После выделения и освобождения множества блоков исполняемой памяти эта программа должна в цикле пытаться выделить/освободить дополнительную исполняемую память и заметить, когда это делается медленно. Вот мой алгоритм для VAllocStress:- Много раз в цикле:
- Выделить посредством VirtualAlloc некоторый объём исполняемой памяти со случайным адресом
- Освободить память
- Затем в бесконечном цикле:
- "Поспать" 500 мс (не хочу "объедать" процессор)
- Выделить посредством VirtualAlloc исполняемую память с постоянным адресом
- Напечатать сообщение, если вызов VirtualAlloc занимает более 500 мс
- Освободить память
К этому моменту я сымитировал фрагментацию CFG, длительное сканирование и зависание. Ура!
Первопричина
Оказалось, что у v8 (движок JavaScript в Chrome) есть объекты CodeRange для управления кодогенерацией, и каждый объект CodeRange ограничен диапазоном адресов в 128 МБ. Он должен быть небольшим во избежание безудержного выделения памяти CFG.Но что если у вас много объектов CodeRange, для которых выделяется и затем освобождается память со случайными адресами? Я сделал конструктор CodeRange, оставил gmail запущенным, и нашёл дымящийся пистолет. Каждую пару минут создавался (и разрушался) новый объект CodeRange. В отладчике было легко найти, что эти объекты выделяет WorkerThread::Start, и вдруг всё стало ясно:
- gmail использует служебные сценарии, возможно, для режима офлайн
- Они появляются и исчезают с интервалом в несколько минут, потому что так работают служебные сценарии
- Каждый рабочий поток получает временный объект CodeRange, который выделяет для откомпилированного кода JavaScript несколько исполняемых страниц в случайном месте 47-разрядного адресного пространства
- 2 ТБ памяти, зарезервированной для CFG, получает несколько записей при каждом выделении страниц для кода
- Память, выделенная для CFG, не освобождается
- NtQueryVirtualMemory мучительно медленно сканирует память CFG (около 1 мс на блок) по непонятным причинам
Память
Резерв CFG начинается с резервирования адресов – память не выделяется. По мере того как выделяются исполняемые страницы, части резерва CFG превращаются в выделенную память, используя действительные страницы памяти. Эти страницы не освобождаются. При выделении и освобождении блоков исполняемой памяти со случайным расположением область CFG вырастет до произвольного размера! Это не совсем так. Блок памяти CFG лучше представлять себе как кэш ограниченного размера. Однако это мало утешает, когда его размер составляет 2 ТБ на процесс!Худшее, из того, что я видел: вкладка gmail была открыта восемь дней и накопила 353,3 МБ памяти CFG и 59,2 МБ страничных таблиц для проецирования памяти, в сумме потеряно 400 МБ. По некоторым причинам большинство людей, в отличие от меня, сталкиваются с более слабыми симптомами либо не видят их.
Решение
Команда v8 (движок JavaScript в Chrome) теперь повторно использует адреса для объектов CodeRange, что позволит обойти эту проблему. Microsoft уже решила свои проблемы производительности при сканировании памяти CFG. Может, когда-нибудь Microsoft будет освобождать области CFG при освобождении исполняемой памяти, по крайней мере в простых случаях, когда освобождаются большие диапазоны адресов. Было сообщено об ошибке vmmap.Большинство моих коллег и наших пользователей не сталкивалось с проблемой. Я заметил её только по следующим причинам:
- Я использовал gmail офлайн
- У меня была старая версия Windows 10
- Наше IT-подразделение регулярно сканирует компьютеры средствами WMI
- Я обратил внимание
- Мне повезло
Кстати, зависание происходило в 10:30, потому что именно в это время наше IT-подразделение запускает сканирование с целью инвентаризации. Для запуска сканирования вручную надо нажать кнопку "Run Now" здесь: Control Panel | Configuration Manager | Actions | Select ‘Hardware Inventory Cycle’.
Исходный код
Если вы хотите поиграться самостоятельно, то можете воспользоваться исходным кодом VAllocStress и VirtualScan.Кроличьи норы
Расследование включало множество кроличьих нор. Одни были важными (страничные таблицы), другие - поучительными (блокировки), а третьи были напрасной тратой времени (WMI). Мы поговорим об этом, а также об ошибке vmmap, в следующей записи. Если вам нужны кровавые подробности – некоторые из них оказались неверными или не относящимися к делу – полное расследование находится на crbug.com/870054.Обсуждение на Hacker news
Обсуждение на Reddit
Комментариев нет:
Отправить комментарий