Дело об о-о-о-ч-ч-ч-е-е-е-н-ь медленных входах в систему

Дело относится к моему любимому разряду дел, в которых я использую собственные инструменты для решения проблемы, затронувшей меня самого. Это дело в своей основе может коснуться каждого, особенно тех, кто много путешествует, и демонстрирует использование некоторых возможностей программы Process Monitor, о которых многие не догадываются, что делает его идеальным для описания и распространения.

История разворачивалась в позапрошлую неделю, когда я отправился в Орландо выступить на конференции Microsoft TechEd North America. Когда я был там, я столкнулся с пятиминутными задержками при входе в свою систему Windows 7, сопровождавшимися черным экраном:

Обычно я отношу отдельные задержки, подобные этой, на счет проблем с сетью, часто встречающихся на конференциях с их WiFi-сетью, предоставляемой отелем. Но я постоянно нарывался на эту проблему переключаясь между системой Windows 8, установленной на моем лэптопе для тестирования и проведения презентаций, и Windows 7, где находятся средства разработки. Получить заблокированный на такой промежуток времени компьютер, – мало сказать, будешь несколько раздосадован.

В первый раз, когда появился черный экран, я принудительно перезагрузил систему после пары минут ожидания, поскольку подумал, что она зависла. Когда я задержка случилась во второй раз, я был вынужден подождать, и столкнуться с разочаровывающим фактом, что моя система не в порядке. Когда я вышел из системы и вошел в нее снова без перезагрузки, задержки не произошло. Она случалась только после перезагрузки, которую я делал, переключаясь между Windows 7 и Windows 8. Что самое печальное, всякий раз, когда я перезагружался, я торопился на свою следующую презентацию, поэтому был вынужден терпеть неудобства в течение нескольких дней, пока наконец не нашел возможности исследовать проблему.

Как только выдался свободный момент, я запустил программу Sysinternals Autoruns, усовершенствованную утилиту управления автозапуском программ, чтобы запретить все образы, расположенные на разделяемых сетевых ресурсах. Из прошлого опыта запуска Autoruns на лаптопе мне было известно, что служба Microsoft IT настраивает несколько плановых задач для выполнения командных файлов, расположенных на корпоративных разделяемых сетевых ресурсах, и подозревал, что таймауты связаны с попыткой запустить их:

Я вышел из системы и вошел обратно, держа пальцы перекрещенными, но задержки по-прежнему были на месте. Следующим шагом, я попытался войти в локальную учетную запись, чтобы посмотреть является ли проблема общесистемной или связана лишь с моим профилем. Нет задержки. Это положительный знак, так как означает, что с чем бы проблема ни была связана, возможно, ее относительно легко исправить после обнаружения.

Теперь моей целью было установить, что удерживало от переключения на рабочий стол. Мне требовался способ увидеть, что происходит во время регистрации в системе непосредственно после загрузки. Способ, сразу приходящий в голову, – использовать Sysinternals Process Monitor для регистрации событий процесса загрузки. Process Monitor – инструмент, регистрирующий общесистемные операции с файловой системой, реестром, процессами, DLL и сетью, – способен записывать действия с самых ранних этапов загрузки до момента, когда система выключается или пока вы не запустите пользовательский интерфейс Process Monitor. Я выбрал запись загрузки из меню Options и открыл диалог записи загрузки:

Этот диалог позволяет настроить программу на сбор трассировочных событий при мониторинге загрузки, которые представляют собой периодические снимки стеков потоков. Я выбрал односекундную трассировку, надеясь на то, что если даже не замечу операций, объясняющих задержку, то смогу найти разгадку из стеков потоков, которые были активны сразу перед задержкой или когда она происходила.

После перезагрузки я вошел, подождал пять минут, глядя в черный экран, затем добрался до рабочего стола, где снова запустил Process Monitor и сохранил журнал загрузки. Вместо просмотра нескольких миллионов захваченных событий, копание в которых можно сравнить с поиском иголки в стоге сена, я использовал фильтр Process Monitor для поиска операций, занимающих более одной секунды и поэтому могущих вызывать замедление:

К несчастью, фильтр очистил окно вывода, перечеркнув мои надежды быстро найти ключ к разгадке.

Предполагая, что, возможно, последовательность процессов, запущенная при входе в систему могла вызвать что-то похожее, я открыл диалог дерева процессов из меню Tools. Этот диалог показывает взаимоотношения родитель-ребенок для всех активных процессов при записи журнала, что в случае загрузки означает все процессы, выполняющиеся во время загрузки и входа в систему. Сфокусировавшись на Winlogon.exe, интерактивном менеджере входа в систему, я заметил, что процесс Atbroker.exe запустился приблизительно тогда, когда я ввел свои учетные данные, и затем Userinit.exe выполнился, когда, наконец, возник рабочий стол:

