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 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 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:

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:

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:

(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:

# 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).

  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 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.

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:

  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:

  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:

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:

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 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 🍪 😋