Хабрахабр

Отладка как процесс

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

Таким образом, оптимизация и систематизация процесса debugging'а может приносить весомые плоды в виде сэкономленных человеко-часов, повышения скорости решения проблем и, в конце концов, увеличения лояльности ваших пользователей.

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

(А еще в конце поста мы добавили обращение Джона Скита ко всем дотнетчикам, обязательно посмотрите)

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

На своих примерах я покажу что получалось из-за нарушения этих правил. Мы выработаем общий язык общения во время отладки, а также увидим прямой путь к поиску основных проблем.

Утилиты отладки


Конечно, любой debugging невозможен без утилит для отладки. Моими любимыми являются:

  • Windbg, который помимо самого debugger'а, имеет богатый функционал по изучению дампов памяти. Дамп памяти — это срез состояния процесса. В нем можно найти значение полей объектов, call-stack'и, но, к сожалению, дамп памяти статичен.
  • PerfView — это профилировщик, написанный поверх ETW-технологии.
  • Sysinternals — утилита, написанная Марком Руссиновичем, которая позволяет чуть дальше копнуть внутрь устройства операционной системы.

Падающий сервис

Начнем с примера из моей жизни, в котором я покажу, как бессистемность процесса debugging'а ведет к неэффективности.

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

Net 3. Сервис был написан под . У этого сервиса была маленькая особенность — он падал. 0 и было это очень давно. Пофиксили мы это элегантно — выставили в свойствах сервиса рестарт после падения. Падал часто, примерно раз в два-три часа.

Но к проекту подключился я и первое, что решил сделать — исправить это. Сервис был для нас не критичен и мы могли это пережить.

NET-разработчики идут в случае, если что-то не работает? Куда . Но там я не нашел ничего, кроме записи о том, что сервис упал. Они идут в EventViewer. Ни сообщений о нативной ошибке, ни call-stack'а не было.

Есть проверенный инструмент что делать дальше — оборачиваем весь main в try-catch.

try { ProcessRequest();
} catch (Exception ex) { LogError(ex);
}

Идея простая: try-catch сработает, залогирует нам ошибку, мы её прочитаем и пофиксим сервис. Компилируем, деплоим в продакшн, сервис падает, ошибки нет. Добавляем ещё один catch.

try { ProcessRequest();
} catch (Exception ex) { LogError(ex);
} catch { LogError();
}

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

try { ProcessRequest();
} catch (Exception ex) { LogError(ex);
} catch { LogError();
} finally { LogEndOfExecution();
}

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

Прошло две недели.

Это состояние называется отчаяние и выглядит вот так: Я смотрел в PerformanceMonitor, где видел сервис, который падает, потом поднимается, потом снова падает.

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

Нативный handle — это ссылка на ресурс операционной системы: файл, реестр, ключ реестра, мьютекс и тд. Красная линия — это количество нативных handle'ов, которыми владеет процесс. Это наталкивает на мысль о том, что где-то есть утечка handle'ов. По какому-то непонятному стечению обстоятельств падение роста количества handle'ов совпадает с моментами падения сервиса.

Начинаем выполнять команды. Берем дамп памяти, открываем его в WinDbg. Попробуем посмотреть очередь финализации тех объектов, которые должны быть освобождены приложением.

0:000> !FinalizeQueue

В самом конце списка я нашел web-браузер.


Решение простое — взять WebBrowser и вызывать для него dispose:

private void Process() { using (var webBrowser = new WebBrowser()) { // Processing ...
}
}

Выводы из этой истории можно сделать такие: две недели — это долго и слишком много, чтобы найти невызванный dispose; то, что мы нашли решение проблемы — везение, так как не было какого-то определенного подхода, не было системности.

После этого у меня возник вопрос: а как дебажить эффективно и что для этого делать?

Для этого надо знать всего три вещи:

  1. Правила отладки.
  2. Алгоритм нахождения ошибок.
  3. Проактивные техники отладки.

