-
-
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
%% 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. | |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
%% 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