Не устанавливаются приложения, тормозит станция

Метки:  , , , , , , , , ,

Сегодня я хотел бы обсудить довольно специфическую проблему, которая долгое время не давала покоя техническому отделу, скажем так условного корпоративного клиента. Не то что бы она была какой-то уж чрезвычайно сложной, скорее просто никому не интересной (как в том анекдоте про Джо) :), и решалась местным персоналом при помощи полной "перезаливки" станции пользователя. Кстати, к слову сказать, проблема, которая будет описана в данной статье, мне уже встречалась, но всё никак не появлялось возможности детального её изучения. Благо, не так давно возникший аналогичный инцидент явился отправной точкой для написания этой заметки. Надо заметить, что для детального описания сбоев, в будущем хотелось бы все же разработать какой-нибудь единый диагностический шаблон, то есть собрать с проблемной станции именно ту информацию, которая представляла бы собой наиболее точное описание всех необходимых конфигураций и однозначно идентифицировала проблему, что бы пользователи могли находить решения по проблемам со схожими симптомам.

Описание проблемы

Рабочее окружение:

  • Корпоративная доменная среда;
  • Пользовательская станция под управлением Windows 7 Professional x64 6.1.7601 SP1;
  • Агент SCCM 2012 версия 5.00.8239.1403.

Довольно редко, при введении в эксплуатацию свежеперезалитой/сохранившейся от другого пользователя рабочей станции, счастливый обладатель начинал жаловался на очень медленное быстродействие, многие программы запускались чрезвычайно медленно (на протяжении десятков минут!). Работать же в уже запущенных приложениях было практически невозможно. При удаленном подключении к станции и попытке удалить произвольное программное обеспечение, было зафиксировано, что процессы инсталляций/деинсталляций "виснут", не устанавливаются приложения, то есть сам процесс установки/удаления может длиться бесконечно, не завершаясь в течении приемлемого временного интервала. Когда удавалось запустить какое-либо диагностическое ПО (Process Hacker / Process Explorer и подобные), была зафиксирована активность с базой (хранилищем) компонентов. Кроме этого никаких отличительных симптомов обнаружить не удалось.

Диагностика

Убедившись в том, что пользовательская станция действительно ОЧЕНЬ СИЛЬНО тормозит, я решил не прибегать к внешнему инструментарию, а начать с использования встроенного Монитора ресурсов (resmon), благо интерфейс я все же увидел минут через 20 (!) после запуска приложения. С трудом переключаясь между элементами интерфейса, я прошелся по вкладкам ЦП, Память, Диск, Сеть и зафиксировал аномальную дисковую активность: на вкладке Диск, в разделе Работа диска, наблюдалось "повышенная" активность процесса WERFault.exe, который активно работал несколькими с файлами вида C:\ProgramData\Microsoft\Windows\WER\ReportQueue\Critical_6.1.7601_xxxx...xxxx_cab_xxxxxxxx. При этом поток данных был действительно большим, скорость превышала несколько мегабайт/секунду. Судя по всему (подтвердить скриншотом не могу, просто забыл заскриншотить удаленный экран внешним скринером) похожих процессов было несколько, и все они работали с аналогичными файлами в дереве директорий с корнем в C:\ProgramData\Microsoft\Windows\WER\ReportQueue\. Никакой другой нетипичной активности в системе не наблюдалось, поскольку и этого системе хватало сполна, отсюда был сделан вывод, что причиной торможения системы является сильно нагруженная дисковая подсистема (шина SATA, винчестер ST3500413AS).

К сожалению в тот момент я не догадался остановить Службу регистрации ошибок Windows, что в разы бы упростило мне дальнейшую работу с клиентом. Поэтому, если Вы видите повышенную нагрузку от процессов WERFault, которая приводит к существенному снижению общей производительности системы, первым делом останавливайте службу, а потому уже продолжайте диагностику.

Затем я попытался устранить лишнюю нагрузку на систему и удалить один установленный компонент командой:

msiexec /uninstall {XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX} /q UNINSTALLPASSWORD=""

.. процесс msiexec.exe наглухо вис, показывая, что работает с хранилищем. При этом процессы, относящийся к деинсталлируемому ПО успешно были выгружены из памяти, однако сам msiexec упорно не хотел завершать свою работу. Все попытки инсталляции различных дистрибутивов заканчивались тем же "подвисанием" установщика, который просто стопорился на каком-нибудь из окон процесса установки, одним словом приложения не устанавливались. Общая производительность станции была, как уже отмечалось, очень низкая, низкая настолько, что порой невозможно было переключиться из окна в окно (!), окна приходилось просто сворачивать, только что бы добраться до находящегося на заднем плане окна :)
Тем не менее, первая подсказка у нас уже есть, сперва я попытался открыть в проводнике каталог C:\ProgramData\Microsoft\Windows\WER\ReportQueue\, с которым так активно работали процессы WERFault. Директория относилась к системному механизму WER.

WER (Windows Error Reporting) - подсистема отчетов в операционной системе Windows, предназначающаяся для отправки сообщений об ошибках на удаленные специализированные сервера. Под сообщением здесь понимается пакет данных, включающий всю необходимую для проведения анализа инцидента информацию.

