Report each `riak_kv_put_fsm` and `riak_kv_get_fsm` process that executes in more than `LatencyMS` milliseconds. Also, for various strategic API functions in the `file`, `bitcask`, and `eleveldb` modules, report latencies above the same limit.

fsm_latency_tracer.erl

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

-module(fsm_latency_tracer).
-compile(export_all).

start() ->
    start(500).

start(LatencyMS) ->
    dbg:tracer(process, {fun trace/2, new_stats(LatencyMS)}),
    dbg:p(all, call),
    [catch dbg:tpl(Mod, Func, Arity, [{'_', [], []}]) ||
        Mod <- [riak_kv_put_fsm, riak_kv_get_fsm],
        {Func, Arity} <- [{init, 1}, {finalize, 1}, {finish, 2}]],
    [catch dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]) ||
        Mod <- [bitcask],
        {Func, Arity} <- [
                          {open,1}, {open,2},
                           {close,1},
                           {close_write_file,1},
                           {get,2},
                           {put,3},
                           {delete,2},
                           {sync,1},
                           {iterator,3}, {iterator_next,1}, {iterator_release,1},
                           {needs_merge,1},
                           {is_empty_estimate,1},
                           {status,1}]],
    [catch dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]) ||
        Mod <- [eleveldb],
        {Func, Arity} <- [
                          {open,2},
                          {close,1},
                          {get,3},
                          {put,4},
                          {delete,3},
                          {write,3},
                          {status,2},
                          {destroy,2},
                          {is_empty,1},
                          {iterator,2},
                          {iterator_move,2},
                          {iterator_close,1}]],
    [catch dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]) ||
        Mod <- [file],
        {Func, Arity} <- [
                          {write,2},
                          {pwrite,2},
                          {pwrite,3}]],
    
    %% Don't need return_trace events for this use case, but here's
    %% how to do it if needed.
    %%dbg:tpl(bitcask, merge_single_entry, 6, [{'_', [], [{return_trace}]}]).

    {ok, TPid} = dbg:get_tracer(),
    io:format("Tracer pid: ~p, use ~p:stop() to stop\n", [TPid, ?MODULE]),
    %% timer:send_interval(Interval, TPid, print_report),
    io:format("Not using timer:send_interval...\n"),
    {started, TPid}.

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

trace({trace, Pid, call, {riak_kv_put_fsm, init, _}}, {Dict, LMS}) ->
    {dict:store({put, Pid}, now(), Dict), LMS};
trace({trace, Pid, call, {riak_kv_put_fsm, finish, _}}, {Dict, LatencyMS}) ->
    Start = case dict:find({put, Pid}, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    case timer:now_diff(now(), Start) div 1000 of
        Elapsed when Elapsed > LatencyMS ->
            io:format("~p ~p: put: ~p msec @ ~p ~p\n", [date(), time(), Elapsed, node(), Pid]);
        _Elapsed ->
            ok
    end,
    {dict:erase(Pid, Dict), LatencyMS};
trace({trace, Pid, call, {riak_kv_get_fsm, init, _}}, {Dict, LMS}) ->
    {dict:store({get, Pid}, now(), Dict), LMS};
trace({trace, Pid, call, {riak_kv_get_fsm, finalize, _}}, {Dict, LatencyMS}) ->
    Start = case dict:find({get, Pid}, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    case timer:now_diff(now(), Start) div 1000 of
        Elapsed when Elapsed > LatencyMS ->
            io:format("~p ~p: get: ~p msec @ ~p ~p\n", [date(), time(), Elapsed, node(), Pid]);
        _Elapsed ->
            ok
    end,
    {dict:erase(Pid, Dict), LatencyMS};
trace({trace, Pid, call, {bitcask, _, _}}, {Dict, LMS}) ->
    {dict:store({bitcask, Pid}, now(), Dict), LMS};
trace({trace, Pid, return_from, {bitcask, Func, _}, _Res}, {Dict, LatencyMS}) ->
    Start = case dict:find({bitcask, Pid}, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    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,
    {dict:erase(Pid, Dict), LatencyMS};
trace({trace, Pid, call, {eleveldb, _, _}}, {Dict, LMS}) ->
    {dict:store({eleveldb, Pid}, now(), Dict), LMS};
trace({trace, Pid, return_from, {eleveldb, Func, _}, _Res}, {Dict, LatencyMS}) ->
    Start = case dict:find({eleveldb, Pid}, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    case timer:now_diff(now(), Start) div 1000 of
        Elapsed when Elapsed > LatencyMS ->
            io:format("~p ~p: eleveldb ~p: ~p msec\n", [date(), time(),
                                                        Func, Elapsed]);
        _Elapsed ->
            ok
    end,
    {dict:erase(Pid, Dict), LatencyMS};
trace({trace, Pid, call, {file, _, _}}, {Dict, LMS}) ->
    {dict:store({file, Pid}, now(), Dict), LMS};
trace({trace, Pid, return_from, {file, Func, _}, _Res}, {Dict, LatencyMS}) ->
    Start = case dict:find({file, Pid}, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    case timer:now_diff(now(), Start) div 1000 of
        Elapsed when Elapsed > LatencyMS ->
            io:format("~p ~p: file ~p: ~p msec\n", [date(), time(),
                                                        Func, Elapsed]);
        _Elapsed ->
            ok
    end,
    {dict:erase(Pid, Dict), LatencyMS};
trace(print_report, DictStats) ->
    %%%%% print_stats(DictStats),
    %%%%% new_stats();
    DictStats;
trace(Unknown, DictStats) ->
    erlang:display(wha),
    io:format("Unknown! ~P\n", [Unknown, 20]),
    DictStats.

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

print_stats(_DictStats) ->
    ok.