Фев. 23

Возврат в прошлое. Историческая отладка приложений

Привет. В этой статье хочу рассказать о приеме, который поможет вам быстрее исправлять ошибки в Production.

Для работы нам понадобится Visual Studio Enterprise, триал можно скачать тут. Но для начала, по традиции, обрисую проблематику.

Жизненный цикл ошибки

Не думаю, что стоит объяснять влияние скорости исправления ошибок на бизнес. Посему провалимся сразу в метрику. Есть такой KPI: MTTR (Mean Time To Repair). Если просто, то это время, затрачиваемое на исправление ошибок в системе. Задача состоит в том, чтоб это время сократить. Для того, чтоб его сократить, давайте разберемся, из чего оно состоит. Представим себе, что в продуктиве начинает глючить наше приложение. Условно время жизни дефекта можно поделить на пять этапов:
— Первый отрезок времени — это то, насколько быстро баг обнаружат и заведут соответствующий тикет в инцидент менеджмент систему;
— Второй отрезок времени — это то, насколько быстро тикет дойдет до «нужного» человека, который непосредственно будет исправлять проблему;
— Третий отрезок времени — поиск причины проблемы и исправление;
— Четвертый отрезок времени — тестирование изменений;
— Пятый отрезок времени — согласование и применение изменений.

Давайте подумаем, как мы можем повлиять на это время.

Скорость обнаружения бага (первый отрезок времени) напрямую зависит от зрелости систем диагностики и поддержки бизнес приложений, если это проблема «технического» характера. Иными словами, если начинают валится необработанные исключения, сбои в системе, нужно как можно больше информации об этом собрать в логи и как можно быстрее оповестить ответственных сотрудников о возникновении аномалий. Также в средних и больших компаниях, у которых есть свои вычислительные мощности, есть команда «operational», которая посменно, 24\7 смотрит в кучу мониторов и глазами отслеживают деградацию производительности, перегрузку серверов, алерты от систем. Есть и другие источники, которые могут оповестить о возникшей проблеме: пользователи систем, колл-центры. Тут важно наладить эффективную коммуникацию между IT поддержкой и этими самыми пользователями. В разных компаниях, в зависимости от размера штата сотрудников, вида деятельности, эти процессы выстраиваются по-своему и серебряной пули здесь нет.

На втором отрезке времени все зависит от ваших бизнес процессов. Часто бывает так, что после обнаружения проблемы заводится тикет, который несколько дней еще гуляет от отдела к отделу, пока не найдет «своего» человека.

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

С четвертым отрезком времени в принципе все ясно. Главное — не проводить точечное тестирование конкретного метода, в котором обнаружилась ошибка, а прогонять все тесты, которые были созданы ранее (мало ли, вдруг ваше исправление негативным образом повлияет на другой функционал).

С пятым отрезком все не так просто. Я работал в разных компаниях, где исправления применялись, например, только при смене логической даты или раз в 2 недели (было и такое) вместе с выпуском накопительного патча. В общем, это опять-таки, ваши бизнес процессы.

Так же стоит учитывать, что баги бывают разных приоритетов, и в зависимости от приоритета они могут идти по разным веткам процессов. Соответственно, и MTTR для них будет разным.

Я предлагаю сфокусироваться на третьем участке.

Поиск причины бага

Если проанализировать, на что мы тратим время в ходе исправления бага в коде, окажется, что большая часть времени уходит на анализ того, где конкретно и из-за чего произошла ошибка. А уж потом непосредственное исправление кода. StackTrace — это, конечно, хорошо, но помогает далеко не всегда.

Лет пять назад, когда я начинал изучать платформу Azure PaaS (Azure Cloud Services), была проблема: есть Azure эмулятор, который позволяет разрабатывать приложение. Так вот, при разработке сервиса в эмуляторе вроде все окей, приложение загружается и не подает никаких признаков нестабильной работы. Как только приложение уезжает в облако, начинается процесс «cycling»: поднимается сервер, поднимается приложение, возникает критическая ошибка, сервер перезагружается и опять то же самое. Это происходит до тех пор, пока вы руками на портале не грохните ваш deployment. Выяснить причину тогда было практически не реально: удаленной отладки не было, стандартная диагностика не давала необходимой информации.

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

Решением было включение IntelliTrace — это отладка событий, которые по факту уже произошли. Это достаточно интересный инструмент в Visual Studio, который позволяет визуально отобразить, в каком участке кода произошло исключение, какие параметры методу были переданы. В общем, что произошло до того, как возникла ошибка.

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

