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

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

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

Like everything, I initially decided to try existing solutions. A simple Google search gave me a few 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 are not suitable. Some do not allow to accumulate results, some even consider general calls and no matter whether the database is there or not, something is paid and also does not have the necessary functionality. Having scratched a turnip, I realized that I would have to write my own personal profiler.

Fortunately, Ecto (DSL for working with the database) has the ability to configure the logger and see all the information after the execution of 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 that takes one argument. And do something interesting inside this function. In particular, look at the information that this argument contains, and it contains a lot of things and almost everything we need, but unfortunately does not contain information about where the call came from.

Stacktrace

This is where stacktrace comes on the scene. You can call and view information about it in elixir in various ways. I will use the Process module method:

 Process.info(self(), :current_stacktrace) 

But, there are some nuances. See 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 when running StacktraceTest.a ?

I'm sure not every experienced elixir-ist will correctly answer it.

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 is what the function f produced , below - g . It seems everything is cool, the information is exhaustive, but no. Attentive reader, immediately ask, but where are the function calls 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 fall 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 behavior is BEAM (Erlang VM). And it is impossible to change anything here without rewriting the virtual machine code. A detailed discussion was here https://github.com/elixir-lang/elixir/issues/6357

Therefore, the function e is also not included in stacktrace. rescue/catch are end calls, but after (in the d function) is not.

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

Someone will ask why I did not use the standard debugger that comes out of the box in Erlang and which saves the arguments. I thought about it, but debugger does not allow saving the call frame in a variable and then processing this data in any way. Only in the file or in the console. Therefore, the decision with him disappeared immediately.

So we received a call frame. All the relevant information we have. Time to process it.

Profiler

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

Here I will only briefly describe the principle of operation:

1. We receive information about the query in the database (in particular, the query time - query_time ), which is transmitted to us by Ecto
2. We retrieve the call frame
3. We leave only those modules created within the application from the stektrais (all dependency modules and Elixir itself are excluded)
4. We save the data in two tables Mnesia (data is not stored on disk, but stored only in memory):
   
   • with a unique key of the form Module.function/arity
   • with a unique key equal to the resulting frame rate
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 the call came first in the stack.
6. Each new call increments the counter calls and query_time .
7. The data is formatted and output as a list via the web interface (the interface also added information about the average query time equal to query_time / calls).

Total

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

PS As for the plugin itself. I will be glad to any additions and PR. Maybe someone add buns and make a beautiful interface :)