Erlang Central

Difference between revisions of "Measuring Function Execution Time"

From ErlangCentral Wiki

(New page: Category:Testing Category:Articles == 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...)
 
(Added a fun version of the timing function)
(3 intermediate revisions by 2 users not shown)
Line 12:Line 12:
 
=== The Basic Way ===
 
=== The Basic Way ===
  
The most basic way to measur function execution time is to use the function <tt>tc</tt> in the module <tt>timer</tt>. An example is shown below:
+
The most basic way to measure function execution time is to use the function <tt>tc</tt> in the module <tt>timer</tt>. An example is shown below:
  
<code>
+
<code caption="Timing a function with the timer module.">
 
1> timer:tc(lists, seq, [1,10]).  
 
1> timer:tc(lists, seq, [1,10]).  
 
{5,[1,2,3,4,5,6,7,8,9,10]}
 
{5,[1,2,3,4,5,6,7,8,9,10]}
Line 20:Line 20:
 
</code>
 
</code>
  
This tells us that generating the list with integers from 1 to 10 using the <tt>lists</tt> module took 5 microseconds (thats ''micro'', not milli).
+
This tells us that generating the list with integers from 1 to 10 using the <tt>lists</tt> module took 5 microseconds (that's ''micro'', not milli).
  
 
=== Making It More Useful ===
 
=== Making It More Useful ===
Line 26:Line 26:
 
The <tt>tc</tt> 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:
 
The <tt>tc</tt> 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:
  
<code>
+
<code caption="A function that measures execution time more elaborately, still using the timer module.">
 
test_avg(M, F, A, N) when N > 0 ->
 
test_avg(M, F, A, N) when N > 0 ->
 
     L = test_loop(M, F, A, N, []),
 
     L = test_loop(M, F, A, N, []),
Line 49:Line 49:
 
With this function we get both the minimum, the maximum, the median and the average execution time:
 
With this function we get both the minimum, the maximum, the median and the average execution time:
  
<code>
+
<code caption="Using the new measuring function.">
 
2> test_avg(lists, seq, [1,10], 10000).
 
2> test_avg(lists, seq, [1,10], 10000).
 
Range: 2 - 7824 mics
 
Range: 2 - 7824 mics
Line 61:Line 61:
  
 
Using this function or just <tt>timer:tc/3</tt> you can easily measure execution time for functions in the Erlang shell. Very useful!
 
Using this function or just <tt>timer:tc/3</tt> 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.
 +
 +
=== Shell Profiling ===
 +
 +
Here's a fun version (pun not intended) of the same function ready to paste into the shell. It's using variables named with the prefix <tt>TC_</tt> to prevent shadowing in the shell, and will be bound to the variable <tt>TC</tt>:
 +
 +
<code caption="A ready baked fun to use in the shell">
 +
TC = fun(TC_M, TC_F, TC_A, TC_N) when TC_N > 0 -> TC_L = tl([begin {TC_T, _Result} = timer:tc(TC_M, TC_F, TC_A), TC_T end || _ <- lists:seq(1, TC_N)]), TC_Min = lists:min(TC_L), TC_Max = lists:max(TC_L), TC_Med = lists:nth(round((TC_N - 1) / 2), lists:sort(TC_L)), TC_Avg = round(lists:foldl(fun(TC_X, TC_Sum) -> TC_X + TC_Sum end, 0, TC_L) / (TC_N - 1)), io:format("Range: ~b - ~b mics~nMedian: ~b mics ~nAverage: ~b mics~n", [TC_Min, TC_Max, TC_Med, TC_Avg]), TC_Med end.
 +
</code>
  
 
=== Advanced Profiling ===
 
=== Advanced Profiling ===

Revision as of 09:28, 18 December 2008


Contents

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

How

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

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.

Shell Profiling

Here's a fun version (pun not intended) of the same function ready to paste into the shell. It's using variables named with the prefix TC_ to prevent shadowing in the shell, and will be bound to the variable TC:

TC = fun(TC_M, TC_F, TC_A, TC_N) when TC_N > 0 -> TC_L = tl([begin {TC_T, _Result} = timer:tc(TC_M, TC_F, TC_A), TC_T end || _ <- lists:seq(1, TC_N)]), TC_Min = lists:min(TC_L), TC_Max = lists:max(TC_L), TC_Med = lists:nth(round((TC_N - 1) / 2), lists:sort(TC_L)), TC_Avg = round(lists:foldl(fun(TC_X, TC_Sum) -> TC_X + TC_Sum end, 0, TC_L) / (TC_N - 1)), io:format("Range: ~b - ~b mics~nMedian: ~b mics ~nAverage: ~b mics~n", [TC_Min, TC_Max, TC_Med, TC_Avg]), TC_Med end.

Advanced Profiling

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

Authors

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