Отладка средствами trace/dbg/sys

11 октября 2014

Доклад для 5-й встречи Belarus Erlang User Group. На сей раз встреча публиковалась в youtube :)

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

И какие найдутся для этого средства? Да много их:

  • отладка через логи в консоль или файл;
  • debugger;
  • trace/dbg;
  • sys;
  • библиотеки-обертки над все этим от третьих сторон.

Полагаю, что многие, как и я сам, хорошо знакомы с отладкой через логи. lager, io:format (вероятно обернутый в макрос или функцию) – вот они, друзья программиста :)

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

Имеется графический отладчик, debugger. Он менее известен. Я вот и не пользовался ни разу. Но кому-то, наверное, полезен :)

Про debugger надо сказать, что он отлаживает один процесс, а в это время остальные процессы живут своей жизнью. И, вероятно, пытаются взаимодействовать с отлаживаемым процессом. Посылают сообщения, ждут ответа. А отлаживаемый процесс как раз остановлен брейкпоинтом.

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

Все это в том или ином виде есть в большинстве языков. А Erlang, кроме этого, предлагает свои инструменты. Причем встроенные на самом низком уровне, с низким влиянием на работу системы (с некоторыми оговорками), и применимую для отладки в реальном времени на продакшене. Об этом и поговорим.

Тулы эти мощные, но довольно сложные в освоении. Конечно, есть документация. Но лучше начать с более простых источников:

trace/dbg неплохо описаны в 17-й главе "Erlang Programming" Francesco Cesarini и в 9-й главе "Stuff Goes Bad. Erlang in Anger" Fred Hebert.

У Цезарини более подробно и обстоятельно. У Фреда кратко и больше про recon – его тулзу для мониторинга системы, и recon_trace – обертку над dbg, кое-что упрощающую и кое-что полезное добавляющую.

erlang:trace, erlang:trace_pattern

Функции модуля erlang, низкоуровневый инструмент, который является основанием для других, более удобных тулов. Присутствует в языке с первой версии.

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

Так что нужно быть осторожным, выбирая параметры трассировки. И использовать более грамотные обертки, как recon_trace Фреда Хеберта.

erlang:trace(PidSpec, How, FlagList) -> integer()

http://www.erlang.org/doc/man/erlang.html#trace-3

У функции 3 аргумента.

PidSpec указывает, какие процессы мы хотим трассировать. How это флаг, включающий или выключающий трассировку. FlagList указывает, какие события на этих процессах мы хотим трассировать.

PidSpec имеет варианты:

  • Pid процесса
  • атомы: existing, new, all;

existing – трассировать имеющиеся процессы, игнорировать новые, которые создаются уже после того, как трассировка включена. new – наоборот, игнорировать имеющиеся процессы, трассировать новые. all – трассировать все процессы.

FlagList имеет много вариантов. Рассмотрим некоторые.

  • send, 'receive' – трассировать отправку/получение сообщений
  • procs – трассировать события жизненного цикла процесса и связи между процессами: spawn, exit, link, unlink, getting_linked, getting_unlinked, register, unregister
  • call – трассировать вызовы функций (подробности ниже)
  • running – трассировать работу планировщика процессов
  • garbage_collection – трассировать сборку мусора

Когда включена трассировка, генерируются специальные сообщения вида:
{trace, Pid, EventTag, Data1 [,Data2]}

Например:
{trace, Pid, 'receive', Msg} - процесс Pid получил сообщение Msg
{trace, Pid, send, Msg, To} - процесс Pid отправил сообщение Msg процессу To
{trace, Pid, call, {M, F, Args}} - процесс Pid начал выполнение функции {M, F, Args}
и т.д.

Кто получает эти сообщения? По умолчанию тот процесс, который вызвал erlang:trace. Но можно при вызове указать в FlagList аргумент {tracer, Pid}, и сделать получателем сообщений какой-нибудь другой процесс.

Процесс-получатель называется tracer process, и он может быть только один. По понятным причинам, для него самого трассировку включить нельзя.

