Elixir by Example

Profiling

Runs on the native BEAM only Download source

Tracing tells you what a process calls. A profiler tells you where the cost goes: how many times each function ran, how long it took, or how much memory it allocated. Erlang/OTP ships :tprof (OTP 27+), which replaces the older :eprof and :cprof with one tool. It measures one of three things:

  • :call_count: calls per function, the cheapest.
  • :call_time: time per function, the usual choice.
  • :call_memory: words allocated per function.

Time changes on every run, so this page uses counts and memory, which don't. The code under test builds a report by appending to a list, a common mistake.

defmodule Report do
  def slow(items), do: Enum.reduce(items, [], fn x, acc -> acc ++ [x * 2] end)

  def fast(items) do
    items
    |> Enum.reduce([], fn x, acc -> [x * 2 | acc] end)
    |> Enum.reverse()
  end
end

:tprof.profile/2 runs a function with profiling on. By default it prints a table that includes pids; report: :return hands back the data instead, so we can print the rows our own way: busiest function last.

profile = fn label, fun ->
  {_result, {:call_memory, rows}} =
    :tprof.profile(fun, %{type: :call_memory, report: :return})

  IO.puts(label)

  rows
  |> Enum.map(fn {mod, fun, arity, per_process} ->
    calls = per_process |> Enum.map(&elem(&1, 1)) |> Enum.sum()
    words = per_process |> Enum.map(&elem(&1, 2)) |> Enum.sum()
    {Exception.format_mfa(mod, fun, arity), calls, words}
  end)
  |> Enum.sort_by(fn {_name, _calls, words} -> words end)
  |> Enum.each(fn {name, calls, words} ->
    IO.puts("  #{String.pad_trailing(name, 36)} calls: #{calls}, words: #{words}")
  end)
end

items = Enum.to_list(1..200)
profile.("slow, 200 items:", fn -> Report.slow(items) end)
slow, 200 items:
  anonymous fn/2 in Report.slow/1      calls: 200, words: 400
  :erlang.++/2                         calls: 200, words: 39800

Almost all the memory goes to ++. Appending copies the whole left-hand list every time, so the 200th call copies 199 elements. Double the input and the cost quadruples: the work is quadratic.

more = Enum.to_list(1..400)
profile.("slow, 400 items:", fn -> Report.slow(more) end)
slow, 400 items:
  anonymous fn/2 in Report.slow/1      calls: 400, words: 800
  :erlang.++/2                         calls: 400, words: 159603

Prepending allocates one list cell (2 words) and copies nothing, and one Enum.reverse/1 at the end puts the order back.

profile.("fast, 200 items:", fn -> Report.fast(items) end)
fast, 200 items:
  Enum.reverse/1                       calls: 1, words: 4
  :lists.reverse/2                     calls: 1, words: 396
  anonymous fn/2 in Report.fast/1      calls: 200, words: 400

In a project you don't need to write any of this: mix profile.tprof -e "Report.slow(Enum.to_list(1..200))" prints the same tables (--type calls|time|memory).

On a live node, the same API takes a running process instead of a function: :tprof.start/0, then :tprof.enable_trace/1 with the pids or :processes, :tprof.set_pattern/3 for the modules, and :tprof.collect/0 after a few seconds.

Pitfall: :call_time and :call_memory slow the profiled code down a lot, and profiling every process makes the whole node slower. On a production node, profile one process or one module, for a few seconds, and start with :call_count.

Pitfall: a profiler shows where one process spends its time. If the node is slow because work waits in a mailbox or a run queue, the profile looks fine. Check message_queue_len and reductions first (see Mailboxes and Schedulers and Reductions).

Pitfall: don't trust a micro-benchmark from a script or iex: code evaluated there isn't compiled the same way as a module. Profile functions in compiled modules, as here, and use a benchmarking library like benchee for timings.

Go deeper: chapter 21 of The BEAM Book by Erik Stenman, "Profiling, Monitoring, and Performance Optimization", compares the profiling tools and what each costs.

Improve this page on GitHub