Это расследование, как и многие другие, началось с того, что я занимался собственными делами, не пытаясь искать себе проблем. На этот раз всё, что я сделал — открыл крышку ноутбука и попытался выполнить вход в систему.
В первые несколько раз, когда это приводило к задержке в двадцать секунд, я игнорировал проблему, надеясь, что она решится сама собой. В следующие несколько раз я задумался о расследовании, но проблемы производительности, возникающие ещё до того, как ты вошёл в систему, сложнее решать, а мне было лениво.
Когда я заметил, что избегаю закрывать ноутбук, потому что меня пугают эти слишком частые задержки, то понял, что пора заняться этим серьёзно.
К счастью, я недавно исправил трассировку кольцевого буфера UIforETW, сделав его надёжным, поэтому я запустил его и начал ждать следующего случая задержки. Долго ожидать мне не пришлось.
Мне потребовалось несколько раз, чтобы получить полностью устраивающую меня трассировку ETW. И поскольку эта территория была для меня незнакомой, на выяснение происходящего потребовалось какое-то время. Я по-прежнему не полностью разобрался в проблеме, но на 90% понял причины её возникновения. Мне удалось многое узнать, в том числе некоторые новые подробности о Windows-планировщике, а также я обнаружил абсолютно эффективное решение.
Идеальная трассировка, которую я в конце концов записал, при загрузке в Microsoft Windows Performance Analyzer (WPA) выглядит так:
Стандартные события, окна в фокусе и использование ЦП
Эта таблица и два графика содержат кучу информации. Верхняя таблица (Generic Events) показывает записанные UIforETW нажатия клавиш. Я пытался нажимать клавишу (код виртуальной клавиши 162) раз в секунду, пока не появится поле ввода пароля. Так как эти 17 нажатий клавиши выбраны, в графике ниже они показаны вертикальными синими линиями для упрощённой визуализации времени выполнения критически важных событий. По оси x отложено время в секундах.
Горизонтальные полосы верхнего графика (Window in Focus) показывают, какой процесс имеет фокус на протяжении этого времени. Всего есть шесть разных процессов. Период Tracing off — это краткое время, в течение которого был закрыт ноутбук.
На нижнем графике показано использование ЦП. Информация получается по данным переключения контекста, поэтому должна быть совершенно точной и полной. В этой трассировке значение 100% показывает момент, когда использовались все восемь логических процессоров моего четырёхъядерного восьмипоточного ноутбука.
Получив данные трассировки, я должен был разобраться, чем же втайне занимается мой ноутбук, когда закрыта крышка и до момента, когда я снова вернусь в систему.
Буря перед затишьем
Как мы видим, ноутбук в начале трассировки ноутбук находится в относительном простое, как и должен быть. Затем я закрыл его крышку. Похоже, это вызвало всплеск активности ЦП и изменения фокуса окон. Window in Focus изменилось с UIforETW на Idle, потом на csrss, обратно на Idle, на LogonUI, а затем снова на Idle. Кто бы мог подумать?
В течение этого интервала ноутбук выполнял примерно 17 секунд ЦП различных видов обработки. Часть её является работой, необходимой для отключения. Часть — это программы (в том числе и внутренние инструменты Google), которые зарегистрированы в Планировщике заданий для выполнения «При блокировании рабочей станции любым пользователем» — вполне логично. Я даже заметил, что выполняется работа по созданию элементов UI для выполнения входа в систему, когда пользователь продолжит работу — нужно ведь быть готовыми заранее, правда?
17 секунд ЦП — довольно долгое время для перехода ноутбука в сон. Даже на моём ноутбуке с четырьмя ядрами и восемью потоками процесс занимает больше четырёх секунд. На моём домашнем ноутбуке для засыпания требуется больше 13 секунд времени ЦП, и почти все они уходят на код Windows. Службе политики диагностики действительно нужно выполнять пару SruDbTableSearches прежде, чем ноутбук сможет отдохнуть?
Думаю, эта излишняя работа при переходе в сон — тоже проблема, но это не та самая проблема, которую я ищу. Поэтому я просто решил от неё отвернуться.
И только гораздо позже я осознал, что именно в течение этого времени были брошены зёрна разрушения моего бага…
Сон
После блокировки ноутбука активность ЦП отсутствует. В этом конкретном тесте ноутбук был заблокирован в течение примерно 16 секунд.
Судорожное пробуждение
Активность ЦП при переходе в сон несравнима с тем, когда он начал пробуждаться. В течение этого времени мой перегруженный ноутбук выполнял примерно 172 секунд времени ЦП (!!!) в течение 22,6 секунды. Это большой объём работы.
Одна из загадок этого процесса заключается в падении использования ЦП почти до нуля спустя примерно секунду после первоначальной вспышки активности. Этот кратковременный промежуток простоя кажется довольно аномальным, учитывая окружающий его хаос. Но я думаю, что эта особенность не связана с проблемой, поэтому не стал обращать на неё внимания.
Ещё одна загадка заключается в том, почему столько программ оживает после этой краткой паузы. Забавно, что самым серьёзным нарушителем, ответственным за 31,6 из 172 секунд ЦП, стал Windows Performance Analyzer (WPA) — та самая программа, которую я использую для анализа трассировок. Три копии, которые я оставил запущенными, упорно трудятся над рендерингом своего UI, несмотря на то, что он пока не виден.
Кроме того, тёмные паттерны возникают при попытке инициализации ноутбуком устройств. KeStallExecutionProcessor — это ждущий цикл, и было странно видеть, что это самая исполняемая функция всей системы. Неужели секунда с лишним ждущего цикла — единственный способ запуска оборудования? 700 мс времени ЦП действительно обязательно тратить на инициализацию мыши и клавиатуры? Должны ли Microsoft и Intel игнорировать рекомендацию Microsoft о максимуме в 50 микросекунд?
Драйверы ждущего цикла. i8042prt.sys написан Microsoft. Два следующих созданы Intel.
В конечном итоге, за это время активно выполняется множество программ. Похоже, большинство из них сталкивается с той же проблемой, что и WPA — отчаянно пытается отрисовать пиксели на скрытом экране, и это намекает на баг Windows. Но даже без этого бага explorer.exe и другие программы энергично стремятся что-то делать. Но в конце концов, хотя это избыточное использование ЦП является необходимой частью проблемы, это не сама проблема. Так что я снова перестал обращать на неё внимание.
Фокус
При анализе трассировок важно выяснить, когда происходят важные действия. Основными уликами стали события ввода, потому что я прекратил нажимать на control после появления формы ввода пароля. Вот последние три нажатия на клавишу control в приближенном виде на графике Window in Focus:
Похоже, что критически важными событиями являются получение фокуса LockApp.exe, после которого фокус почти мгновенно получает LogonUI.exe. Предположительно, я ввёл пароль в LogonUI.exe (удобно, что трассировка не перехватила события клавиатуры), после чего фокус кратковременно переключился на explorer, а затем на UIforETW, с которого я начал.
Также похоже на то, что LogonUI.exe не может получить фокус до LockApp.exe — этот паттерн повторяется во всех трассировках, которые я изучал.
Итак, спустя больше тысячу слов, посвящённых решению этой загадки, у нас наконец сформировался чёткий вопрос, который мы можем исследовать: почему прежде чем LockApp.exe получит фокус после выхода из простоя, проходит двадцать секунд?
У нас есть вопрос? Отлично, давайте на него ответим
При помощи полученных из переключения контента данных CPU Usage (Precise) я быстро обнаружил, что в течение двадцати секунд после пробуждения LockApp.exe получил менее одной миллисекунды времени ЦП, а в течение более чем 14 секунд (с 35,158 с до 49,827 с) не работал вообще:
LockApp долгое время вообще не работает
Документация о значении столбцов в таблицах CPU Usage (Precise) находится здесь.
Если процесс или поток какое-то время не выполнялся, и вы хотите узнать, почему, то обычно важные улики можно найти в первом переключении контекста после долгого затишья, а именно переключения на 49,827 секунды трассировки. Я изменил порядок столбцов, чтобы показать больше данных этого переключения контекста:
LockApp подготовлен, но не выполняется. Странно...
Count, равное 1 означает, что мы просматриваем данные для одного переключения контекста.
Time Since Last, равное 38.2 миллионам микросекунд означает, что этот поток не выполнятся в течение 38,2 секунд. Само по себе это не хорошо и не плохо. Простаивающие потоки экономят энергию, да и в конце концов ноутбук какое-то время находился во сне.
Switch-In Time просто сообщает нам, когда точно поток помещается в ЦП — когда выполняется переключение контекста на этот поток.
И теперь мы переходим к столбцу Ready. Он сообщает нам, как долго поток был готов к выполнению, но не выполнялся. Иными словами, этот поток чего-то ждал (блокировки, дескриптора) и это что-то было освобождено или инициировано, но поток по-прежнему не выполнялся в течение 19,493 секунды.
Чтобы лучше понять столбец Ready (us), можно взглянуть на столбец Ready Time (s). Он говорит нам, когда поток подготовлен. Мы видим, что на 30,333 секунды трассировки этот поток был подготовлен к выполнению, но не выполнялся до 49,827 секунды. Похоже, это важно.
Такое расположение столбцов иначе показывает нам то же переключение контекста:
New Thread Stack и Ready Thread Stack
Итак, этому потоку (который, как показывает New Thread Stack, ожидал NtWaitForWorkViaWorkerFactory) было приказано проснуться (системным процессом, вызывающим KeSetEvent) вскоре после того, как я открыл крышку ноутбука, на 30.333 секунды трассировки. Но он запустился не тогда (что было бы «хорошо»), а спустя 19,494 с, и это плохо.
Обычно при проведении подобного анализа ожидания я трачу много времени на то, чтобы разобраться, почему поток ожидает, и что заставило его не быть готовым. Но я сейчас я впервые выполнял анализ ожидания, при котором это было не важно, и вопрос заключался в том, почему этот готовый поток не выполняется.
Дела...
Большинство людей не тратит так много времени на изучение трассировок ETW, поэтому здесь нужно пояснение. Это очень странно. Если поток готов, то он обычно запускается мгновенно, или спустя несколько миллисекунд. Готовность потока, как можно понять из названия, означает, что поток готов к выполнению и почти ничто не может ему помешать. Но давайте разберёмся в том, что может предотвратить выполнение готового потока.
Приоритет потоков
Сначала я предположил, что это простой случай «голода» ЦП. Время ЦП требуется десяткам процессов, и из-за этого LockApp не получает нужного, пока нагрузка не снизится. Однако эта теория не совсем соответствует симптомам, потому что процессу LockApp удалось продолжаться примерно 18 секунд вообще не получая времени ЦП.
Теория «голода» ЦП хороша тем, что она проверяема. Мне удалось повысить приоритет процесса LockApp при помощи Диспетчера задач (во время одного из кратких промежутков времени, когда он не был приостановлен системой UWP), поэтому в окончательной трассировке, которую я использовал для этого поста, LockApp выполнялся с высоким приоритетом. Обычный поток Windows работает с приоритетом примерно 8-10. Наибольший приоритет, с которым может выполняться обычный (не реального времени) поток Windows — 15. Мои трассировки ETW показали, что LockApp всегда работал с приоритетом 13 или выше.
Вот график времени ЦП для критических 19,494 секунды, сгруппированный и раскрашенный по приоритету потока (New In Pri, настоящего приоритета, который был назначен потоку). Мы видим, что потоки с приоритетами 4, 8, 9 и 10 потребляют подавляющее большинство времени ЦП, особенно в конце:
Использование ЦП по приоритету
Вот ещё одно изображение со скрытыми потоками с приоритетами 0-12. Каждый раз, когда график падает ниже 12,5% (что обозначает один логический процессор времени ЦП моего восьмипоточного ноутбука), LockApp обязательно должен запускаться, и становится совершенно невероятно, что приоритет мешает ему выполняться так часто, когда множество потоков с меньшим или равным приоритетом получают кучу времени.
Использование ЦП по приоритету, только потоки с высоким приоритетом
Устранение инвертирования приоритетов
Есть предположение, что алгоритмы инвертирования приоритетов Windows настолько способствуют другим потокам, что LockApp.exe блокируется. Но так как показанные выше графики демонстрируют, что в принятии решений о планировании используются истинные приоритеты, от этого (всегда малоубедительного) предположения придётся отказаться.
Выгрузка ядра стека
Когда я рассказал об этой головоломке в Twitter, один из комментаторов предположил, что был выгружен стек ядра потока. Я не был знаком с этой ситуацией, но после объяснений Джона Верта (он понимает в своём деле) я отключил подкачку стека ядра и перезагрузил компьютер. Ничего не изменилось. На самом деле, я и не думал, что это поможет, учитывая, что у меня 32 ГБ памяти, а проблема возникает многократно и часто; но лучше было точно в этом убедиться.
Приостановка процесса
Так как LockApp — это современное UWP-приложение, оно подвержено ограничениям, схожим с теми, которые свойственны приложениям для смартфонов. Среди прочего это означает, что оно может быть приостановлено, когда не находится на переднем плане, а затем «разморозиться» при возврате на передний план. Джеймс Форшоу предложил записать провайдер Microsoft-Windows-Kernel-Process ETW, чтобы получить данные об этом.
События спроектированы так, чтобы вызывать максимальную растерянность. Название задачи Process Freeze используется и для «размораживания» и для «замораживания», а версия события win:Stop означает, что процесс запускается (прекратил замораживаться), а версия win:Start означает, что процесс останавливается (начинает замораживаться). Всё это чрезвычайно логично, но сильно сбивает с толку. Если бы названия событий были разделены на Freeze и Thaw, то путаницы получилось бы меньше.
По этим событиям нет документации, но благодаря анализу я определил, что эти события всегда создаются Background Tasks/Broker Infrastructure Service. Название и process ID соответствующего процесса указываются в поле FrozenProcessID.
События ProcessFreeze (также используемые для размораживания)
Исследовать этот провайдер было интересно — у него есть множество многообещающих событий — но в конечном итоге оказалось, что во время трассировки LockApp не приостанавливался и не размораживался. Однако этот провайдер показался достаточно полезным, поэтому я модифицировал UIforETW, чтобы будущие версии всегда его записывали.
Мы уже всё исключили
Ни одна из описанных выше теорий не казалась мне сильно вероятной, и теперь мы их все исключили. Я начал искать помощи, и попросил подкинуть мне идей друга из Microsoft. И в этот момент я обнаружил, что так хорошо известный в Windows приоритет потока 0-31 на самом деле является всего лишь пятью битами низкого приоритета полной системы приоритетов.
Использование служебного положения
Оказалось, что моё невежество было моей собственной виной. Если бы я внимательно прочитал все 108 страниц раздела Threads книги Windows Internals, 7th Edition, Part 1, то я бы понял, что происходит. Если вы хотите заскочить вперёд, то эта тема раскрывается на страницах с 287 по 295.
Это поле сверхприоритета, о котором я не знал, называется Rank. Оно отображается в WPA как скрытый по умолчанию столбец (чтобы найти его, придётся открыть View Editor) под названием NewThreadRank. При планировании потоков Thread Rank обладает преимуществом перед приоритетом. Почти все потоки имеют Rank 0, а поток с Rank 0 всегда имеют более высокий приоритет, чем поток с Rank 2. Включив столбец NewThreadRank и взглянув на левую часть таблицы, мы сразу же можем увидеть проблему:
Ранг важнее, чем приоритет
Потоки LockApp.exe имеют Rank 2 и это значит, что они, несмотря на приоритет 14, по сути обладает наименьшим приоритетом в системе.
Почти полное объяснение
Так как оказалось, что потоки LockApp.exe имеют Rank 2, они могут выполняться только когда ни один из потоков с Rank 0 «не хочет» выполняться. Поскольку многие приложения (по непонятным причинам) активно рендерят свои невидимые экраны, они сражаются за каждую крошку времени ЦП, не оставляя ничего для более высоких значений рангов. Как только LockApp.exe получает крошечную долю времени ЦП, он быстро перемещается в Rank 0 (а нагрузка на ЦП падает), после чего процесс входа в систему выполняется обычным образом.
Узнав эту информацию, я начал изучать, как меняется со временем ранг LockApp. В последние несколько секунд перед уходом в сон ноутбука LockApp внезапно перешёл с ранга 0 на 2. Ранг предназначен для того, чтобы ЦП не позволял процессам занимать слишком много времени, как например в том случае, когда Windows Photos слишком увлекается непрошеной фоновой обработкой и выполняет переход с ранга 2 до 19:
Microsoft.Photos спускается по рангу
Из документации можно понять, что основное предназначение ранга потока — справедливое разделение времени ЦП между сессиями на машине, чтобы процессы одного пользователя не вредили другим. Оба эти варианта использования ранга дают понять, что ранг потока должен повышаться, только если тот использует много времени ЦП, а когда ноутбук отправлялся в сон, LockApp.exe использовал всего 79,3 мс времени ЦП, а остальная часть системы — 17 с времени ЦП. И тем не менее, ОС почему-то решила понизить ранг LockApp до 2 в процессе перехода ко сну.
ОС изменяет ранг потока, только если он относится к «группе планирования» (KSCHEDULING_GROUP), а большинство потоков в обычной установке Windows не являются её членами. Следовательно, большинство потоков не подвергается изменению ранга, поэтому они могут тратить время ЦП так, как им захочется.
Оставшиеся загадки
К сожалению, до сих пор непонятно, почему перед включением сна LockApp.exe понижается до Rank 2. Я предположу, что LockApp находится в группе планирования, и, вероятно, один из алгоритмов ведёт себя неправильно. Но мне не удалось найти API для расследования этого, да и время поджимало. Если вам известны какие-то подробности, то напишите в комментариях к оригиналу статьи. Сам принцип использования ранга как наиболее важного компонента в принятии решений о планировании должен, как мне кажется, неизбежно поломаться, если большинство процессов системы в нём не задействовано — потоки в группах планирования всегда рискуют остаться без нужных ресурсов. Планирование динамического распределения ресурсов (DFSS) обречено на провал, если большинство потоков в нём не участвует.
Также я не знаю, почему после ухода в сон остаются активными так много приложений. Обычно это объясняют тем, что «многие таймеры заканчиваются, когда ноутбук пробудет в режиме сна несколько часов», но такое объяснение не подходит, если ноутбук находился во сне всего несколько секунд, а поведение рендеринга WPA указывает на то, что в оконной системе происходит что-то неправильное. Добавьте к этому приложения с плохим поведением и драйверы ждущего цикла, и всё суммируется в долгое время ЦП.
То, что утихание бури ЦП и запуск LockApp происходят одновременно, приводит к очевидному объяснению: LockApp может работать только тогда, когда потребность в ЦП падает. Но есть и столь же убедительное объяснение: как только LockApp получает возможность запуска (или, возможно, её получает LogonUI), потребность в ЦП падает. Подходят оба объяснения, но я думаю, что больше правдоподобно второе, потому что в противном случае мы не можем объяснить, почему внезапно прекращается кажущийся бесконечным рендеринг WPA.
Решение проблемы
Как только я понял, что LockApp.exe — это отдельное приложение, испытывающее проблемы с запуском, и что повышение его приоритета не помогает, я отключил его. В этом мне помог такой файл DisableLockScreen.reg:
Windows Registry Editor Version 5.00
[HKEY_LOCAL_MACHINESOFTWAREPoliciesMicrosoftWindowsPersonalization]
“NoLockScreen”=dword:00000001
Благодаря отключению экрана блокировки ноутбук приходит в себя сразу после открывания крышки. Я не заметил ни торможения, ни бурь ЦП, а для входа теперь требуется на один шаг меньше.
В первом посте в twitter, который я опубликовал, когда впервые столкнулся с проблемой, содержится временная шкала расследования, которая может оказаться кому-то полезной. Кроме того, в пост пришло много умных людей из twitter, спасибо им.
Когда я вернулся к статье, то выяснил, что после включения обратно экрана блокировки проблема исчезла. Простая перезагрузка не устранила её — в феврале я много раз перезагружался, но мы, наверно, так и не узнаем, почему она пропала.
Обсуждения
Автор: PatientZero
