Profiling process and all calls happening in it

[hauleth]

I am working on profiling Ranch protocol handler which is implemented as gen_statem. Currently I am tracing all handle_event/4 function calls, but that results in a lot of separate traces and it is hard to see overall picture. Would it be possible to trace single process (ideally running it from source code)? It would make profiling such code way easier than current workaround (I have tried monitoring enter_loop which I use, but that never produced any output).

[Stratus3D]

So you want a limited number of call traces, but only for a specific pid?

[hauleth]

I want to listen for all calls within given PID. Alternatively (in this particular case) if there would be a possibility for time limit (like in #48) then I could listen on enter_loop (which never exits) and then limit it by elapsed time.

[ruslandoga]

👋

This doesn't produce a flamegraph / flamechart (yet), but I wonder if something like this could work

Ranch handler with a Telemetry span

defmodule Echo do
  @behaviour :ranch_protocol

  def child_spec(opts) do
    :ranch.child_spec(__MODULE__, :ranch_tcp, opts, __MODULE__, [])
  end

  def start_link(ref, transport, opts) do
    {:ok, :proc_lib.spawn_link(__MODULE__, :init, [ref, transport, opts])}
  end

  def init(ref, transport, _opts) do
    {:ok, socket} = :ranch.handshake(ref)
    loop(socket, transport)
  end

  defp loop(socket, transport) do
    case transport.recv(socket, 0, :infinity) do
      {:ok, data} ->
        :telemetry.span([:ranch, :handler], %{}, fn ->
          _work = Enum.each(1..100, fn _ -> String.codepoints(data) end)
          {transport.send(socket, data), %{}}
        end)

        loop(socket, transport)

      _ ->
        transport.close(socket)
    end
  end
end

Naive tprof wrapper

defmodule Flame do
  def trace_span(event) do
    ref = make_ref()
    counter = :atomics.new(1, signed: false)
    caller = self()

    config = %{ref: ref, counter: counter, caller: caller}

    :telemetry.attach("flamegraph-on", event ++ [:start], &Flame.handle_start/4, config)

    :telemetry.attach_many(
      "flamegraph-off",
      [event ++ [:stop], event ++ [:exception]],
      &Flame.handle_stop/4,
      config
    )

    receive do
      {^ref, :done} ->
        :telemetry.detach("flamegraph-on")
        :telemetry.detach("flamegraph-off")
        :done
    end
  end

  def handle_start(_event, _measurements, _metadata, config) do
    if :atomics.add_get(config.counter, 1, 1) == 1 do
      :tprof.enable_trace(self())
      :tprof.set_pattern(:_, :_, :_)
    end
  end

  def handle_stop(_event, _measurement, _metadata, config) do
    :tprof.disable_trace(self())
    :tprof.format(:tprof.inspect(:tprof.collect()))
    send(config.caller, {config.ref, :done})
  end
end

In IEx:

iex> :tprof.start(%{type: :call_time})
iex> {:ok, client} = :gen_tcp.connect({127, 0, 0, 1}, 5555, [:binary, active: false])
iex> spawn(fn -> Flame.trace_span([:ranch, :handler]) end)
iex> :gen_tcp.send(client, String.duplicate("a", 100))
iex> :tprof.stop()

Output

****** Process <0.230.0>  --  100.00% of total ***
FUNCTION                                  CALLS  TIME (μs)  PER CALL  [    %]
'Elixir.Enum':each/2                          1          0      0.00  [ 0.00]
gen:call/4                                    1          0      0.00  [ 0.00]
gen:do_for_proc/2                             1          0      0.00  [ 0.00]
gen:'-call/4-fun-0-'/4                        1          0      0.00  [ 0.00]
erlang:monotonic_time/0                       1          0      0.00  [ 0.00]
erlang:whereis/1                              1          0      0.00  [ 0.00]
erlang:port_command/3                         1          0      0.00  [ 0.00]
erlang:'++'/2                                 1          0      0.00  [ 0.00]
gen_tcp:send/2                                1          0      0.00  [ 0.00]
ranch_tcp:send/2                              1          0      0.00  [ 0.00]
tprof:collect/0                               1          0      0.00  [ 0.00]
tprof:collect/1                               1          0      0.00  [ 0.00]
lists:foreach/2                               1          0      0.00  [ 0.00]
inet_db:lookup_socket/1                       1          0      0.00  [ 0.00]
gen_server:call/3                             1          0      0.00  [ 0.00]
inet_tcp:send/2                               1          0      0.00  [ 0.00]
'Elixir.Flame':handle_stop/4                  1          0      0.00  [ 0.00]
telemetry:execute/3                           1          0      0.00  [ 0.00]
telemetry:merge_ctx/2                         1          0      0.00  [ 0.00]
telemetry:'-execute/3-fun-0-'/4               1          0      0.00  [ 0.00]
gen:do_call/4                                 1          1      1.00  [ 0.07]
erlang:port_get_data/1                        1          1      1.00  [ 0.07]
telemetry_handler_table:list_for_event/1      1          1      1.00  [ 0.07]
lists:foreach_1/2                             2          1      0.50  [ 0.07]
prim_inet:send/4                              1          1      1.00  [ 0.07]
erlang:monitor/2                              2          2      1.00  [ 0.13]
prim_inet:send/3                              1          2      2.00  [ 0.13]
ets:lookup/2                                  1          4      4.00  [ 0.26]
erlang:demonitor/2                            2          5      2.50  [ 0.33]
erlang:term_to_binary/2                       1          5      5.00  [ 0.33]
'Elixir.String':codepoints/1                100          6      0.06  [ 0.39]
'Elixir.Flame.Echo':'-loop/2-fun-0-'/2      100          6      0.06  [ 0.39]
'Elixir.Enum':'-each/2-fun-0-'/3            100         14      0.14  [ 0.91]
'Elixir.Enum':reduce_range/5                 51         19      0.37  [ 1.24]
'Elixir.Flame.Echo':'-loop/2-fun-1-'/3        1         57     57.00  [ 3.71]
erts_internal:port_command/3                  1         79     79.00  [ 5.14]
'Elixir.String':do_codepoints/1           10100       1334      0.13  [86.74]

I think it might be possible to turn tprof output into at least something resembling flamegraphs. Inspired by #50