Технології

24-ядерний ПРОЦЕСОР, а я не можу набрати електронний лист

Я не шукав неприємностей. Не запускав процес складання Chrome тисячу разів за вихідні, а тільки займався звичайними завданнями 21-го століття — просто писав електронний лист в 10:30 ранку. І раптом Gmail підвисало. Я продовжував друкувати кілька секунд, але на екрані не з’являлося жодних символів. Потім раптово Gmail відвис — і я повернувся до свого дуже важливого листа. Але згодом все повторилося, тільки на цей раз Gmail ще довше не відповідав на запити. Це дивно…

Важко встояти перед можливістю провести гарне розслідування, але в даному випадку виклик особливо сильний. Адже я в Google працюю над поліпшенням продуктивності Chrome для Windows. Виявити причину зависання — моя робота. І після безлічі невдалих спроб і важких зусиль мені все-таки вдалося з’ясувати, як Chrome, Gmail, Windows і наш IT-відділ разом завадили мені набрати електронний лист. По ходу справи знайшовся спосіб заощадити значну кількість пам’яті для деяких веб-сторінок в Chrome.

У розслідуванні виявилося так багато нюансів, що я залишу деякі для іншої статті, а зараз повністю поясню причини підвисань.

Як звичайно, у мене в тлі працює UIforETW і відстежує циклічні буфери, тому залишалося тільки ввести Ctrl+Win+R — і буфери приблизно за останні тридцять секунд активності системи збереглися на диск. Я завантажив їх в Windows Performance Analyzer (WPA), але не зміг остаточно встановити зависання.

Коли програма Windows перестає передавати повідомлення, то видаються події ETW з зазначенням, де саме це сталося, тому такі типи зависань тривіально знайти. Але, мабуть, Chrome продовжував передавати повідомлення. Я пошукав момент, коли один з ключових потоків Chrome або увійшов в активний цикл, або повністю простоював, але нічого явної не знайшов. Були деякі місця, де Chrome переважно простоював, але навіть тоді всі ключові потоки продовжували працювати, тому не можна було бути впевненим, де відбулося зависання — Chrome міг просто простоювати в відсутність подій:

У UIforETW є вбудований кейлоггер, який часто корисний при ідентифікації ключових точок у трасуванні. Тим не менш, з очевидних причин безпеки за замовчуванням анонімізує натискання клавіш, розцінюючи кожне введене число “1”, а букву “A”. Це ускладнює пошук точного моменту зависання, тому я змінив тип трасування з «приватного» на «повний» і очікував зависання. Близько 10:30 на наступного ранку зависання повторилося. Я зберіг буфери трасування і зберіг таку позначку в полі інформації трасування UIforETW:

Набирав «відкласти для тих, у кого більший досвід роботи з Scuba» — і Gmail підвисло в кінці слова «тих», а потім відновив роботу в районі слова «досвід». Вкладка Gmail з PID 27368.
Це просто робочий варіант звичайного обговорення рутинних поїздок, але важливо, що тепер з’явився спосіб знайти зависання в трасуванні ETW. Я завантажую трасування, дивлюся на дані кейлогерам в поле Generic Events (події видаються самим UIforETW, а кожне являє собою фіолетовий ромб на скріншоті внизу) — і відразу бачу, де відбулося зависання, з яким явно корелює провал у використанні CPU:

Добре, але чому Chrome зупинився? Ось деякі натяки: на скріншотах не показано, що кожен раз при цьому WmiPrvSE.exe повністю використовує гіперпотік CPU. Але це не повинно мати значення. В моїй машині 24 ядра/48 потоків, так що споживання одного гіперпотоку означає, що система вільна на 98%.

Потім я наблизився до явно важливого періоду, коли Chrome простоював — і подивився, зокрема, на процес CrRendererMain в chrome.exe (27368), відповідний вкладці Gmail.

Примітка: хочу сказати спасибі собі з 2015 року за прохання Microsoft поліпшити механізми іменування потоків, і спасибі Microsoft за реалізацію всього запропонованого — назви потоків у WPA просто чудові!
Проблема вирішилась. Протягом 2,81 секунди зависання цей потік запускався за розкладом 440 разів. Зазвичай запуску кожні 6 мс достатньо, щоб зробити програму чуйною, але з якоїсь причини цього не сталося. Я помітив, що кожен раз, коли він прокидався, то був на одному стеку. Якщо спростити:

