Beautiful Erlang - Timing

February 9, 2011

If you’re trying to optimize the performance of an application, it’s helpful to take measurements. The simplest method is to track the start time and end time of a small block of code, then print the difference.

Side note: To accurately measure perfomance, you should really average the performance over a longer period of time using repeatable input in a controlled environment. The method I describe here is useful for getting rough measurements and for comparing code with vastly different performance characteristics. In other words, it’s painting in broad strokes.

In Erlang, I used to find myself doing the following:

Start = now(),

...some code...

End = now(),
DiffMS = timer:now_diff(End, Start) / 1000,
io:format("The operation took: ~p milliseconds~n", [Diff])

Needless to say, all that typing made me dread adding timing statements to code. Plus, if I wanted multiple timing statements in the same block of code I was stuck naming the variables ‘Start1’, ‘Start2’, ‘Start3’, etc.

To simplify the process, I made the following macro:

-ifndef(TIMEON).
%% Yes, these need to be on a single line to work...
-define(TIMEON, erlang:put(debug_timer, [now()|case erlang:get(debug_timer) == undefined of true -> []; false -> erlang:get(debug_timer) end])).
-define(TIMEOFF(Var), io:format("~s :: ~10.2f ms : ~p~n", [string:copies(" ", length(erlang:get(debug_timer))), (timer:now_diff(now(), hd(erlang:get(debug_timer)))/1000), Var]), erlang:put(debug_timer, tl(erlang:get(debug_timer)))).
-endif.

This allows me to write:

?TIMEON,

...some code...

?TIMEOFF(my_code_block).

Which prints:

  :: 5.00ms : my_code_block

The ?TIMEON statement works by stuffing the current time into a queue in the process dictionary under the ‘debug_timer’ key, initializing the queue if it is not already initialized.

The ?TIMEOFF statement pops the first value from the aforementioned queue and compares it to the current time, printing the results.

You may ask, “Why all the trouble queuing the current time into a list?” The answer is that we want the timing function to work even when it is nested. In other words, you can put timing statement inside another timing statement. The first ?TIMEOFF call will print the inner time, and the second ?TIMEOFF call will print the outer time.

Happy Hacking!

Back