Правила отладки

  1. Повтори ошибку.
  2. Если ты не исправил ошибку, то она не исправлена.
  3. Пойми систему.
  4. Проверь штепсель.
  5. Разделяй и властвуй.
  6. Освежись.
  7. Это твой баг.
  8. Пять почему.

Это довольно понятные правила, которые сами себя описывают.

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

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

Брайан Керниган сказал как-то, что если мы были такие умные, чтобы написать эту систему, то нам нужно быть вдвойне умными, чтобы её дебажить. Пойми систему.

Наш мониторинг рисует графики: Небольшой пример к правилу.

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

Оптимизация web-performance делается просто: берем PerfView, запускаем его на продакшн-машине, он снимает trace в течении 3-4 минут, мы этот trace забираем на локальную машину и начинаем его изучать.

Одна из статистик, которую показывает PerfView — garbage collector.

Можно в PerfView увидеть где конкретно тратится это время. Посмотрев на эту статистику мы увидели, что 85% времени сервис тратит на сборку мусора.

Исправление напрашивается само самой: заменяем все string'и на StringBuilder'ы. В нашем случае — это создание строк. Деплоим на продакшн, смотрим результаты в сравнении со старым графиком: Локально получаем прирост производительности на 20-30%.

Правило «Пойми систему» — это не только о том, чтобы понять как в вашей системе происходят взаимодействия, как ходят сообщения, а о том, чтобы попробовать смоделировать свою систему.

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

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

Отладка не начинается с запуска WinDbg или PerfView на продакшн-машинах, она начинается с проверок фактов и данных. Правило «проверь штепсель» — это про факты и данные. Если сервис не отвечает, возможно он просто не запущен.

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

Один из наших сервисов не хотел останавливаться.

Делаем гипотезу: возможно, в проекте есть цикл, который бесконечно что-то обрабатывает.

Из дампа вытаскиваем call-stack'и всех потоков с помощью команды ~*e! Проверить гипотезу можно по-разному, один из вариантов — это взять дамп памяти. Начинаем смотреть и видим три потока. ClrStack.

Таким образом, наша гипотеза не оправдывается. Первый поток находится в Main'е, второй — в обработчике OnStop(), а третий поток ждал какие-то внутренние задачи. Скорее всего, deadlock. Здесь нет зацикливания, все потоки чего-то ждут.

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

Чтобы это проверить, можно через WinDbg посмотреть каждую задачу по-отдельности. Делаем вторую гипотезу: возможно, у нас deadlock одной задачи на вторую.

В проекте мы увидели такой код: Оказывается, одна из задач упала, а вторая — нет.

await openAsync();
_initLock.SetResult(true);

Он означает, что инициализационная задача открывает connection и после этого выставляет TaskCompletionSource в true. А что, если здесь упадет Exception? Тогда мы не успеваем выставить SetResult в true, поэтому fix к этому багу был такой:

try { await openAsync();
_initLock.SetResult(true);
} catch(Exception ex) { _initLock.SetException(ex);
}

В этом примере мы выдвигали две гипотезы: о бесконечном цикле и о deadlock'e. Правило «разделяй и властвуй» помогает локализовать ошибку. Последовательными приближениями и решаются такие проблемы.

И в зависимости от гипотезы мы применяем разные действия. Самое важное в этом правиле — это гипотезы, поскольку со временем они превращаются в паттерны.

Это правило о том, что надо просто встать из-за стола и пройтись, выпить воды, сока или кофе, сделать что угодно, но самое главное — отвлечься от своей проблемы. Освежись.

Согласно методу мы должны рассказать о своей проблеме уточке. Есть очень хороший метод под названием «уточка». Причем, ему не обязательно отвечать, достаточно слушать и соглашаться. В качестве уточки можно использовать коллегу. И зачастую, после первых проговоров проблемы, ты сам находишь решение.

Об этом правиле расскажу на примере. Это твой баг.