WER используется разделенные пути отправки:

  • %LOCALAPPDATA%\Microsoft\Windows\WER -- для ошибок уровня пользователя;
  • %PROGRAMDATA%\Microsoft\Windows\WER -- для ошибок системного уровня.

Очевидно, что в нашем случае используется второй (системный) вариант. Далее, в каталоге ReportQueue было обнаружено большое количество подкаталогов такого вот примерно вида:

Каталог ReportQueue содержит отчеты об ошибках, которые ставятся в очередь на отправку. Отчеты требуют пользовательского подтверждения отправки и наличия сетевого подключения для осуществления непосредственной загрузки данных на сервер. Когда отчет успешно выгружен, он удаляется из каталога ReportQueue и перемещается в каталог ReportArchive.

Обратите внимание на время, отраженное в левом столбце. Судя по всему, директории создавались механизмом WER со скоростью одна директория в одну-две минуты, при этом происходила запись огромного количества данных в файлы внутри каждой из директорий. С чего бы это механизму WER так себя вести? Получается, если WER у нас с большой скоростью собирает данные для отправки, то в системе у нас с большой скоростью что то падает? Что еще добавляло нагрузки на систему в целом, так это то, что папки в каталоге ReportQueue обозначались синим цветом, то есть, судя по всему, использовалось сжатие NTFS. В связи с жуткими тормозами, спустя продолжительное время, мне все же удалось войти в одну из перечисленных директорий и взглянуть на её содержимое:

Вот так выглядит комплект данных для отправки отчета разработчикам. Глядя на размер файла CBS.log, я начал смутно догадываться о причинах медленной работы системы :) ведь файл журнала компонентной модели присутствовал в каждой поддиректории и каждый раз копировался в новую. В последствии, в зависимости от системных настроек, вся эта гигантская прорва информации еще и пытается каким-либо образом закачаться на локальный/удаленный сервер отчетов. Попытаемся разобраться в предназначении каждого файла из комплекта отправки:

Файл(ы) Описание
CBS.log
CbsPersist_20161212063219.cab
CbsPersist_20161214063539.cab
CbsPersist_20161215072328.cab
CbsPersist_20161229150211.cab
CbsPersist_20170112111614.cab
FilterList.log
Копия части содержимого директории журнала компонентной модели, который размещается в системе по пути %WinDir%\Logs\CBS\. В копию входит сам файл журнала компонентной модели, а так же упакованные файлы предыдущих периодов.
poqexec.log Журнал очереди незавершенных операций. Файл содержит ошибки для части процесса инсталляции, которая производится после перезагрузки операционной системы. Каждый сбой отображается в файле в виде отдельной строки. Оригинальный файл располагается по пути %WinDir%\winsxs\poqexec.log.
Report.wer Файл отчета для пакета WER.
SCM.EVM Журнал сессии трассировки событий Диспетчера управления службами (Service Control Manager, SCM). Оригинальный файл располагается по пути %WinDir%\system32\LogFiles\Scm
Sessions.xml Журнал транзакций стека обслуживания в формате XML. Содержит данные трассировки о всей активности стека обслуживания (идентификатор сессии, клиент, статус, задачи, и действия). Оригинал располагается по пути %WinDir%\servicing\sessions\
WER4BA8.tmp.hdmp Дамп кучи (HeapDump). Дамп сбойного процесса, содержащий, вдобавок к данным минидампа, еще и данные кучи (heap).
WER5644.tmp.mdmp Минидамп (Minidump). Дамп сбойного процесса, содержащий информацию о потоках и стеках потоков.

После изучения содержимого каталога отправки становится очевидным, что WER готовит "отчет" об инциденте, куда включает все необходимые (?) файлы для передачи разработчику. Однако, почему происходило бесконечное создание фактически одинаковых пакетов отсылки? Вероятно, WER действовал в пределах нормы, просто в системе в тот момент что-то очень часто "падало", что и приводило к постоянной генерации отчетов. Давайте попытаемся разобраться что именно. Под рукой у нас для этого имеется все необходимое, а именно пара файлов с именами WER4BA8.tmp.hdmp и WER5644.tmp.mdmp, которые являются ничем иным как разными версиями дампа приложения. Не очень хорошо пока разбираюсь в структуре памяти процесса и не понимаю, что мне могут дать в данной ситуации данные кучи, поэтому откроем любой из этих файлов в отладчике WinDbg, благо в версии 6.12.0002.633 отладчик позволяет открывать и расширение .mdmp и .hdmp (в более ранних версиях могли иметься ограничения). При анализе дампа через команду !analyze -v мы видим имя сбойного процесса (PROCESS_NAME: TrustedInstaller.exe) и ниже по тексту стек вызовов момента падения:

