Database Query Profiler in Phoenix. And a little bit about how stacktrace works in Elixir / Erlang

In our company we use Elixir, the Phoenix and Ecto framework. And recently, at work, I was given the task of making a query profiler in the database to find out the bottlenecks of the system that should be optimized. Thus, the tasks were as follows:

1. Find out which functions are most often used in the database (query calls)
2. Find out which functions create the longest and slowest queries (query time)
3. The results must be accumulated and displayed as a list / graph.

Like everyone else, initially I decided to try the existing solutions. A simple Google search gave me several articles, and some solutions a la:

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

and etc.

A quick inspection immediately made it clear that existing solutions were not suitable. Some do not allow to accumulate results, some generally consider common challenges and it does not matter if the database is there or not, something is paid and also does not have the necessary functionality. After scratching my turnips, I realized that I would have to write my own custom profiler.

Fortunately, Ecto (DSL for working with the database) has the ability to configure the logger and see all the information after executing the request, as follows:

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

This means that we can write our own module with the name EctoProfiler which necessarily has a public log function inside , which takes one argument. And do something interesting inside this function. In particular, to look at the information that this argument contains, but it contains a lot of things and almost everything that we need, but unfortunately does not contain information about where this call came from.

Stacktrace

Then stacktrace enters the scene. You can call and view information about it in elixir in various ways. I will use the method of the Process module:

Process.info(self(), :current_stacktrace)

But, there are some nuances. Take a look at the module below:

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

The question is a million dollars. What do we get at points f and g at startup StacktraceTest.a?

I am sure that not every experienced elixir-ist will answer it correctly.

By running this module, and calling the function, we get the following:

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]}
  ]}}

Above what function f deduced , below - g . Everything seems to be cool, the information is exhaustive, but no. An attentive reader will immediately ask, where are the calls to the functions a , b ?

Here we come to the most interesting.

If function a returns the same value that function b (tail chain) returns , then function a does not get into stacktrace. This is a consequence of the optimization of the last call, the so-called tail recursion in Erlang / Elixir. Each function call in the tail means that the stack frame for the calling function is destroyed. This is the behavior of BEAM (Erlang VM). And it is impossible to change anything here without rewriting the code of the virtual machine. A detailed discussion was here.https://github.com/elixir-lang/elixir/issues/6357

Therefore, the e function also did not fall into stacktrace. rescue/catch- are end calls, but after(in function d ) - not.

Unfortunately, Stacktrace also does not contain arguments called functions. This means that you will not be able to detail information in handle_infoother callbacks regarding messages being called. The reason also lies in the way Erlang works with the stack. Since it is stored for some time, and the arguments can be arbitrarily large, stacktrace in this case would eat up all the memory. This, by the way, is the reason that Erlang plans to redo the processing and storage of the call stack in case of errors (the arguments are saved there). There is a discussion about this .

Someone will ask why I did not use the standard one debugger, which comes out of the box in Erlang and which saves the arguments. I thought about this, but it debuggerdoes not allow stektreys calls to be stored in a variable and then process this data somehow. Only to a file or to the console. Therefore, the decision with him fell away immediately.

So we received a stack trace of calls. All relevant information we have. Time to process it.

Profiler

Using all this information your own profiler was written. I will not provide here a detailed description of his work with code examples. Who cares - can get acquainted with him on github

Here I will only briefly describe the principle of operation:

1. We get information about the request in the database (in particular, the time of the request - query_time), which is transmitted to us by Ecto
2. Retrieving a Stack Trace
3. We leave from the stack trace only those modules that are created inside the application (all modules of dependencies and of Elixir itself are excluded)
4. We save the received data in two Mnesia tables (the data is not saved on disk, but is stored only in memory):
   
   • with a unique view key Module.function/arity
   • with a unique key equal to the received stack trace
5. Both tables contain a key, and attributes: calls- number of requests, query_time- total time of requests. The table with the trace also contains information about the function where a call passed in the first on the stack.
6. Each new call increments the counter callsand query_time.
7. The data is formatted and displayed as a list via the web interface (the interface also contains information about the average query time equal to query_time / calls).

Total

Unfortunately, the solution has drawbacks related to the operation of the stack trace described above. But you can well get information about how your application works and draw conclusions about optimization.

PS As for the plugin itself. I will be happy with any additions and PR. Maybe someone add some goodies and make a nice interface :)