Посмотрев в call-stack я увидел, что он возникал, когда мы генерировали LinqToSql-запрос внутри sql-клиента. Была проблема в одном AccessViolationException.

К счастью, в то время мы уже использовали change management system. По этому багу было понятно, что где-то нарушается целостность памяти. Net 4. В итоге через пару часов стало понятно что произошло: мы поставили . 2 на наши продакшн-машины. 5.

Net 4. Соответственно, мы отправляем баг в Microsoft, они его рассматривают, мы с ними общаемся, они исправляют баг в . 1. 6.

Кроме этого, мы отправили им десятки гигабайт дампов памяти, мы ставили сотни private-сборок, чтобы поймать эту ошибку. Для меня это вылилось в 11 месяцев работы с поддержкой Microsoft, конечно, не ежедневно, но от начала до fix'а прошло именно 11 месяцев. Поэтому баг всегда ваш. И все это время мы не могли сказать нашим клиентам, что виновата Microsoft, а не мы.

Мы у себя в компании используем Elastic. Пять почему. Elastic хорош для агрегации логов.

Ты приходишь с утра на работу, а Elastic лежит.

Практически сразу стало понятно — упали Master Nodes. Первый вопрос — почему лежит Elastic? Почему они не поднялись? Они координируют работу всего кластера и, когда они падают, то весь кластер перестает отвечать. Поискав ответ, нашли — не соответствует версия плагина. Наверно, должен стоять автостарт? Их убил OOM Killer. Почему же Master Nodes вообще упали? Почему же стало мало памяти? Это такая штука на linux-машинах, которая в случае нехватки памяти закрывает ненужные процессы. Почему же раньше это работало, а сейчас нет? Потому что запустился процесс обновления, что следует из системных логов. А потому что мы неделей раньше добавили новые узлы, соответственно Master Nodes понадобилось больше памяти для хранения индексов, конфигурации кластера.

В примере мы много раз могли свернуть с правильного пути, но полный fix выглядит так: обновляем плагин, запускаем сервисы, наращиваем память и делаем пометку на будущее, что в следующий раз, при добавлении новых узлов в кластер, нужно убедиться в достаточности памяти на Master Nodes. Вопросы «почему?» помогают найти корень проблемы.

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

Алгоритм отладки

Впервые про алгоритм отладки я прочитал в книге Джона Роббинса «Debugging applications». Он описывает процесс отладки так:

Этот алгоритм полезен своим внутренним циклом — работой с гипотезой.

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

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

На одном из наших web-сервисов падал exception. На этот алгоритм у меня есть хороший пример.

Но по правилам, это все-таки проблема наша. Первая наша мысль — это не наша проблема.

На каждую тысячу запросов примерно один StructureMapException, поэтому воспроизвести проблему можем. Во-первых, повторяем ошибку.

Во-вторых, пытаемся описать проблему: если пользователь делает http-запрос на наш сервис в момент, когда StructureMap пытается сделать новую зависимость, то в этом случае происходит исключение.

Проверяем гипотезу с помощью procdump.exe. В-третьих, выдвигаем гипотезу о том, что StructureMap — это wrapper и внутри что-то есть, что кидает внутреннее исключение.

procdump.exe -ma -e -f StructureMap w3wp.exe

Оказывается, что внутри лежит NullReferenceException.

Исследуя call-stack этого исключения понимаем, что оно происходит внутри object-builder'а в самом StructureMap.

Нужно понять где оно возникает и кто его генерирует. Но NullReferenceException — это не сама проблема, а следствие.

Учитывая, что в . Выдвигаем следующую гипотезу: наш код почему-то возвращает зависимость null. Net все объекты в памяти располагаются один за одним, если мы посмотрим на объекты в куче, которые лежат до NullReferenceException, то они нам, возможно, укажут на код, который сгенерировал исключение.

Она показывает, что интересный нам объект — это лямбда-функция, которая используется в следующем коде. В WinDbg есть команда — List Near Objects: !lno.

