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

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

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

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

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

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

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

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

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

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

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

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

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

Профильные события отключены по умолчанию, так что я нажал на кнопке "profile event" на панели инструментов, чтобы включить их отображение, надеясь, что они помогут мне в решении проблемы:

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

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

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

Стек первого потока идентифицировал поток как основной поток "состояния машины" Winlogon, ожидающий некоторого неизвестного уведомления, что не дало мне никаких подсказок:

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

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

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

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

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

TechEd Europe, которая прошла в Амстердаме на прошлой неделе, дала мне еще один шанс повторить доклады, которые я делал на TechEd US. Я провел аналогичную сессию "Case of the Unexplained", как и на 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

Источник: http://blogs.technet.com/markrussinovich
Перевод: Dazila