Using Profiling in Elixir to Improve Performance
Tags: elixir
Published: 2022-05-03 10:52:22

Elixir is all about performance. Say you have an app up and running with Elixir, but some parts aren't working as fast as you would like them to.

That is where profiling comes in.

Profiling tools usually walk you through the frequency and duration of function calls and where they spend their time.
Erlang has impressive profile tooling available at its disposal.

In this post, we will look into three profiling tools in Elixir: `cprof`, `eprof`, and `fprof`.

## Do I Need Profiling for My Elixir App?

Firstly, I want to clarify that you may not need profiling at all. As Donald Knuth wrote: _'premature optimization is the root of all evil.'_ Some operations just cannot be optimized.

For example, say you want to fetch something from your database. You issue a query and get a reply. This incurs a network round trip with some data. If you need all the data, the network round trip time cannot be optimized without moving your database closer to the app.

With that out of the way, let's jump into profiling options.

## Profiling with `cprof` in Elixir

`cprof` counts the number of times each function is invoked.
It doesn't profile the time spent in those functions, so it comes with the least amount of overhead.

Use it when you already have an estimate of your functions' runtimes. You'll see the frequency with which each function is invoked.

Let's see how we can profile a Fibonacci number generator with `cprof`.

You can [follow along with the code](https://gist.github.com/pulkit110/c8223b7ebf4dc6cb918f440c45e201cd). It uses the [Rosetta Code algorithm for Fibonacci sequence generation](https://rosettacode.org/wiki/Fibonacci_sequence#Elixir).

Jump into an IEx session and run `cprof` like this:

```elixir
iex(15)> :cprof.start()
19244
iex(16)> FibonacciRosettaCode.list(10)
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55]
iex(17)> :cprof.analyse(FibonacciRosettaCode)
{FibonacciRosettaCode, 79,
 [
   {{FibonacciRosettaCode, :fibonacci, 3}, 54},
   {{FibonacciRosettaCode, :fibonacci, 1}, 11},
   {{FibonacciRosettaCode, :"-fun.fibonacci/1-", 1}, 11},
   {{FibonacciRosettaCode, :module_info, 1}, 1},
   {{FibonacciRosettaCode, :list, 1}, 1},
   {{FibonacciRosettaCode, :__info__, 1}, 1}
 ]}
iex(18)> :cprof.stop()
19266
```

First, start `cprof`, run the code that you want to profile, and then call `:cprof.analyse/1` to fetch the statistics for the given module. Several other options are available inside the [`:cprof` module](https://www.erlang.org/doc/man/cprof.html), like pausing profiling with `:cprof.pause/0`.

We can also use Mix's wrapper task [profile.cprof](https://hexdocs.pm/mix/1.12/Mix.Tasks.Profile.Cprof.html) directly.

```sh
➜ mix profile.cprof -e "FibonacciRosettaCode.list(10)"
                                                                     CNT
Total                                                                113
FibonacciRosettaCode                                                  77  <--
  FibonacciRosettaCode.fibonacci/3                                    54
  FibonacciRosettaCode.fibonacci/1                                    11
  FibonacciRosettaCode."-fun.fibonacci/1-"/1                          11
  FibonacciRosettaCode.list/1                                          1
Enum                                                                  24  <--
  Enum.reduce_range/5                                                 12
  anonymous fn/3 in Enum.map/2                                        11
  Enum.map/2                                                           1
  ...
```

Here, we can see that the function `fibonacci/3` is called the most.

So, if we can somehow decrease the number of calls to that function or optimize the code inside it, we could improve performance.

## `eprof` Profiling in Elixir

`cprof` measures _counts_ while `eprof` measures the _execution time_ (in addition to counts) spent inside each function.
It has slightly more overhead than `cprof`. Use `eprof` when you want to find the most time-consuming functions.

The usage is very similar to `cprof`. You just need to `start` the profiler, run the code you want to profile, and then call `analyze` to fetch the results.

Let's analyze the results from the mix task [`profile.eprof`](https://hexdocs.pm/mix/1.12/Mix.Tasks.Profile.Eprof.html) on our sample Fibonacci generator.

```sh
➜ mix profile.eprof -e "FibonacciRosettaCode.list(10)"
#                                               CALLS     % TIME µS/CALL
Total                                             106 100.0   45    0.42
anonymous fn/0 in :elixir_compiler_1.__FILE__/1     1  0.00    0    0.00
:lists.reverse/1                                    1  2.22    1    1.00
:lists.reverse/2                                    1  2.22    1    1.00
FibonacciRosettaCode.fibonacci/1                   11  4.44    2    0.18
Enum.map/2                                          1  4.44    2    2.00
Range.new/2                                         1  4.44    2    2.00
FibonacciRosettaCode."-fun.fibonacci/1-"/1         11  8.89    4    0.36
FibonacciRosettaCode.list/1                         1  8.89    4    4.00
:erlang.apply/2                                     1  8.89    4    4.00
anonymous fn/3 in Enum.map/2                       11 13.33    6    0.55
Enum.reduce_range/5                                12 13.33    6    0.50
FibonacciRosettaCode.fibonacci/3                   54 28.89   13    0.24
```

Here, we can see that `fibonacci/3` is again the most time-consuming part of our program, consuming 28.89% of the total execution time and 0.24µS per call.

In addition, `eprof` also allows us to profile function calls across different processes.

The usage is very simple. Let's see an example:

```elixir
:eprof.start_profiling([self()])

# Do some work
1..100 |> Enum.each(fn i ->
  spawn(fn -> FibonacciRosettaCode.list(i + 1) end)
end)

:eprof.stop_profiling()
:eprof.analyze()
```

You need to call `start_profiling/1` with a list of processes to profile.

By default, this also tracks any other processes started from a profiled process.

When you are done, call `stop_profiling` and run `analyze` to get the results. They should look something like this, with an entry for each process and the percentage of time it was busy:

```sh
****** Process <0.150.0>    -- 37.26 % of profiled time ***
FUNCTION                                                             CALLS        %   TIME  [uS / CALLS]
--------                                                             -----  -------   ----  [----------]
io:request/2                                                             3     0.00      0  [      0.00]
...

****** Process <0.277.0>    -- 0.05 % of profiled time ***
FUNCTION                                             CALLS        %  TIME  [uS / CALLS]
--------                                             -----  -------  ----  [----------]
'Elixir.FibonacciRosettaCode':fibonacci/3                2     0.00     0  [      0.00]
'Elixir.FibonacciRosettaCode':fibonacci/1                3     3.03     1  [      0.33]
'Elixir.FibonacciRosettaCode':'-fun.fibonacci/1-'/1      3     3.03     1  [      0.33]
...
```

The great thing about this is that you can run it in production systems by accessing the remote console. Just call `start_profiling/1`, wait some time to process the requests or manually trigger some requests that you want to profile. Then call `stop_profiling` followed by `analyze` to get the results.

## Using `fprof` in Elixir

The final inbuilt tool that you can use to profile your applications is `fprof`. It is a comprehensive profiling tool that generates a trace file containing timestamped entries for function calls, process-related events, and garbage collection data.

You can then feed this trace file into other tools to visualize the results thoroughly or use `:fprof.analyse` like above to fetch function counts and execution times.

Running `fprof` through IEx is quite advanced compared to running `cprof` and `eprof`, but `fprof` allows tracing multiple processes.

Here is how you can generate a trace file for all processes:

```elixir
:fprof.start()
:fprof.trace([:start, procs: :all])

# Do some work
1..100 |> Enum.each(fn i ->
  spawn(fn -> FibonacciRosettaCode.list(i + 1) end)
end)

:fprof.trace(:stop)
:fprof.profile()
:fprof.analyse(totals: false, dest: 'prof.analysis')
```

This generates a comprehensive trace of everything that went on during the run with:

- `CNT` - the number of times a function is called
- `ACC` - the accumulated time spent in the function, including other function calls
- `OWN` - the time the function spent to be executed

[Here's the full file (50 MB)](https://gist.github.com/pulkit110/10ad017e52ad25c6b0ad36199544fd8f), if you are interested.

Like `eprof`, `fprof` is a great tool for profiling applications in production directly. Note that this will significantly slow down the application, so be prepared for degraded performance during profiling and a huge trace file.

So you have the data now. If you are feeling adventurous, you can start digging through the file and look for patterns.

Or, you can use some tools to help visualize your data.
A popular one is [`erlgrind`](https://github.com/isacssouza/erlgrind). It converts the `fprof` file to `cgrind` format that you can open inside [`KCachegrind`](https://kcachegrind.github.io/html/Home.html).

To convert the file, download `erlgrind` and then run `src/erlgrind profile.fprof`.

This will generate a `prof.cgrind` file that you can open to see graphs like this:

![qcachegrind graph](https://blog.appsignal.com/images/blog/2022-04/cgrind.png)

## Profile and Collect Metrics from Your Elixir App in Production

`eprof` and `fprof` can assist with profiling your application in production, but there are a couple of additional tools worth mentioning — Phoenix Live Dashboard and AppSignal.

### Phoenix Live Dashboard

[Phoenix's live dashboard](https://github.com/phoenixframework/phoenix_live_dashboard) can provide a great, quick overview of metrics. While not exactly a profiler, it shows OS data and metrics from telemetry events and processes, among other things.

Here is an example of the dashboard in action:

![Phoenix Live Dashboard Screenshot](https://blog.appsignal.com/images/blog/2022-04/phoenix-live-dashboard.png)

### AppSignal

[AppSignal](https://appsignal.com/) is another great tool for collecting performance data (among other things). [Adding AppSignal to an existing application](https://docs.appsignal.com/elixir/installation/#installing-the-package) takes a few seconds.

Just install the `appsignal` dependency and run the `appsignal.install` mix task with an API key. It has a good set of default metric collection including the throughput and response times for the application. You could even set up [minutely probes](https://docs.appsignal.com/elixir/instrumentation/minutely-probes.html) to track custom metrics.

Here's an example of the AppSignal dashboard collecting data from a sample application:

![AppSignal Screenshot](https://blog.appsignal.com/images/blog/2022-04/appsignal.png)

If you are looking to collect data about specific blocks of code that you suspect are slow, AppSignal's instrumentation feature can help collect this data. Just wrap the suspected code inside `Appsignal.instrument/2`, like this:

```elixir
defmodule MyApp.PageController do
  use MyApp, :controller

  def index(conn, _params) do
    custom_function()
    render(conn, "index.html")
  end

  defp custom_function do
    Appsignal.instrument("custom_function", fn ->
      :timer.sleep(1000)
    end)
  end
end
```

This will show up on the AppSignal event graph tagged as `custom_function`. You can then explore this event across multiple calls and make an informed decision about the need for optimization.

Check out the full list of features in [the AppSignal docs](https://docs.appsignal.com/elixir/).

## Wrap-up: Measure Your Elixir App's Performance with Profiling

In this post, we saw how inbuilt tools like `cprof`, `eprof`, and `fprof` can help gather performance insights for your code, even during production.

We also took a quick look at a couple of other tools to monitor and trace your applications: Phoenix Live Dashboard and AppSignal.

Until next time, happy profiling!

**P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, [subscribe to our Elixir Alchemy newsletter and never miss a single post](/elixir-alchemy)!**