public CompoundInterceptor FindInterceptor(Type type) { CompoundInterceptop interceptor; if (!_analyzedInterceptors.TryGetValue(type, out interceptor)) { lock (_locker) { if (!_analyzedInterceptors.TryGetValue(type, out interceptor)) { var interceptorArray = _interceptors.FindAll(i => i.MatchesType(type)); interceptor = new CompoundInterceptor(interceptorArray); _analyzedInterceptors.Add(type, interceptor);
}
}
}
return interceptor;
}

В этом коде мы сначала проверяем существует ли значение в Dictionary в _analyzedInterceptors, если не находим, то внутри lock добавляем новое значение.

Но проблема здесь в _analyzedInterceptors, который использует обычный Dictionary в многопоточной среде, а не ConcurrentDictionary. По идее этот код никогда не сможет вернуть null.

Последний шаг нашего алгоритма — это «научись и расскажи». Корень проблемы найден, мы обновились до последней версии StructureMap'а, задеплоили, убедились, что все исправлено. В нашем случае это был поиск в коде всех Dictionary, которые используются в lock'е и проверка, что все они используются правильно.

Он делает упор на гипотезу — а это самое главное в отладке. Итак, алгоритм отладки — это интуитивный алгоритм, который существенно экономит время.

Проактивная отладка

По своей сути проактивная отладка отвечает на вопрос «что произойдет, когда появится баг».

Важность техники проактивной отладки можно увидеть на диаграмме цикла жизни бага.

Проблема в том, что чем дольше баг живет, тем больше мы ресурсов (времени) на него тратим.

На самом же деле мы хотим сместить свой фокус на момент создания бага. Правила отладки и алгоритм отладки фокусируют нас на моменте, когда баг найден и мы можем придумать что дальше с ним делать. Я считаю, что мы должны делать Minimum Debuggable Product (MDP), то есть такой продукт, который имеет минимально необходимый набор инфраструктуры для эффективной отладки в продакшене.

MDP состоит из двух вещей: фитнес-функции и USE метода.

Были популяризированы Нил Фордом и соавторами в книге «Building Evolutionary Architectures ». Фитнес-функции. Таким образом, фитнес-функция — это тест на архитектуру. По своей сути фитнес-функции, по мнению авторов книги, выглядят так: есть архитектура приложения, которую мы можем разрезать под разными углами, получая такие свойства архитектуры, как maintainability, performance и прочее, и на каждый такой разрез мы должны писать тест — фитнес-функцию.

Для написания таких тестов можно использовать все что угодно: NUnit, MSTest и тд. В случае MDP, фитнес-функция — это проверка debuggability. Его плюс здесь в том, что он хорошо работает с командной строкой. Но, поскольку, отладка — это, зачастую, работа с внешними tool'ами, я покажу на примере использование Pester'а (powershell unit testing framework).

Это и будет являться теми условностями, которые мы будем проверять в наших тестах. Например, внутри компании мы договариваемся, что будем использовать конкретные библиотеки для логирования; при логировании мы будем использовать конкретные паттерны; pdb-символы должны быть отданы всегда на symbol server.

Describe 'Debuggability’ ` | Where-Object { $_ -like "*Line nubmers: TRUE*" } ` | Should -Not –BeNullOrEmpty } }

Этот тест проверяет, что все pdb-символы были отданы на symbol server и были отданы правильно, то есть те, которые содержат номера строк внутри. Для этого берем скомпилированную версию продакшена, находим все exe- и dll-файлы, пропускаем все эти бинарники через утилиту syschk.exe, которая входит в пакет «Debugging tools for windows». Утилита syschk.exe сверяет бинарник с symbol server'ом и, если находит там pdb-файл, печатает отчет об этом. В отчете мы ищем строку «Line numbers: TRUE». И в финале проверяем, чтобы результат был не «null or empty».

После того, как прошли интеграционные тесты и unit-тесты, запускаются фитнес-функции. Такие тесты необходимо встраивать в continuous deployment pipeline.