Стоит сказать, что сам по себе Intellitrace встроенн в Visual Studio, и с его помощью можно собирать всю необходимую для отладки информацию на локальном компьютере.

Для сбора информации на сервере используется IntelliTrace Standalone Collector.

Использование IntelliTrace Standalone Collector

По сути эта тула собирает RunTime логи вашего приложения и складывает их на диск. Когда стала необходимость понять, что же творится на сервере, вы просто качаете лог, загружаете его в Visual Studio и в режиме отладки, строчка за строчкой, смотрите как работало ваше приложение.

Для настройки коллектора на сервере необходимо выполнить несколько простых шагов:

1. Скачать последний IntelliTrace Standalone Collector;

2. Извлечь .cab файл командой
expand /f:* IntelliTraceCollection.cab;

3. Сконфигурировать план сбора данных.

По умолчанию при установке коллектора создается два XML файла:
— collection_plan.ASP.NET.trace.xml — аналогичный настройке Intellitrace по умолчанию в Visual Studio;
— collection_plan.ASP.NET.default.xml — это эквивалент «IntelliTrace events and call information» настройки в Visual Studio.

Настраивать планы сбора можно либо вручную путем редактирования XML, либо используя открытую тулу IntelliTrace Collection Plan Configurator.

4. Указать директорию, куда будут складываться логи. Указывается в плане сбора, в тэге «LogFileDirectory». Например: "C:\IntelliTraceLogFiles".

5. Дать доступ нашему веб приложению к директории с логами:
icacls "C:\IntelliTraceLogFiles" /grant "IIS APPPOOL\DefaultAppPool":F

6. Если Powershell не установлен на сервере, установить его:

7. Импортировать IntelliTrace powershell cmdlets.

Для этого нужно запустить Powershell и выполнить:
Import-Module "C:\IntelliTraceCollector\Microsoft.VisualStudio.IntelliTrace.PowerShell.dll"

8. Запустить сбор логов:
Start-IntelliTraceCollection "<ApplicationPool>" <PathToCollectionPlan> <FullPathToITraceFileDirectory>

Логи будут записываться в .iTrace файл.

Несколько команд для работы коллектором:
Checkpoint-IntelliTraceCollection «<applicationpool>» — снять снепшот .iTrace файла;
Get-IntelliTraceCollectionStatus — получить текущий статус коллектора;
Stop-IntelliTraceCollection «<applicationpool>» — остановить сбор логов.

Стоит сказать, что IntelliTrace Standalone Collector может собирать данные с любых Managed приложений или служб.

Вот пример запуска коллектора для приложения:
C:\IntelliTraceCollector\IntelliTraceSC.exe launch /cp:"C:\IntelliTraceCollector\collection_plan.ASP.NET.default.xml" /f:"C:\IntelliTraceLogFiles\MyApp.itrace" "C:\MyApp\MyApp.exe"

А для запуска коллектора над зарегистрированной службой

Нужно в реестре перейти к ключу:
HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\MyWindowsService

И в значении добавить:

COR_ENABLE_PROFILING=1 
COR_PROFILER={AAAAAA70-DFED-4CB4-A1D6-920F51E9674A} 
COR_PROFILER_PATH=<Path_where_collector_was_extracted>\Microsoft.IntelliTrace.Profiler.14.0.0.SC.dll 
VSLOGGER_CPLAN=<Full_path_to_collection_plan_XML_file>

После этого перезапустить службу. Важно убедится, что пользователь, из-под которого запущена служба, имеет доступ на запись в папку с логами.

Собственно, после того, как логи записаны, их можно скачать на локальный компьютер и открыть в Visual Studio:

Мы можем просмотреть детали события, кликнув «View Details»:

Тут мы можем посмотреть дерево вызовов, а кликнув «Debug this call» перейти непосредственно в режим исторической отладки:

Если в нашем приложении возникали исключения, они попадают в отдельную группу «Exception Data»:

Откуда мы сразу можем перейти к отладке:

Несколько советов по применению

Применять на Production этот механизм нужно аккуратно. В зависимости от детализации логов, Intellitrace может просаживать производительность вашего приложения в большей или меньшей степени. В идеале его включать только при воспроизведении ошибок или когда «что-то идет не так».

В настройках обязательно указывайте лимит в MB на максимальный размер лога.

Версия приложения, которая крутится на сервере и которую вы проверяете, должна совпадать с версией кода, который загружен в Visual Studio. Посему, не забудьте из Source Control поднять нужную версию кода.

Если есть вопросы, пишите в комментариях, отвечу.