How To Reduce Reductions in Elixir
Tags: elixir, apm
Published: 2023-10-05 10:47:17

In this article, we'll show how you can use Elixir's `profile.eprof` mix task to evaluate and improve code performance in your Elixir application. You'll see how we used the profiling mix task to lower reductions in our `instrument/3` function and [custom instrumentation](https://docs.appsignal.com/elixir/instrumentation/instrumentation.html) functionality, both key parts of our Elixir integration.

## Our Key Components

Before we explain how we used Elixir's `profile.eprof` mix task to improve our `instrument` function's performance, let's take a moment to understand what `profile.eprof` does.

### Elixir's `profile.eprof` Mix Task

Elixir's `profile.eprof` mix task evaluates a piece of code with the [eprof](https://www.erlang.org/doc/man/eprof.html) profiling tool enabled. When the code runs, it outputs a time profile report, which shows the number of calls to each function and the amount of time spent in each function.

### AppSignal's `instrument` Function

In its most basic form, the `instrument/3` function wraps a piece of code to gain performance insights:

```elixir
Appsignal.instrument("slow", fn ->
  :timer.sleep(1000)
end)
```

The example above creates a new trace (named "slow" when there's no current trace) or a child span in a trace that's already running.

With AppSignal, we can save and query our application's performance samples to quickly find similar samples or retrieve older samples when debugging issues.

## Profiling our `instrument` Function

To look into the `Appsignal.Instrumentation.instrument/3` function, we evaluated the following code snippet through the `eprof` task:

```shell
mix profile.eprof -e "(1..1_000) |> Enum.each(fn _ -> Appsignal.Instrumentation.instrument(\"name\", \"category\", fn -> :ok end) end)"
```

For convenience, this is a formatted version of the executed code, which calls the `instrument/3` function a thousand times to eliminate any outliers and gauge the average performance of functions called by the instrument function:

```elixir
(1..1_000)
|> Enum.each(fn _ ->
  Appsignal.Instrumentation.instrument(\"name\", \"category\", fn -> :ok end)
end)
```

## Interpreting Profiling Data

Running the profiler produced the following report:

```bash
# This report sample has been redacted for brevity

Profile results of #PID<0.315.0>
#                                                        CALLS     %  TIME µS/CALL
Total                                                    11701 100.0 53586    0.46
:application.get_env/2                                    4000  0.90   484    0.12
:ets.lookup/2                                             6000  7.62  4083    0.68
Appsignal.Nif._create_root_span/1                         1000 13.82  7404    7.40
Appsignal.Nif._close_span/1                               1000 29.76 15947   15.95
```

The report shows all function calls executed as a result of calling `instrument/3`, with the rightmost column showing the time per call in microseconds.

We then interpreted the profiling data for our `instrument` function to understand how our function performed and find places in our code to reduce the number of functions called by our `instrument` function.

## Looking for Reductions

Looking back at our report, we can see that the `Appsignal.Nif._close_span/1` and `Appsignal.Nif._create_root_span/1` functions took the most time, at roughly 16 and 7 microseconds per call, respectively.

Both functions were called 1,000 times, which made sense because that equated to the number of started and stopped spans. Although some performance gains might be had here, we skipped these function calls, as they were called a reasonable amount of times.

One place above these is `:ets.lookup/2`, which only took 0.68 microseconds per call, but was called 6,000 times, or $6n$ (where $n$ is the number of calls to the `instrument/3` function).

```elixir
  def instrument(name, category, fun) do
    instrument(fn span ->
      _ =
        span
        |> @span.set_name(name)
        |> @span.set_attribute("appsignal:category", category)

      call_with_optional_argument(fun, span)
    end)
  end
```

Investigating the `instrument/3` function revealed that the `Span.set_name/1` function called `:ets.lookup/2` twice.

### Reducing Calls

Although AppSignal uses [ets](https://www.erlang.org/doc/man/ets.html) internally to store the currently open spans, from checking the configuration, it turned out that the lookups in the `set_name/1` function actually happened.

Internally, the integration checked to see if `set_name/1` was active before calling `Span.set_name/2`, the function used to set the span name.

```elixir
def set_name(%Span{reference: reference} = span, name)
    when is_reference(reference) and is_binary(name) do
  if Config.active?() do
    :ok = @nif.set_span_name(reference, name)
    span
  end
end
```

However, this call wasn't needed, as calling this function with a `nil` value instead of a span is a no-op. When the integration isn't active, nils are passed around instead of spans so this extra check could be safely removed.

After making these changes to our code and re-running our profiler, we saw a reduction in the number of calls by $2n$, leaving $4n$ calls to the `:ets.lookup/2` function:

```
:ets.lookup/2                                             4000  5.06  2458    0.61
Appsignal.Nif._create_root_span/1                         1000 16.30  7922    7.92
Appsignal.Nif._close_span/1                               1000 32.91 16001   16.00
```

Another lookup was caused by a duplicate call to `Application.get_env/1`. Since the application environment is stored in ets as well, each `get_env/1` call also does a lookup.

Previously, the environment was checked twice, in both the `active?/0` and `valid?/0` functions. If either of these is false, the integration is disabled. The implementation looked like this:

```elixir
  def active? do
    :appsignal
    |> Application.get_env(:config, @default_config)
    |> do_active?
  end

  defp do_active?(%{active: true}), do: valid?()
  defp do_active?(_), do: false
  def valid? do
    do_valid?(Application.get_env(:appsignal, :config)[:push_api_key])
  end

  defp do_valid?(push_api_key) when is_binary(push_api_key) do
    !empty?(String.trim(push_api_key))
  end

  defp do_valid?(_push_api_key), do: false
```

Exposing `valid?/1` (which takes a configuration and only tests if the push API key is present) saved a call to `Application.get_env/2`, which internally called another ets lookup:

```elixir
  def active? do
    :appsignal
    |> Application.get_env(:config, @default_config)
    |> active?
  end

  defp active?(%{active: true} = config) do
    valid?(config)
  end

  defp active?(_config), do: false

  def valid? do
    :appsignal
    |> Application.get_env(:config)
    |> valid?
  end

  defp valid?(%{push_api_key: key}) when is_binary(key) do
    !(key
      |> String.trim()
      |> empty?())
  end

  defp valid?(_config), do: false
```

Having re-run the profiler, we saw the number of calls to `:ets.lookup/2` was $3n$:

```
:erlang.whereis/1                                         4000  1.88   757    0.19
Appsignal.Nif._set_span_attribute_string/3                1000  1.90   766    0.77
Appsignal.Tracer.create_span/3                            1000  2.02   813    0.81
Process.whereis/1                                         4000  2.17   875    0.22
Appsignal.Tracer.running?/0                               4000  2.30   926    0.23
:ets.lookup/2                                             3001  3.91  1576    0.53
Appsignal.Nif._create_root_span/1                         1000 17.12  6903    6.90
Appsignal.Nif._close_span/1                               1000 33.97 13696   13.70
```

There was one call to try and find the parent, another call to see if the PID at the time was ignored, and a last call to check if the integration was active at that time.

It might be possible to remove the check that sees if the integration is active, which happens before starting every span. However, this particular update only consists of performance enhancements, so changes in functionality aren't included.

### Removing Unnecessary Calls

A line above the `:ets.lookup/2` function is `Appsignal.Tracer.running?/0`, a function that's called to ensure ets is running before executing lookups, inserts, and deletions.

Because ets produces an `ArgumentError` when it's not active, a check was called to ensure the registry was running every time the table was evaluated.

For example, this included a function to find the current span for a process named `Tracer.lookup/1`:

```elixir
def lookup(pid) do
  if running?(), do: :ets.lookup(@table, pid)
end
```

This patch removed those checks and added error handling around each function that called ets, removing `Appsignal.Tracer.running?/0` completely:

```elixir
def lookup(pid) do
  try do
    :ets.lookup(@table, pid)
  rescue
    ArgumentError -> []
  end
end
```

### The Final Profile

To summarise, we utilized `profile.eprof` to locate and reduce $7n$ unnecessary calls, including:

- Calls to `:ets.lookup/2` from $6n$ to $3n$
- All $4n$ calls to `Appsignal.Tracer.running`

This resulted in a small but significant improvement in our `instrument` function's performance.

## Sample AppSignal's Performance Monitoring

The ability to save and search performance samples is just one of AppSignal's many developer-driven features designed to help you get the most out of your application's metrics. Developers say they also love us thanks to our:

- Intuitive interface that is easy to navigate.
- Simple and predictable pricing.
- Developer-to-developer support.

If you experience any issues when using AppSignal for Elixir, our [support team](mailto:support@appsignal.com) is on hand to help! And remember, if you're new to AppSignal, we'll welcome you onboard with an exceptionally delicious shipment of stroopwafels 🍪 😋