Покажу ещё один пример с проверкой нужных библиотек в коде.

Describe 'Debuggability’ { It 'Contains package for logging’ { Get-ChildItem -Path . -Recurse -Name "packages.config" ` | ForEach-Object { Get-Content "$_" } ` | Where-Object { $_ -like "*nlog*" } ` | Should -Not –BeNullOrEmpty } }

В тесте мы берем все файлы packages.config и пытаемся найти в них библиотеки nlog. Аналогично мы можем проверить, что внутри поля nlog используется поле correlation id.

Последнее, из чего состоит MDP — это метрики, которые нужно собирать. USE методы.

Идея простая: если в коде есть какая-то проблема, достаточно взять три метрики: utilization (использование), saturation (насыщение), errors (ошибки), которые помогут осознать где проблема. Продемонстрирую на примере метода USE, который был популяризирован Бренданом Греггом.

Некоторые компании, например Circonus (они делают monitoring soft), свои дашборды выстраивают в виде обозначенных метрик.

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

Если взять какую-нибудь бизнес-фичу, то, скорее всего, в ней можно выделить три метрики:

  • Использование — время обработки запроса.
  • Насыщение — длина очереди.
  • Ошибки — любые исключительные ситуации.

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

При проверке оказывается, что сервис работает, использует 4-5% CPU. Первая гипотеза, которую мы сделали, — сервис упал и надо его запустить заново.

Воспользуемся утилитой etrace. Вторая гипотеза — внутри сервиса падает ошибка, которую мы не видим.

etrace --kernel Process ^ --where ProcessName=Ex5-Service ^
--clr Exception

Утилита позволяет в realtime подписываться к ETW-events и выводить их на экран.

Но, второй вопрос, почему его нет в логах? Видим, что падает OutOfMemoryException. Ответ находится быстро — мы его перехватываем, пытаемся подчистить память, немного подождать и начать работать заново.

while (ShouldContinue()) { try { Do(); } catch (OutOfMemoryException) { Thread.Sleep(100); GC.CollectionCount(2); GC.WaitForPendingFinalizers(); } }

Следующая гипотеза — кто-то съедает всю память. Согласно дампу памяти, больше всего объектов находится в кэше.

public class Cache { private static ConcurrentDictionary<int, String> _items = new ...
private static DateTime _nextClearTime = DateTime.UtcNow; public String GetFromCache(int key) { if (_nextClearTime < DateTime.UtcNow) { _nextClearTime = DateTime.UtcNow.AddHours(1); _items.Clear(); } return _items[key]; } }

Из кода видно, что каждый час кэш должен очищаться. Но памяти уже не хватало, до очистки даже не доходили. Посмотрим на пример метрики USE для кеша.

По графику сразу видно — возросла память, сразу начались ошибки.

Итак, выводы о том, что же такое проактивная отладка.

  • Отладка — это требование к архитектуре. По сути, то, что мы разрабатываем — это модель работы системы. Сама же система — это байты и биты, которые лежат в памяти на продакшн-серверах. Проактивная отладка говорит о том, что необходимо думать о своем операционном окружении.
  • Уменьшайте путь бага в системе. К техникам проактивной отладки относятся и проверка всех публичных методов и их аргументов; кидать Exception сразу, как он появился, а не отлаживать до какого-то момента и тд.
  • Minimum Debuggable Product — хороший инструмент, чтобы коммуницировать между собой и вырабатывать требования к отлаживаемости продукта.

Итак, как фиксить баги эффективно?

  1. Применяйте проактивную отладку.
  2. Следуйте алгоритму.
  3. Проверяйте гипотезы.

В этот раз спонсор нашей рекламы — Jon Skeet. Даже если вы не собираетесь в Москву на новый DotNext, видео стоит посмотреть (Джон очень старался).

Теги
Показать больше

Похожие статьи

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

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

Кнопка «Наверх»
Закрыть