erlang:trace_pattern(MFA, MatchSpec, FlagList) -> integer()

http://www.erlang.org/doc/man/erlang.html#trace_pattern-3

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

Для этого нужно вызвать еще и erlang:trace_pattern/3.

И мы будем получать события трассировки, когда заданные в erlang:trace процессы будут вызывать заданные в erlang:trace_pattern функции.

Тут аргументы посложнее :)

Первый аргумент MFA указывает функцию, которую мы хотим трассировать. Это кортеж {Module, Function, Arity}, который однозначно указывает функцию. Но он допускает wildcards, и так может указывать на несколько функций:

  • {Module, Function, '_'} – все функции с таким именем и любым Arity;
  • {Module, '_', '_'} – все функции данного модуля;
  • {'_', '_', '_'} – вообще все функции.

Второй аргумент, MatchSpec, сложнее.

Во-первых, он используется для включения-выключения трассировки (как и в erlang:trace) если задать значения true/false.

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

И, наконец, можно задать собственно match specification, чтобы событие трассировки генерировалось не для любого вызова функции, а в зависимости от аргументов. Подробности ниже.

Третий аргумент, TraceFlags, добавляет еще некоторые опции:

  • global – трассировать только глобальные вызовы;
  • local – трассировать любые вызовы (и глобальные и локальные)
  • call_count – включает счетчик вызовов функции;
  • call_time – добавляет время выполнения функции в событие трассировки.

Глобальный вызов, это вызов экспортированной функции с указанием модуля:
my_module:my_func(Arg).

А вот это локальный вызов:
my_func(Arg).

dbg

Как видно, erlang:trace и erlang:trace_pattern хоть и мощные, но не удобные в использовании. Придется печатать много букв в консоли, чтобы управлять трассировкой с их помощью. Модуль dbg делает такое управление более удобным и лаконичным.

http://www.erlang.org/doc/man/dbg.html

У Цезарини читаем:

Small impact on system performance, making it a suitable candidate for tracing large live systems.

У Хеберта читаем:

Its interface is a bit clunky in terms of usability, but it’s entirely good enough to do what you need. The problem with it is that you have to know what you’re doing, because dbg can log absolutely everything on the node and kill one in under two seconds.

Так что трейсить большие продакшен системы конечно можно, и нужно. Но с осторожностью :)

В документации мы видим целую пачку функций с короткими непонятными названиями: dbg:p/2, dbg:p/3, dbg:tp/2 и т.д. Все они обертки, задающие те или иные аргументы для erlang:trace, erlang:trace_pattern. А короткие они для того, чтобы их быстро набирать в консоли.

Рассмотрим некоторые из них.

dbg:p(PidSpec, FlagLists) -> {ok, MatchDesc} | {error, term()}

PidSpec имеет варианты:

  • Pid процесса в разных формах (собственно Pid, кортеж {N, N, N}, строка "<N.N.N>");
  • имя, под которым процесс зарегистрирован;
  • атомы: existing, new, all;

FlagLists принимает аналогичные значения, как в erlang:trace, но в лаконичном виде:

  • s (send), r (received), m (message = send + receive)
  • p (procs) события spawn, exit, link, unlink, getting_linked, getting_unlinked, register, unregister
  • c (call)

Таким образом вызов:

dbg:p({0.55.0}, m)

аналогичен вызову:

erlang:trace({0.55.0}, [true], [send, 'receive'])

dbg:c(Mod, Fun, Args, FlagList)

Оберкта для erlang:trace_pattern, выполняет:

erlang:trace_pattern({Mod, Fun, Args}, true, FlagList),
apply(Mod, Fun, Args),

То есть, задает trace_pattern для функции, и тут же ее вызывает. Удобный способ, чтобы быстро отладить конкретную функцию.

Причем вызов dbg:c должен идти в паре с вызовом dbg:p, так же, как в паре идут erlang:trace и erlang:trace_pattern

Есть вариант dbg:c(Mod, Fun, Args), без указания FlagList. В этом случае автоматически устанавливаются все флаги.

