Сложное дело о зависаниях Outlook

Об этом случае мне рассказал мой друг Эндрю Ричардс (Andrew Richards), инженер по технической поддержке Microsoft Exchange Server. Этот случай действительно интересен, поскольку при решении проблемы использовалась утилита Sysinternals, которую я написал лично для использования службой поддержки Microsoft, кроме того, фактически это две истории в одной.

Этот случай произошел с системным администратором, который связался со службой поддержки Microsoft, чтобы сообщить о том, что пользователи в его сети жалуются на зависания Outlook, которые длятся около 15 минут. Тот факт, что с данной проблемой столкнулось несколько пользователей, указывает на то, что источником проблемы является Exchange, так что запрос был направлен в службу поддержки Exchange Server.

Команда Exchange разработала набор инструментов для сбора данных Performance Monitor, включающий несколько сотен счетчиков и который бывает очень полезен для диагностики проблем Exchange, включая отслеживание активности сообщений LDAP, RPC и SMTP, счетчик подключений Exchange, счетчик использования памяти и процессора. Поддержка Exchange попросила администратора собрать информацию об активности сервера с циклами по 12 часов, первый из которых должен был продолжаться с 9 часов вечера до 9 часов следующего утра. Когда инженеры поддержки Exchange просмотрели записанный лог, они смогли сразу отметить две тенденции, даже несмотря на большое количество записей: первое - это то, что загрузка сервера Exchange утром увеличивалась, когда пользователи приходили на работу и запускали Outlook; второе - графики активности показывали изменения в поведении сервера в период времени между 8:05 и 8:20 утра, что в точности совпадало с длительностью зависаний, на которые жаловались пользователи:

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

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

Одним из способов получения дампа является "присоединение" к процессу отладчика, такого как Windbg из пакета Debugging Tools for Windows (входит в состав Windows Software Development Kit) и выполнение команды .dump, но загрузка и установка этих инструментов, запуск отладчика, присоединение к правильному процессу и сохранение дампов является длительной процедурой. Вместо этого Эндрю сказал администратору загрузить утилиту Sysinternals Procdump (отдельная утилита, которую вы можете запустить без необходимости установки какого-либо ПО на сервере). Procdump позволяет просто получать дамп процесса и включает в себя опции, которые создают несколько дампов за указанный временной интервал. Эндрю попросил администратора запустить Procdump в следующий раз, когда упадут показатели использования CPU сервером, что она сгенерировала пять дампов процесса Exchange Server, Store.exe, отстоящих друг от друга на три секунды:

procdump -n 5 -s 3 store.exe c:\dumps\store_mini.dmp

На следующий день проблема снова проявилась, и администратор послал Эндрю файлы дампов, сгенерированные Procdump. Когда процесс временно зависает, это часто это связано с тем, что один из потоков этого процесса блокирует защищенные данные, к которым нужно обратиться другим потокам, и удерживает эту блокировку, выполняя какую-то длительную операцию. Поэтому первым делом Эндрю проверил сделанные блокировки. Часто используемая внутрипроцессная синхронизирующая блокировка является критической секцией, и команда отладчика !locks выводит список таких критических секций в дампе, которые были блокированы, ID потока, который производил блокировку и число потоков, которые ожидали освобождение ресурса. Эндрю использовал похожую команду !critlist из расширения отладчика Sieext.dll (общедоступную версию которого, Sieextpub.dll, можно скачать здесь). На выходе этой команды стало видно, что несколько потоков ожидали освобождения потоком 223 критической секции:

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

Как мы уже видели в предыдущих статьях из цикла "Дело о …", отладчик не уверен, как интерпретировать стек, когда он сталкивается с кадром стека, указывающим на Savfmsevsapi - образ, для которого он не может получить символы. Для большинства образов Windows используемые ими символы зарегистрированы на сервере символов Microsoft, так что скорее всего это была сторонняя DLL, загруженная в процесс Store.exe, и поэтому подозреваемая в вызове зависания. Команда перечисления модулей ("lm") извлекает информацию о версиях загруженных модулей, и пути к этим модулям явно указали на то, что Savfmsevsapi был частью продукта обеспечения безопасности почты от Symantec:

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

