latency_histogram_tracer.erl

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

-module(latency_histogram_tracer).
-compile(export_all).

start(Mod, Func, Arity, RunSeconds) ->
    catch folsom_metrics:delete_metric(foo),
    folsom_metrics:new_histogram(foo, uniform, 50*1000*1000),
    dbg:tracer(process, {fun trace/2, new_stats(0)}),
    dbg:p(all, call),
    dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]),
    
    {ok, TPid} = dbg:get_tracer(),
    io:format("Tracer pid: ~p, use ~p:stop() to stop\n", [TPid, ?MODULE]),
    io:format("Otherwise, tracing stops in ~p seconds\n", [RunSeconds]),
    io:format("Current date & time: ~p ~p\n", [date(), time()]),
    spawn(fun() -> timer:sleep(RunSeconds * 1000), stop() end),
    {started, TPid}.

stop() ->
    io:format("Histogram stats:\n~p\n", [catch folsom_metrics:get_histogram_statistics(foo)]),
    dbg:stop_clear(),
    catch exit(element(2,dbg:get_tracer()), kill),
    timer:sleep(100),
    catch folsom_metrics:delete_metric(foo),
    stopped.

trace({trace, Pid, call, {_, _, _}}, {Dict, LMS}) ->
    {dict:store(Pid, now(), Dict), LMS};
trace({trace, Pid, return_from, {_, _, _}, _Res}, {Dict, LatencyMS}) ->
    DKey = Pid,
    Start = case dict:find(DKey, Dict) of
                {ok, StTime} -> StTime;
                error        -> now()
            end,
    Elapsed = timer:now_diff(now(), Start) div 1000,
    folsom_metrics_histogram:update(foo, Elapsed),
    {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.