chrome_child.dll (stack base)
KernelBase.dll!VirtualAlloc
ntoskrnl.exe!MiCommitVadCfgBits
ntoskrnl.exe!MiPopulateCfgBitMap
ntoskrnl.exe!ExAcquirePushLockExclusiveEx
ntoskrnl.exe!KeWaitForSingleObject (stack leaf)

Chrome викликає VirtualAlloc, який намагається оновити деякі “CfgBits” і повинен отримати блокування. Спочатку я припустив, що Chrome викликав VirtualAlloc 440 разів, що здається дивним. Але реальність виявилася ще більш дивною. Chrome викликав VirtualAlloc одного разу — і повинен був отримати блокування. Chrome сигналізував про доступність блокування, але — 439 разів поспіль — коли Chrome прокидався і намагався отримати блокування, вона виявлялася недоступна. Блокування виходило повторно через процес, згаданий вище.

Це тому що блокування Windows за своєю природою несправедливі — і якщо потік звільняє блокування, а потім негайно його запитує знову, то може отримувати його вічно. Голод. Детальніше про це наступного разу.

У кожному разі процесом, який сигналізує Chrome захопити блокування, був WmiPrvSE.ехе, відпускає блокування на цей стек:

ntoskrnl.exe!KiSystemServiceCopyEnd (stack base)
ntoskrnl.exe!NtQueryVirtualMemory
ntoskrnl.exe!MmQueryVirtualMemory
ntoskrnl.exe!MiUnlockAndDereferenceVad
ntoskrnl.exe!ExfTryToWakePushLock (stack leaf)

Деякий час зайняв розбір в WMI (докладніше про це наступного разу), але в підсумку я написав програму для відтворення поведінки WMI. У мене були дані вибірки CPU, які показали, на що витрачає час WmiPrvSE.exe (у спрощеному вигляді з деякими правками):

WmiPerfClass.dll!EnumSelectCounterObjects (stack base)
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, який використовується для сканування пам’яті процесу і викликається відповідним чином іменованим GetProcessVaData, де Va, ймовірно, означає віртуальну адресу. Моя програма VirtualScan просто викликала NtQueryVirtualMemory в очевидному циклі для сканування адресного простору зазначеного процесу, код працював дуже довго для сканування процесу Gmail (10-15 секунд) — і приводив до зависання. Але чому?

Перевага власноруч написаного циклу сканування в тому, що можна генерувати статистику. NtQueryVirtualMemory повертає дані для кожного суміжного діапазону адресного простору з відповідними атрибутами. Такими можуть бути «все зарезервовано», «все зафіксовано з певними настройками захисту» і т. д. В процесі Gmail близько 26 000 цих блоків, але я знайшов інший процес (як виявилося, це WPA) з 16 000 блоками пам’яті, який сканувався дуже швидко.

В якийсь момент я подивився на процес Gmail за допомогою vmmap і зауважив, що процес Gmail займає чимало пам’яті (361 836 КБ) і багато окремих блоків (49 719), які надходять з єдиного джерела зарезервованої пам’яті — джерела розміром 2 147 483 648 КБ, тобто 2 ТБ. Що?

Я знав, що резервування 2 ТБ використовується для Control Flow Guard (CFG), і згадав, що “CFG” справді з’являвся в стеках викликів, де чекав процес Gmail Chrome — на стеку був присутній MiCommitVadCfgBits. Може, велика кількість блоків у регіоні CFG і було проблемою!

Control Flow Guard (CFG) використовується для захисту від експлойтів. Два терабайта зарезервовані як бітовий масив, який вказує на валідні непрямі відгалуження до 128-терабайтного адресного простору користувача режиму. Тому я змінив свій сканер віртуальної пам’яті для підрахунку, скільки блоків знаходиться в регіоні CFG (просто пошук резервації 2 ТБ), а скільки блоків помічені як виконуються. Оскільки пам’ять CFG використовується для опису виконуваної пам’яті, то я очікував побачити в процесі один блок пам’яті CFG для кожного блоку виконується пам’ять. Замість цього я побачив 98 блоків виконується пам’яті і 24 866 блоків фіксованої CFG-пам’яті. Істотне розходження:

 Scan time, Committed, page tables, committed blocks
Total: 41.763 s, 1457.7 MiB, 67.7 MiB, 32112, 98 code blocks
CFG: 41.759 s, 353.3 MiB, 59.2 MiB, 24866