Как мы помним, TrustedInstaller.exe является ключевым модулем для выполнения операций со стеком обслуживания. Судя по стеку вызовов, процесс TrustedInstaller.exe (Установщик модулей Windows) находился в момент сбоя в ожидании какого-то внешнего события, судя по всему ожидании запуска/готовности какого-то сервиса (службы) посредством функций библиотеки sechost.dll (Host for SCM/SDDL/LSA Lookup APIs). В стеке мы видим функцию StartServiceCtrlDispatcherW, которая устанавливает связь главного потока процесса службы с Диспетчером управления службами (SCM), и вызывается, судя по всему, в тот момент, когда SCM запускает процесс службы. Но вот какой именно службы (вероятно, имеется в виду одноименная служба Установщик модулей Windows) и нормально ли завершился процесс запуска, можно сказать только отлаживая код.

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

Двигаемся далее, мы выяснили что падает TrustedInstaller.exe, вопрос почему он падает с завидным постоянством? Ну упало один раз, с кем не бывает :) но зачем же так часто? Выходит, что бы часто падать, необходимо часто запускаться, кто-то постоянно создает задачи на установку пакетов. Вот тут то мы вспоминаем, что у нас в нашей корпоративной среде используется агент SCCM 2012. Что это такое? Выдержка из Wikipedia:

System Center Configuration Manager (SCCM, ранее SMS) — продукт для управления ИТ-инфраструктурой на основе Microsoft Windows и смежных устройств. Предоставляет такие возможности, как: управление обновлениями, развёртывание ПО и операционных систем, интеграция с NAP, инвентаризация аппаратного и программного обеспечения, удалённое управление, управление виртуализированными и мобильными системами на базе Windows.

Очень модная в данный момент штука, чрезвычайно громоздкая, написанная на старом бейсике начала 90-х годов и скомпилированная с опциями максимизации кода (шутка) :) Так вот этот самый агент SCCM и спамил нам постоянно задачи на установку обновлений операционной системы. Вроде как разобрались что именно падает и кто постоянно создает эти падающие впоследствии задачи. Но почему TrustedInstaller.exe падает? Первое что приходит на ум, так это проанализировать файл журнала компонентной модели CBS.log и поискать ответ в нем. Приведу основные, самые интересные (на мой взгляд), выдержки из этого файла, поскольку целиком файл занял порядка 1 гигабайта, вставлять его полностью не вижу возможности да и смысла, поэтому перечислим лишь основные моменты:

Во-первых, бросается в глаза код ошибки 0x800f0805, намекая на битые пакеты (?). Далее в файле можно увидеть интересные сообщения: "Store corruption detected" и "MissingWinningComponentKey on resource", что сразу же наводит нас на мысль о повреждении хранилища компонентов.

Решение

Скорее по привычке, нежели обоснованно, первой я запустил команду Sfc с ключом /verifyonly и тут же получил следующую ошибку:

sfc another service

Эта лишняя (в данной ситуации) команда дала понять, что стек обслуживания кем-то занят. Скорее всего, со стеком одновременно невозможно работать нескольким источникам. Вспоминаем, про TrustedInstaller.exe, однако его снятие нам ничего не даст, поскольку работает агент SCCM, который постоянно создает задачи. Поэтому, сперва при помощи диспетчера задач были сняты все процессы SCCM: CcmExec.exe, CmRcService.exe, а уже затем все процессы msiexec.exe и процесс TrustedInstaller.exe.

kill trustedinstaller

Поле этого вся активность со стеком обслуживания прекратилась. Далее была выполнена команда:

DISM /Online /Cleanup-Image /ScanHealth

результатом выполнения которой было следующее сообщение "Выполнение операции scanhealth завершено, см. журнал по адресу %windir%\logs\CBS\Checksur.log. Операция успешно завершена.":

с рекомендацией проверить файл %WinDir%\Logs\CBS\CheckSUR.log. Привожу выдержку ключевых моментов содержимого данного файла:

Видно, что DISM исправил 376 ошибок. После этого была произведена перезагрузка системы и SCCM продолжил штатную установку обновлений. Более проблем у пользователя не возникало.

Выводы

Инцидент породил слишком большое количество вопросов.

  • Почему у нас агент обновления ругается на битые пакеты? Приходят ли они действительно битые с сервера обновлений или причина в другом?
  • Почему TrustedInstaller не отслеживает повреждения хранилища пакетов/компонентов и падает вместо завершения с кодом ошибки? Ошибка в коде модуля?
  • Почему WER копирует в ReportQueue большие объемы данных, тем самым сильно нагружая систему? А если устроить циклическое падение множества процессов в системе, то WER просто "положит" станцию, как в этом случае?

Я думаю, что все эти вопросы останутся без ответов, поскольку мы не докопались до сути проблемы. Ну а исключить возможность возникновения подобных ситуаций в будущем можно через консоль Configuration Manager Console. Как один из вариантов: Software Library - Software Updates - Software Update Groups, задать для требуемой группы Alert, а вот уже на Alert'ы потом повесить необходимые действия. Возникает вопрос в более тонкой интеграции агента SCCM со стеком обслуживания с целью отслеживания ситуации с падающим процессом TrustedInstaller.exe на клиентской машине и остановке задач по установке компонентов. В нашем случае он продолжал ставить задания на запуск установки обновлений.

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

Добавить комментарий

Ваш e-mail не будет опубликован. Обязательные поля помечены *