Measuring Function Execution Time

From Erlang Community

[edit] Why?

Why would you want to measure the execution time of a function call? There could be several reasons:

• You want to improve the speed of your code, measuring how much faster it is since the previous version
• You want to compare two implementations of the same functionality with regards to speed

[edit] How

[edit] The Basic Way

The most basic way to measure function execution time is to use the function tc in the module timer. An example is shown below:

1> timer:tc(lists, seq, [1,10]). 
{5,[1,2,3,4,5,6,7,8,9,10]}
2>

This tells us that generating the list with integers from 1 to 10 using the lists module took 5 microseconds (that's micro, not milli).

[edit] Making It More Useful

The tc function is already quite useful, but generally function execution times vary depending on different circumstances. In most cases it is external ones, such as garbage collection, io operations etc. To get a more stable view of the performance of your function, a simple helper function is easy to write:

test_avg(M, F, A, N) when N > 0 ->
    L = test_loop(M, F, A, N, []),
    Length = length(L),
    Min = lists:min(L),
    Max = lists:max(L),
    Med = lists:nth(round((Length / 2)), lists:sort(L)),
    Avg = round(lists:foldl(fun(X, Sum) -> X + Sum end, 0, L) / Length),
    io:format("Range: ~b - ~b mics~n"
	      "Median: ~b mics~n"
	      "Average: ~b mics~n",
	      [Min, Max, Med, Avg]),
    Med.

test_loop(_M, _F, _A, 0, List) ->
    List;
test_loop(M, F, A, N, List) ->
    {T, _Result} = timer:tc(M, F, A),
    test_loop(M, F, A, N - 1, [T|List]).

With this function we get both the minimum, the maximum, the median and the average execution time:

2> test_avg(lists, seq, [1,10], 10000).
Range: 2 - 7824 mics
Median: 3 mics
Average: 4 mics
3
3> 

The function returns the median execution time, since it is the best way to dodge the large numbers (in this case 7824) that are exceptions to the normal execution time.

Using this function or just timer:tc/3 you can easily measure execution time for functions in the Erlang shell. Very useful!

As an exercise, add a metric for the first iteration and not including the first iteration in the range, median, and average calculations. First Iteration metrics are necessary in some systems to examine the effects of OS caching, runtime caching, compiler optimizations, first-time memory allocation, and garbage collection. Many times, you will find that it is the first iteration that is the outlying data point in your benchmarks.

[edit] Advanced Profiling

For more advanced profiling tools please see the Profiling chapter in the Erlang Efficiency Guide.

[edit] Authors

Adam Lindberg works as a consultant at Erlang Training & Consulting.