dbg:tp/2,3,4, dbg:tpl/2,3,4

Тоже обертка для erlang:trace_pattern, в нескольких вариантах. Позволяет задать MatchSpec.

dbg:tp ставит флаг global, и трассирует глобальные вызовы. dbg:tpl ставит флаг local, и трассирует все вызовы.

Аргументы:

dbg:tp(Module, MatchSpec)
// тоже самое, что
erlang:trace_pattern({Module, '_', '_'}, MatchSpec, [])
dbg:tp(Module, Function, MatchSpec)
// тоже самое, что
erlang:trace_pattern({Module, Function, '_'}, MatchSpec, [])
dbg:tp(Module, Function, Arity, MatchSpec)
//тоже самое, что
erlang:trace_pattern({Module, Function, Arity}, MatchSpec, [])

dbg:ctp/0,1,2,3, dbg:ctpg/0,1,2,3, dbg:ctpl/0,1,2,3

Эти функции останавливают трассировку, запущенную предыдущими функциями:

  • dbg:ctpg останавливает, если запущено через dbg:tp
  • dbg:ctpl останавливает, если запущено через dbg:tpl
  • dbg:ctp останавливает, неважно как запущено

Да, с остановкой трассировки намудрили. Мало того, что нужно совпадать по аргументам, так еще нужно помнить, какой функцией трассировка запускалась :)

dbg:stop/0, dbg:stop_clean/0

Вышеуказанные функции останавливают трассировку, но не отменяют установленные флаги.

dbg:stop останавливает все трассировки, сбрасывает все флаги, закрывает порты (если был редирект событий трассировки в порты). Но не сбрасывает MatchSpec. То есть, отменяет erlang:trace но не отменяет erlang:trace_pattern

dbg:stop_clear тоже самое, плюс отменяет erlang:trace_pattern

Перенаправление событий трассировки

По умолчанию события трассировки получает tracer process. Он их форматирует и выводит на консоль. Но их можно перенаправить в кастомную функцию, в файл, или на другую ноду.

В кастомную функцию

dbg:tracer(process , {HandlerFun, Data})

Так можно задать кастомную функцию. Она должна получать 2 аргумента – событие трассировки и аккумулятор. Аргумент Data – начальное значение аккумулятора. Функция возвращает новое значение аккумулятора.

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

В файл

Сперва нужно получить ссылку на port function.

PortFun = dbg:trace_port(file, FileOptions)

FileOptions могут быть разными (см документацию). Например {FileName, wrap, FileSuffix} задает ротацию в файлах, аналогично, как ротируются логи.

Затем вызываем

dbg:tracer(port, PortFun)

На другую ноду

Направить события в порт несколько сложнее. Сперва нужно получить ссылку на port function.

PortFun = dbg:trace_port(ip, Port)

Где Port – это номер порта или кортеж {PortNumber, QueueSize}.

Затем вызываем

dbg:tracer(port, PortFun)

Опция QueueSize позволяет ограничить количество сообщений, которые хранятся в буфере. Это полезно, если клиент не успевает их забирать. Лишние события будут просто игнорироваться.

На другой ноде нужно вызывать

dbg:trace_client(ip, Arg, {HandlerFun, Data})

Где Arg это номер порта или кортеж {HostName, PortNumber}

Такой клиент будет получать события из порта и обрабатывать их кастомной функцией.

Match Specifications

Мощный, но сложный инструмент. Это аргумент для erlang:trace_pattern или dbg:tp, позволяющий трассировать функцию не при каждом ее вызове, а в зависимости от ее аргументов.

Match Specification – это DSL, миниязык внутри Erlang, использующийся в trace_pattern и в ets:select.

http://www.erlang.org/doc/apps/erts/match_spec.html

Сам по себе имеет не очень читаемый синтаксис. К счастью, есть удобная обертка.

dbg:fun2ms(LiteralFun) -> MatchSpec

