Skip to content

Instantly share code, notes, and snippets.

@slfritchie
Created September 19, 2013 09:16
Show Gist options
  • Star 8 You must be signed in to star a gist
  • Fork 5 You must be signed in to fork a gist
  • Save slfritchie/159a8ce1f49fc03c77c6 to your computer and use it in GitHub Desktop.
Save slfritchie/159a8ce1f49fc03c77c6 to your computer and use it in GitHub Desktop.
A couple of handy tracers: fun_args_tracer.erl and latency_histogram_tracer.erl.
%% For example: what ETS tables are being called the most by ets:lookup/2?
%% The 1st arg of ets:lookup/2 is the table name.
%% Watch for 10 seconds.
%%
%% > func_args_tracer:start(ets, lookup, 2, 10, fun(Args) -> hd(Args) end).
%%
%% Tracer pid: <0.16102.15>, use func_args_tracer:stop() to stop
%% Otherwise, tracing stops in 10 seconds
%% Current date & time: {2013,9,19} {18,5,48}
%% {started,<0.16102.15>}
%% Total calls: 373476
%% Call stats:
%% [{folsom_histograms,114065},
%% {ac_tab,69689},
%% {ets_riak_core_ring_manager,67147},
%% {folsom_spirals,57076},
%% {riak_capability_ets,48862},
%% {riak_core_node_watcher,8149},
%% {riak_api_pb_registrations,8144},
%% {folsom,243},
%% {folsom_meters,43},
%% {folsom_durations,20},
%% {timer_tab,18},
%% {folsom_gauges,8},
%% {riak_core_stat_cache,5},
%% {sys_dist,3},
%% {inet_db,1},
%% {21495958,1},
%% {3145765,1},
%% {3407910,1}]
%%
-module(func_args_tracer).
-compile(export_all).
start(Mod, Func, Arity, RunSeconds) ->
start(Mod, Func, Arity, RunSeconds, fun(Args) -> Args end).
start(Mod, Func, Arity, RunSeconds, ArgMangler) ->
catch ets:delete(foo),
ets:new(foo, [named_table, public, set]),
dbg:tracer(process, {fun trace/2, new_stats({foo, ArgMangler})}),
dbg:p(all, call),
%% dbg:tpl(Mod, Func, Arity, [{'_', [], [{return_trace}]}]),
dbg:tpl(Mod, Func, Arity, [{'_', [], []}]),
{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() ->
Sort = fun({_,A}, {_, B}) -> A > B end,
Res = ets:tab2list(foo),
TotalCalls = lists:sum([Count || {_Arg, Count} <- Res]),
io:format("Total calls: ~p\n", [TotalCalls]),
io:format("Call stats:\n~p\n", [catch lists:sort(Sort, Res)]),
dbg:stop_clear(),
catch exit(element(2,dbg:get_tracer()), kill),
timer:sleep(100),
stopped.
trace({trace, _Pid, call, {_, _, Args}}, {Tab, ArgMangler} = Acc) ->
Args2 = ArgMangler(Args),
try
ets:update_counter(Tab, Args2, {2, 1})
catch _:_ ->
ets:insert(Tab, {Args2, 1})
end,
Acc;
%% 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({Tab, _ArgMangler} = Acc) ->
ets:delete_all_objects(Tab),
Acc.
print_stats(_DictStats) ->
ok.
%% For example: create a histogram of call latencies for bitcask:put/3.
%% Watch for 10 seconds.
%%
%% > latency_histogram_tracer:start(bitcask, put, 3, 10).
%%
%% Tracer pid: <0.2108.18>, use latency_histogram_tracer:stop() to stop
%% Otherwise, tracing stops in 10 seconds
%% Current date & time: {2013,9,19} {18,14,13}
%% {started,<0.2108.18>}
%% Histogram stats:
%% [{min,0},
%% {max,48},
%% {arithmetic_mean,2.765411819271055},
%% {geometric_mean,2.527103493663478},
%% {harmonic_mean,2.2674039086593973},
%% {median,3},
%% {variance,3.5629207473971585},
%% {standard_deviation,1.8875700642352746},
%% {skewness,2.0360354571500774},
%% {kurtosis,18.529695846728423},
%% {percentile,[{50,3},{75,4},{90,5},{95,6},{99,8},{999,14}]},
%% {histogram,[{1,13436},
%% {2,12304},
%% {3,10789},
%% {4,7397},
%% {5,4191},
%% {6,1929},
%% {7,873},
%% {8,420},
%% {9,163},
%% {10,79},
%% {11,42},
%% {12,47},
%% {13,11},
%% {14,16},
%% {15,7},
%% {16,5},
%% {17,3},
%% {18,4},
%% {19,2},
%% {20,4},
%% {21,1},
%% {22,11},
%% {23,2},
%% {24,1},
%% {25,2},
%% {26,1},
%% {27,0},
%% {28,1},
%% {29,2},
%% {30,0},
%% {31,0},
%% {40,2},
%% {50,1}]},
%% {n,51746}]
-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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment