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. It uses the Rosetta Code algorithm for Fibonacci sequence generation.
Jump into an IEx session and run cprof like this:
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, like pausing profiling with :cprof.pause/0.
We can also use Mix's wrapper task profile.cprof directly.
➜ 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 on our sample Fibonacci generator.
➜ 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:
: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:
****** 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:
: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), 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. It converts the fprof file to cgrind format that you can open inside KCachegrind.
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:
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 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:
AppSignal
AppSignal is another great tool for collecting performance data (among other things). Adding AppSignal to an existing application 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 to track custom metrics.
Here's an example of the AppSignal dashboard collecting data from a sample application:
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:
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.
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!
Top comments (0)