backend_latency_tracer.erl

backend_latency_tracer.erl

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

-module(backend_latency_tracer).
-compile(export_all).

start() ->
    start(500).

start(LatencyMS) ->
    catch folsom_metrics:delete_metric(foo),
    folsom_metrics:new_histogram(foo, uniform, 9981239823),
    %%% Count the get, put, buckets, keys, exchange, and index FSM init() calls
    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} <- [
                          {open,2},
                          {close,1},
                          {pread,2},
                          {pread,3},
                          {read,2},
                          {write,2},
                          {pwrite,2},
                          {pwrite,3}]],
    [catch dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]) ||
        Mod <- [riak_kv_fs2_backend],
        {Func, Arity} <- [
                          {get_object,4},
                          {put_object,5},
                          {delete,4}]],
    
    %% 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() ->
    io:format("Histogram stats:\n~p\n", [catch folsom_metrics:get_histogram_statistics(foo)]),
    catch folsom_metrics:delete_metric(foo),
    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}) ->
    DKey = {put, Pid},
    Start = case dict:find(DKey, 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(DKey, 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}) ->
    DKey = {get, Pid},
    Start = case dict:find(DKey, 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(DKey, 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}) ->
    DKey = {bitcask, Pid},
    Start = case dict:find(DKey, 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(DKey, 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}) ->
    DKey = {eleveldb, Pid},
    Start = case dict:find(DKey, 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(DKey, Dict), LatencyMS};
trace({trace, Pid, call, {file, _Func, _Args}}, {Dict, LMS}) ->
    {dict:store({file, Pid}, now(), Dict), LMS};
trace({trace, Pid, return_from, {file, Func, _Arity}, _Res}, {Dict, LatencyMS}) ->
    DKey = {file, Pid},
    Start = case dict:find(DKey, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    Elapsed = timer:now_diff(now(), Start) div 1000,
    if Func == pread -> folsom_metrics_histogram:update(foo, Elapsed); true -> ok end,
    case Elapsed of
        X when X > LatencyMS ->
            io:format("~p ~p: file ~p: ~p msec\n", [date(), time(),
                                                        Func, Elapsed]);
        _Elapsed ->
            ok
    end,
    {dict:erase(DKey, Dict), LatencyMS};
trace({trace, Pid, call, {riak_kv_fs2_backend, _, _}}, {Dict, LMS}) ->
    {dict:store({fs2, Pid}, now(), Dict), LMS};
trace({trace, Pid, return_from, {riak_kv_fs2_backend, Func, _}, _Res}, {Dict, LatencyMS}) ->
    DKey = {fs2, Pid},
    Start = case dict:find(DKey, 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: fs2 ~p: ~p msec\n", [date(), time(),
                                                        Func, Elapsed]);
        _Elapsed ->
            ok
    end,
    {dict:erase(DKey, 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.