В нашей компании мы используем Elixir, фреймворк Phoenix и Ecto. И недавно на работе мне поставили задачу, сделать профилировщик запросов в БД, чтобы выяснить узкие точки системы, которые следует оптимизировать. Таким образом задачи были следущие:

Выяснить, какие функции чаще всего обращаются в базу (query calls)
Выяснить какие функции создают самые долгие и медленные запросв (query time)
Результаты необходимо аккумулировать и выводить в виде списка/графика.

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

https://github.com/parroty/exprof
http://erlang.org/doc/man/fprof.html
https://github.com/proger/eflame
https://github.com/TheRealReal/new-relixir

и др.

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

К счастью, у Ecto (DSL для работы с базой) есть возможность конфигурировать логгер и посмотреть всю информацию после выполнение запроса, следующим образом:

config :my_greap_app, MyGreatApp.Repo,
  loggers: [{EctoProfiler, :log, []}]

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

StackTrace

Тут на сцену и выходит stacktrace. Вызвать и посмотреть информацию о нем в elixir можно различными способами. Я буду использовать метод модуля Process:

Process.info(self(), :current_stacktrace)

Но, здесь есть некоторые нюансы. Посмотрите на модуль ниже:


defmodule StacktraceTest do
  @moduledoc false

  def a do
    b()
  end

  def b do
    fn -> c() end.()
  end

  def c do
    {:ok, d()}
  end

  def d do
    e()
  after
    {:ok, f()}
  end

  def e do
    raise "fail"
  rescue
    _ -> g()
  end

  def f do
    IO.inspect Process.info(self(), :current_stacktrace)
  end

  def g do
    Process.info(self(), :current_stacktrace)
  end
end

Вопрос миллион долларов. Что мы получим в точках f и g при запуске StacktraceTest.a ?

Уверен, не каждый опытный elixir-ист правильно на него ответит.

Запустив данный модуль, и вызвав функцию мы получим следующее:

iex(2)>{:current_stacktrace,
 [
   {Process, :info, 2, [file: 'lib/process.ex', line: 646]},
   {StacktraceTest, :f, 0, [file: 'iex', line: 29]},
   {StacktraceTest, :"-d/0-after$^0/0-0-", 0, [file: 'iex', line: 19]},
   {StacktraceTest, :d, 0, [file: 'iex', line: 16]},
   {StacktraceTest, :c, 0, [file: 'iex', line: 13]},
   {:erl_eval, :do_apply, 6, [file: 'erl_eval.erl', line: 670]},
   {:elixir, :eval_forms, 4, [file: 'src/elixir.erl', line: 233]}
 ]}
{:ok,
 {:current_stacktrace,
  [
    {Process, :info, 2, [file: 'lib/process.ex', line: 646]},
    {StacktraceTest, :d, 0, [file: 'iex', line: 17]},
    {StacktraceTest, :c, 0, [file: 'iex', line: 13]},
    {:erl_eval, :do_apply, 6, [file: 'erl_eval.erl', line: 670]},
    {:elixir, :eval_forms, 4, [file: 'src/elixir.erl', line: 233]},
    {IEx.Evaluator, :handle_eval, 5, [file: 'lib/iex/evaluator.ex', line: 245]},
    {IEx.Evaluator, :do_eval, 3, [file: 'lib/iex/evaluator.ex', line: 225]}
  ]}}

Выше то, что вывела функция f, ниже — g. Вроде все круто, информация исчерпывающая, но нет. Внимательный читатель, сразу спросит, а где вызовы функций a, b ?

Вот тут мы и подходим к самому интересному.

Если функция a возвращает то же значение, которое возвращает функция b (tail chain), то функция a в stacktrace не попадает. Это следствие оптимизации последнего вызова, так называемая хвостовая рекурсия в Erlang/Elixir. Каждый вызов функции в хвосте означает, что кадр стека для вызывающей функции уничтожен. Это поведение BEAM (Erlang VM). И изменить здесь что-либо невозможно, не переписав код виртуальной машины. Подробное обсуждение было здесь https://github.com/elixir-lang/elixir/issues/6357

Поэтому функция e, также не попала в stacktrace. rescue/catch — являются концевыми вызовами, а вот after (в функции d) — нет.

К сожалению, Stacktrace также не содержит аргументов, вызываемых функций. Это значит, что вы не сможете детализировать информацию в handle_info и других коллбеках, касаемо вызываемых сообщений. Причина также кроется в том, как Erlang работает со стеком. Так как он хранится некоторое время, а аргументы могут быть сколь угодно большими, stacktrace в этом случае, сьедал бы всю память. Это кстати причина того, что Erlang планирует переделать обработку и хранение стека вызовов в случае ошибок (там как раз сохраняются аргументы). По этому поводу есть обсуждение.

Кто-то спросит, почему же я не использовал стадартный debugger, который идет из коробки в Erlang и который сохраняет аргументы. Я думал об этом, но debugger не позволяет сохранить стектрейс вызовов в переменной и затем как-либо обработать эти данные. Только в файл или в консоль. Поэтому решение с ним отпало сразу.

Итак стектрейс вызовов мы получили. Вся сопуствующая информация у нас есть. Время обработать ее.

Профилировщик

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

Здесь я лишь вкратце опишу принцип работы:

Мы получаем информацию о запросе в БД (в частности время запроса — query_time), которую передает нам Ecto
Извлекаем стектрейс вызовов
Оставляем из стектрейса только те модули, которые созданы внутри приложения (исключаются все модули зависимостей и самого Elixir)
Сохраняем полученные данные в двух таблицах Mnesia (данные не сохраняются на диске, а хранятся только в памяти):
- c уникальным ключом вида Module.function/arity
- с уникальным ключом равный полученному стектрейсу
Обе таблицы содержат ключ, и аттрибуты: calls — кол-во запросов, query_time — суммарное время запросов. Таблица с трейсом, также содержит информацию о функции где в первой по стеку прозошел вызов.
Каждый новый вызов инкрементирует счетчик callsи query_time.
Данные форматируются и выводятся в виде списка через web-интерфейс (в интерфейсе также добавлена информация о среднем времени запроса равным query_time/calls).

Итого

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

P.S. Что касается самого плагина. Я буду рад любым дополнениям и PR. Возможно кто-то добавить плюшек и сделать красивый интерфейс :)

Профилировщик запросов в БД в Phoenix. И немножко о том как работает stacktrace в Elixir/Erlang