Ключ к решению загадки находился в длинной паузе между этими событиями. Я знал, что Logonui.exe просто выводит интерфейс для входа пользователя, а Atbroker.exe – просто вспомогательный механизм для перехода от интерфейса входа к сеансу пользователя, что исключает паузы, по крайней мере первоначально. Черный экран исчезает при запуске Userinit.exe, так что его родительский процесс Winlogon.exe остался под подозрением. Я настроил фильтр на включение событий только от Winlogon.exe и добавил столбец относительного времени, чтобы легко контролировать, когда случилось событие по отношению к началу загрузки. Когда я взглянул на результаты, я сразу увидел, что задержка составляет около шести минут, но в этот период времени нет активности, которая указала бы на ее причину:

События трассировки исключаются по умолчанию, поэтому я щелкнул по кнопке фильтра событий трассировщика на панели инструментов, чтобы включить их в журнал, надеясь, что они прольют свет на проблему:

Чтобы сократить размеры файла журнала, трассировщик Process Monitor захватывает стеки потоков, только если поток выполнялся с последнего момента, как был занесен в журнал. Поэтому я хотел взглянуть на события трассировки потока в начале задержки, но мой взгляд остановился на ежесекундно повторяющейся последовательности одних и тех же четырех потоков на протяжении всего периода существования черного экрана:

Я был вполне уверен, что любой поток приостанавливался, выполнив некоторые действия в начале интервала, и находился в спящем состоянии на остальном его протяжении, поэтому скептически отнесся к тому, что любой из этих потоков имеет отношение к проблеме, но, тем не менее, стоило потратить несколько секунд, чтобы взглянуть на них. Я открыл диалог свойств события в одной из таких групп двойным щелчком на событии и переключился на страницу стека потока, почти не надеясь, что имена вызываемых функций в стеке подскажут ответ.

Когда я впервые запустил в системе Process Monitor, я настроил его на получение символов для образов Windows с публичного сервера символов Microsoft, используя DLL механизма отладки из средств отладки для Windows, чтобы видеть во фреймах стека осмысленные имена функций исполняемых модулей Windows, а не просто смещения в файлах.

Стек первого потока определяет его как поток «конечного автомата» ядра Winlogon, ожидающего какого-то неизвестного оповещения, и не содержит ничего интересного:

Стек следующего потока тоже ничего не разъясняет, показывая, что поток является общим исполняющим потоком:

Стек третьего потока оказался намного более интересным. Он был многоуровневым, включая вызовы функций Multiple UNC Provider (MUP) и драйверов клиентской распределенной файловой системы, ответственных за доступ к файловым серверам:

Я промотал список дальше, чтобы увидеть фреймы, лежащие выше в стеке и имя одной из функций, WLGeneric _ ActivationAndNotifyStartShell _ Execute, подтвердило, что этот поток и отвечает за проблему, так как он запускает оболочку рабочего стола:

Следующая функция фрейма, WNetRestoreAllConnectionsW, вместе с последующими вызовами функций файлового сервера, привела меня к заключению, что Winlogon старался восстановить соответствие букв дисков файлового сервера перед тем, как продолжить запуск оболочки и дать доступ к рабочему столу. Я открыл Explorer, вспомнив, что у меня были два накопителя, отображаемые на разделяемые сетевые диски, расположенные на компьютерах внутри сети Microsoft, один для моей системы разработки, а другой для внутреннего ресурса Sysinternals, куда я публикую предварительные версии утилит. Находясь на конференции, я не имел доступа к интрасети, поэтому Winlogon не мог подсоединить их во время процедуры входа и в итоге, через много минут, выдавал:

Уверенный, что нашел отгадку, я щелкнул правой клавишей мыши на каждом ресурсе и отсоединил его. Я перезагрузил лэптоп, чтобы проверить исправление (точнее, обходной маневр) и к своему огромному удовлетворению убедился, что время от процедуры входа, до появления рабочего стола заняло лишь несколько секунд. Дело было закрыто! Исследовать, почему эти задержки настолько продолжительны, я не имел ни времени, ни необходимости. Мораль этой истории заключается не в самой проблеме, а в том, как с помощью инструментов Sysinternals и приемов поиска ошибок решать проблемы.

Прошедший в Амстердаме TechEd Europe предоставил мне возможность повторить выступление, которое было на TechEd US. Я прочитал ту же лекцию по поиску и устранению неисправностей «Дело о необъяснимом», которая была и на TechEd US, но на этот раз я имел удовольствие поделитться этим свежим случаем, произошедшим лично со мной. Вы можете посмотреть запись этой лекции среди других лекций TechEd, зайдя на страницу моих веб-кастов, на которой выложен список записей моих основных выступлений, либо обратится к непосредственным ссылкам ниже:

Windows Azure Virtual Machines and Virtual Networks
Windows Azure Internals
Malware Hunting with the Sysinternals Tools
Case of the Unexplained 2012

А также можно посмотреть записи всех выступлений на обоих мероприятиях на соответствующих сайтах:

TechEd North America 2012 On-Demand Recordings
TechEd Europe 2012 On-Demand Recordings

Надеюсь, вам понравилось это дело!