Profiling and Debugging in Elixir - Mariaex

I’m looking for a solid mysql driver for Ecto. Mariaex is the only one, but it is behaving strangely and slowly. I’m documenting this debugging in hopes it is useful for future generations.

The raw results are below and the source code for this is on github.

Repeatedly running the benchmark has the latency pinned at 200 ms. This doesn’t make any sense.

# Ecto with Mariaex
./wrk -c 100 -d 10 -t 20 http://localhost:8800/mariaex
Running 10s test @ http://localhost:8800/ecto
  20 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   200.42ms   20.91ms 223.84ms   97.64%
    Req/Sec    24.78      9.38    80.00     69.58%
  4950 requests in 10.04s, 1.05MB read
Requests/sec:    493.13
Transfer/sec:    106.91KB

Setting up a profiler with ExProf:

defmodule MariaProfile  do
  import ExProf.Macro

  @doc "analyze with profile macro"
  def do_analyze do
    c=[ hostname: "10.0.3.82", database: "test", username: "test", password: "test" ]
    {:ok, p} = Mariaex.Connection.start_link(c)
    profile do
      Mariaex.Connection.query(p, "SELECT id, name FROM domains")
    end
  end

  @doc "get analysis records and sum them up"
  def run do
    records = do_analyze
    total_percent = Enum.reduce(records, 0.0, &(&1.percent + &2))
    IO.inspect "total = #{total_percent}"
  end
end

And the results of MariaProfile.run:

FUNCTION                                        CALLS      %  TIME  [uS / CALLS]
--------                                        -----    ---  ----  [----------]
# skipping output 
lists:reverse/1                                     1   3.77     4  [      4.00]
erlang:monitor/2                                    1   3.77     4  [      4.00]
code_server:call/2                                  1   7.55     8  [      8.00]
'Elixir.String.Unicode':do_rstrip/3                29   9.43    10  [      0.34]
'Elixir.MariaProfile':'-do_analyze/0-fun-0-'/1      1   8.64     7  [      7.00]
erlang:send/3                                       1  18.87    20  [     20.00]

Something doesn’t add up here. Setting up a trace to on just what the Mariaex.Connection.query is doing:

iex(14)> :dbg.tracer
{:ok, #PID<0.1460.0>}
iex(15)> c=[ hostname: "10.0.3.82", database: "test", username: "test", password: "test" ]
[hostname: "10.0.3.82", database: "test", username: "test", password: "test"]
iex(16)> {:ok, p} = Mariaex.Connection.start_link(c)
{:ok, #PID<0.1464.0>}
iex(17)> :dbg.p(p) 
{:ok, [{:matched, :nonode@nohost, 1}]}

And the result:

iex(19)> Mariaex.Connection.query(p,"select id from domains limit 1");
(<0.1464.0>) << {'$gen_call',{<0.498.0>,#Ref<0.0.1.129562>},
                             {query,<<"select id from domains limit 1">>,[],
                                    []}}
(<0.1464.0>) << {inet_reply,#Port<0.12988>,ok}
(<0.1464.0>) << {tcp,#Port<0.12988>,
                     <<12,0,0,1,0,2,0,0,0,1,0,0,0,0,0,0,44,0,0,2,3,100,101,
                       102,4,116,101,115,116,7,100,111,109,97,105,110,115,7,
                       100,111,109,97,105,110,115,2,105,100,2,105,100,12,63,0,
                       20,0,0,0,8,39,66,0,0,0,5,0,0,3,254,0,0,2,0>>}
(<0.1464.0>) << {inet_reply,#Port<0.12988>,ok}
(<0.1464.0>) << {tcp,#Port<0.12988>,
                     <<1,0,0,1,1,44,0,0,2,3,100,101,102,4,116,101,115,116,7,
                       100,111,109,97,105,110,115,7,100,111,109,97,105,110,
                       115,2,105,100,2,105,100,12,63,0,20,0,0,0,8,39,66,0,0,0,
                       5,0,0,3,254,0,0,34,0,10,0,0,4,0,0,1,0,0,0,0,0,0,0,5,0,
                       0,5,254,0,0,34,0>>}
(<0.1464.0>) <0.498.0> ! {#Ref<0.0.1.129562>,
                          {ok,#{'__struct__' => 'Elixir.Mariaex.Result',
                                columns => [<<"id">>],
                                command => select,
                                last_insert_id => nil,
                                num_rows => 1,
                                rows => [{1}]}}}
(<0.1464.0>) << {inet_reply,#Port<0.12988>,ok}
{:ok,
 %Mariaex.Result{columns: ["id"], command: :select, last_insert_id: nil,
  num_rows: 1, rows: [{1}]}}

We would have to dig a bit deeper, perhaps by setting up traces to see what’s happenning, but I just can’t go down that rabbit hole.