[erlang-questions] Simple profiling with ?TIME(Tag,Expr)

[Luke Gorrie]

Howdy,

Did I ever post my favourite profiling macro? It's pretty simple:

-define(TIME(Tag,Expr),
        (fun() ->
                 %% NOTE: timer:tc/4 does an annoying 'catch' so we
                 %% need to wrap the result in 'ok' to be able to
                 %% detect an unhandled exception.
                 {__TIME, __RESULT} = timer:tc(erlang,apply,[fun() -> {ok,Expr} end,[]]),
                 io:format("time(~s): ~18.3fms ~999p~n", [?MODULE,__TIME/1000, Tag]),
                 case __RESULT of
                     {ok,_} -> element(2, __RESULT);
                     {'EXIT',Error}  -> exit(Error)
                 end
         end)()).

if you wrap it around a few strategic expressions in your code you end
up with simple running-time summary printouts like this:

time(backup):           3654.744ms restore_table_defs
time(backup):            182.969ms restore_secondary_indexes
time(backup):            311.973ms restore_records
time(backup):             20.928ms checkpoint
time(backup):              5.095ms remove_logs