Так можно написать некий литерал, похожий на локальную функцию, который преобразуется в настоящий MatchSpec.

Например, мы хотим трассировать функцию только если вторым аргументом приходит кортеж, тегированный атомом error. Вот такой: {error, Msg}

Литерал мы напишем так:

fun([_, {error, _}]) -> true end

Из него получим MatchSpec

dbg:fun2ms(fun([_, {error, _}]) -> true end).
[{['_',{error,'_'}],[],[true]}] // Вот как он выглядит :)

И дальше используем его для трассировки:

MatchSpec = dbg:fun2ms(fun([_, {error, _}]) -> true end),
dbg:tp(my_module, my_function, MatchSpec)

То есть, просто матчить входящие аргументы на какие-то конкретные значения не сложно.

Кстати, эти аргументы еще можно ограничивать гардами:

fun([Counter, {error, _}]) when Counter > 10 ->
    true
end

Но MatchSpec умеет больше. В теле LiteralFun можно добавлять специальные конструкции, которые выглядят как вызовы функций. Они будут генерировать дополнительные события.

return_trace()

fun([_, {error, _}]) ->
    return_trace(),
    true
end

Генерирует событие со значением, возвращаемым из трассируемой функции.

exception_trace()

fun([_, {error, _}]) ->
    exception_trace(),
    true
end

Если при выполнении трассируемой функции возникает исключение, генерирует событие, содержащее инфу о нем.

display(Data)

fun([_, {error, Msg}]) ->
    display(Msg),
    true
end

Дает побочный эффект, вывод Msg на консоль.

message(Data)

fun([_, {error, Msg}]) ->
    message(Msg),
    true
end

Генерирует событие, содержащее значение Msg.

caller()

fun([_, {error, _}]) ->
    message(caller()),
    true
end

Позволяет узнать, откуда была вызвана трассируемая функция. Возвращает кортеж {Module, Function, Arity}, который можно передать в событии с помощью message()

process_dump()

fun([_, {error, _}]) ->
    message(process_dump()),
    true
end

Возвращает стэк процесса, форматированный в строку.

self()

fun([_, {error, _}]) ->
    message(self()),
    true
end

Возвращает Pid процесса, в котором выполняется трассируемая функция.

Есть еще несколько таких псевдо-функций, см документацию.

sys

http://www.erlang.org/doc/man/sys.html

Про этот модуль я упоминал раньше, когда рассказывал про gen_server http://yzh44yzh.by/post/gen_server.html#sec-4 Тут кратко повторюсь.

Этот модуль дает дополнительные средства отладки для процессов, которые являются OTP-процессами (запускаются супервизором в рамках OTP-приложения).

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

Вся информация выводится на консоль. Ее можно направить в файл, но не в кастомную функцию, и не в сокет.

recon

У Фреда Хеберта есть проект recon, дающий инструменты для мониторинга и диагностики продакшен нод. Я думаю, мы про этот проект еще поговорим :)

А сейчас только про часть этого проекта – модуль recon_trace.

Это обертка над dbg, дающая некоторые важные фичи. И самая важная среди них – безопасность отладки.

recon_trace ограничивает число обрабатываемых событий трассировки, и позволяет избежать больших нагрузок на io. Можно задавать либо просто лимит получаемых сообщений, либо лимит в единицу времени. tracing process связан с процессом консоли, так что при закрытии консоли трассировка отключается автоматически. То же самое происходит при удаленной отладке при потере связи с нодой.

recon_trace еще больше упрощает интерфейс отладки. Здесь нет необходимости вызвать пару dbg:p / dbp:tpl (erlang:trace / erlang:trace_pattern). Достаточно указать только trace_pattern, и трассировка по умолчанию запускается для всех процессов. Но можно явно указать процессы, если это нужно.

Библиотека концентрируется на отладке функций, и пока не поддерживает отладку сообщений. Второе не так важно для OTP-приложений, где сообщения сводятся к вызовам функций gen_server:call/cast и gen_server:handle_call/handle_cast.

comments powered by Disqus