Однако, в последующие несколько дней администратор стал получать жалобы от некоторых пользователей о том, что Outlook спорадически зависал в течение минуты. Эндрю попросил администратора послать ему данные Performance Monitor об активности за 12 часов для сервера Exchange, но на этот раз никаких очевидных аномалий он не обнаружил:

В попытке определить, отразилось ли зависание на истории использования CPU процессом Store.exe, он удалил все счетчики за исключением счетчика использования CPU данным процессом. Когда он увеличил фрагмент графика, соответствующий утренним часам, когда пользователи входили в систему и загружали сервер, он обратил внимание на три пика в районе 8:30 утра:

Поскольку у сервера есть 8 ядер, счетчик использования процессора для отдельного процесса может использовать диапазон от 0 до 800, так что данные пики были далеки от пределов системы, но определенно выше типичных показателей Exchange для данной системы. Еще больше увеличив график и установив для него вертикальный масштаб так, чтобы еще больше выделить данные пики, он заметил, что средние показатели использования процессора были всегда ниже 75% для одного ядра и пики наблюдались около 15-30 секунд:

Что делал Exchange, когда появлялись эти пики? Они были слишком коротки и случайны, чтобы администратор мог как раньше запустить Procdump и сделать дампы. К счастью, при разработке Procdump я предусмотрел такой сценарий. Она поддерживает несколько условий, при выполнении которых эта утилита генерирует дамп. Например, вы можете настроить Procdump, чтобы сгенерировать дамп для процесса, когда происходит завершение процесса, когда его использование памяти превышает некоторое значение, или даже на основании установленного вами значения счетчика производительности. Тем не менее, основным условием для его запуска являются показатели использования CPU процессом, превышающие указанный порог в течение указанного отрезка времени.

Лог Performance Monitor предоставил Эндрю информацию, которая была нужна ему для составления команды Procdump, которая фиксировала бы дампы для будущих пиков использования CPU:

procdump.exe -n 20 -s 10 -c 75 -u store.exe c:\dumps\store_75pc_10sec.dmp

Данные аргументы указывают Procdump генерировать дамп процесса Store.exe, когда его использование CPU превышает 75% (-c 75) для одного ядра (-u) за десять секунд (-s 10), генерировать до 20 дампов (-n 20), после чего прекращать работу и сохранять дампы в директории C:\Dumps с именами, начинающимися с "store_75pc_10sec". Администратор выполнил команду до того, как пойти домой с работы и затем проверил результаты ее выполнения следующим утром, когда утилита создала 20 файлов дампов. Он отослал их Эндрю в письме, который приступил к их поочередному анализу в отладчике Windbg.

Когда Procdump генерирует дамп по событию CPU, она устанавливает контекст потока в файле дампа для потока, который больше всего занимал CPU на время формирования дампа. Команды отладчика для формирования дампа стека работают относительно текущего контекста потока, простой ввод такой команды наиболее вероятно покажет поток, вызвавший пики в использовании CPU. Больше половины дампов были бесполезны, поскольку они были сделаны уже после того, как пик, вызвавший запись дампа, прошел, или же из-за того, что содержали потоки, выполнявшие код, который, очевидно, не был напрямую связан с пиком. Однако, некоторые дампы имели стек, выглядевший как этот:

Данный кадр стека относился к функции Store EcFindRow, указывавшей на то, что пики были вызваны длинными запросами к базе данных, которые выполняются, когда Outlook обращается к папке с почтой, содержащей тысячи записей. Руководствуясь этими данными, Эндрю предложил администратору составить список больших почтовых ящиков и указал ему на статью команды поддержки Exchange, описывающей, как сделать это в различных версиях Exchange:

Данный скрипт выявил нескольких пользователей, в почтовых ящиках которых содержались десятки тысяч элементов. Администратор попросил этих пользователей уменьшить количество писем так, чтобы их было не больше 5000 (это рекомендация для Exchange 2003; в каждой новой версии это число увеличивается и для Exchange 2010 составляет 100 000 писем), путем их архивации, удаления или размещения их в подпапках. В течении нескольких дней они реорганизовали проблемные папки и жалобы от пользователей прекратили поступать. Мониторинг состояния сервера Exchange на протяжении следующей недели подтвердил, чтоб проблема была решена.

Благодаря Procdump, сложное дело о зависаниях Outlook было успешно закрыто.


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