vmmap показує резервування і виділену пам’ять як блоки, а мій інструмент сканування вважає тільки виділені блоки — ось чому vmmap показує 49 684 блоків, а мій інструмент 24 866
Заднім розумом це здається очевидним, але що якщо бітовий масив CFG ніколи не очищається? Якщо пам’ять виділяється в растровому масиві CFG при виділенні виконуваної пам’яті, але не звільняється при звільненні виконуваної пам’яті? Тоді така поведінка зрозуміла.

Відтворення від початку до кінця

Наступний крок — написання програми VAllocStress, яка виділяє і звільняє тисячі блоків виконується пам’яті за випадковим адресами. Для цього виконуваного файлу повинен працювати 64-бітний режим CFG, і виникли деякі труднощі, тому що я дійсно не знав, що я намагаюся зробити, але все запрацювало. Після виділення і звільнення цієї кількості блоків виконувана в пам’яті програма повинна сидіти в циклі, звідки вона зрідка намагається виділити/звільнити більше виконуваної пам’яті, і стежить, коли цей процес сповільнюється. Ось базовий алгоритм для VAllocStress:

  1. Багаторазовий цикл:
    • Виділити виконувану пам’ять з допомогою VirtualAlloc за випадковим адресою.
    • Звільнити пам’ять.
  2. Потім нескінченний цикл:
    • Сплячий режим на 500 мс (не хочу свинськи захоплювати процесор).
    • Виділити трохи виконуваної пам’яті з VirtualAlloc за заданою адресою.
    • Висновок повідомлення, якщо виклик VirtualAlloc займає більш ~500 мс
    • Звільнити пам’ять.

От і все. Дуже просто. І було так приємно, коли це спрацювало. Я запустив програму, а потім доручив VirtualScan просканувати процес VAllocStress. Швидко з’ясувалося, що блок CFG жахливо фрагментований, і сканування займає дуже багато часу. І моя програма VAllocStress зависала на час сканування!

На цьому етапі я змоделював фрагментацію CFG, тривалий час сканування і зависання. Ура!

Першопричина

Виявляється, в JavaScript-движку v8 задіяні об’єкти CodeRange для управління генератором коду, і кожен об’єкт CodeRange обмежений діапазоном адрес 128 МБ. Здавалося б, це досить невеликий обсяг, щоб уникнути нестримного розподілу CFG, які ми спостерігаємо.

Але що, якщо у вас кілька об’єктів CodeRange, і вони розподіляються по випадковим адресами, а потім звільняються? Я налаштував конструктор CodeRange, залишив працювати Gmail — і знайшов винуватця. Кожні пару хвилин створювався (і знищувався) новий об’єкт CodeRange. В налагоджувач легко бачити, як WorkerThread::Start виділяє ці об’єкти. І тут головоломка склалася:

  1. Gmail використовує сервіс-воркеров, ймовірно, для реалізації автономного режиму.
  2. Вони з’являються і зникають кожні кілька хвилин, тому що так поводяться сервіс-воркеры.
  3. Кожен потік воркера отримує тимчасовий об’єкт CodeRange, який виділяє деякі виконувані сторінки для JITted-коду JavaScript з випадкового розташування в 47-бітному адресному просторі процесу.
  4. При виділенні нових кодових сторінок здійснюються записи в резервації пам’яті CFG на 2 ТБ.
  5. Розподілу CFG ніколи не звільняються.
  6. NtQueryVirtualMemory болісно повільно сканує пам’ять CFG (близько 1 мс на блок) з причин, які я не розумію.

Повільне сканування пам’яті CFG фактично виправлено в Windows 10 RS4 (оновлення від квітня 2018 року), що змусило мене ненадовго задуматися, чи був сенс у всьому цьому розслідуванні. Виявляється, був.

Пам’ять

Резервування 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-відділ запускав відповідне сканування. Якщо хочете запустити сканування вручну, можете зайти в Control PanelConfiguration ManagerActions, вибрати Hardware Inventory Cycle і натиснути Run Now.

Вихідний код

Якщо бажаєте погратися, то вихідний код VAllocStress і VirtualScan лежить на Github.

Нюанси

В цьому розслідуванні багато нюансів. Деякі з них важливі (таблиці сторінок), деякі повчальні (блокування), а деякі виявилися марною тратою часу (деталі WMI). У наступній статті я розповім докладніше про них та про помилку vmmap. Якщо хочете більше кривавих подробиць — деякі з яких виявилися неправильними або неактуальними — можете стежити за розслідуванням на crbug.com/870054.

Related Articles

Залишити відповідь

Ваша e-mail адреса не оприлюднюватиметься. Обов’язкові поля позначені *

Close