accumulating_time_tracer.erl and sample output on a busy-merging Bitcask-based Riak node

accumulating_time_tracer.erl

%% Stolen from: https://gist.github.com/2656289

-module(accumulating_time_tracer).
-compile(export_all).

start(Pid_list, MFA_list, IntervalMS) ->
    %%% Count the get, put, buckets, keys, exchange, and index FSM init() calls
    dbg:tracer(process, {fun trace/2, new_stats()}),
    [dbg:p(Pid, call) || Pid <- Pid_list],
    [catch dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]) ||
        {Mod, Func, Arity} <- MFA_list],
    
    {ok, TPid} = dbg:get_tracer(),
    io:format("Tracer pid: ~p, use ~p:stop() to stop\n", [TPid, ?MODULE]),
    timer:send_interval(IntervalMS, TPid, print_report),
    {started, TPid}.

stop() ->
    dbg:stop_clear(),
    catch exit(element(2,dbg:get_tracer()), kill),
    stopped.

trace({trace, Pid, call, {Mod, Func, Args}}, {Dict}) ->
    Arity = length(Args),
    MFA = {Mod, Func, Arity},
    DKey = {Pid, MFA},
    {dict:store(DKey, now(), Dict)};
trace({trace, Pid, return_from, {Mod, Func, Arity}, _Res}, {Dict}) ->
    MFA = {Mod, Func, Arity},
    DKey = {Pid, MFA},
    Start = case dict:find(DKey, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    Elapsed = timer:now_diff(now(), Start),
    %% case timer:now_diff(now(), Start) div 1000 of
    %%     Elapsed when Elapsed > LatencyMS ->
    %%         io:format("~p ~p: bitcask ~p: ~p msec\n", [date(), time(),
    %%                                                    Func, Elapsed]);
    %%     _Elapsed ->
    %%         ok
    %% end,
    SumDKey = {sum, DKey},
    {OldCount, OldTime} = case dict:find(SumDKey, Dict) of
                              error ->
                                  {0, 0};
                              {ok, Else} ->
                                  Else
                          end,
    Dict2 = dict:erase(DKey, Dict),
    {dict:store(SumDKey, {OldCount+1, OldTime+Elapsed}, Dict2)};
trace(print_report, {Dict}) ->
    print_stats(Dict),
    {dict:from_list([X || {K, _V} = X <- dict:to_list(Dict),
                          element(1, K) /= sum])};
trace(Unknown, {Dict}) ->
    erlang:display(wha),
    io:format("Unknown! ~P\n", [Unknown, 20]),
    {Dict}.

new_stats() ->
    {dict:new()}.

print_stats(Dict) ->
    Reports = lists:sort([{MFA, X} || {{sum, MFA}, X} <- dict:to_list(Dict)]),
    [io:format("~p MFA ~p count ~p elapsed_msec ~p\n",
               [time(), MFA, Count, Sum div 1000]) ||
        {MFA, {Count, Sum}} <- Reports].

output.a.md

Watch the handle_call callback for the file_server module only in the file_server_2 process. Output a report every second, if there was any activity to report for that time interval.

accumulating_time_tracer:start([whereis(file_server_2)], [{file_server, handle_call, 3}], 1000).

Some output from my MBP on a Bitcask-based Riak node that is configured to do a lot of Bitcask merges a lot of the time.

15,59,26} MFA {<0.24.0>,{file_server,handle_call,3}} count 1128 elapsed_msec 755
{15,59,27} MFA {<0.24.0>,{file_server,handle_call,3}} count 316 elapsed_msec 128
{15,59,28} MFA {<0.24.0>,{file_server,handle_call,3}} count 183 elapsed_msec 179
{15,59,29} MFA {<0.24.0>,{file_server,handle_call,3}} count 1014 elapsed_msec 611
{15,59,30} MFA {<0.24.0>,{file_server,handle_call,3}} count 3527 elapsed_msec 876
{15,59,31} MFA {<0.24.0>,{file_server,handle_call,3}} count 4102 elapsed_msec 863
{15,59,32} MFA {<0.24.0>,{file_server,handle_call,3}} count 5589 elapsed_msec 867
{15,59,33} MFA {<0.24.0>,{file_server,handle_call,3}} count 1526 elapsed_msec 638
{15,59,34} MFA {<0.24.0>,{file_server,handle_call,3}} count 5640 elapsed_msec 875
{15,59,35} MFA {<0.24.0>,{file_server,handle_call,3}} count 6550 elapsed_msec 862
{15,59,36} MFA {<0.24.0>,{file_server,handle_call,3}} count 2239 elapsed_msec 887