From b4756c19dcaa904b9d1bc07c127f183956bd71f5 Mon Sep 17 00:00:00 2001 From: Fred Hebert Date: Sat, 1 Mar 2014 22:08:20 +0000 Subject: [PATCH] Docs & Cleanup Documentation added, with examples and everything Cleanup of internal code and moving functions around for a better organization. --- src/recon_trace.erl | 346 ++++++++++++++++++++++++++++++++------------ 1 file changed, 256 insertions(+), 90 deletions(-) diff --git a/src/recon_trace.erl b/src/recon_trace.erl index 52b2b81..43abefa 100644 --- a/src/recon_trace.erl +++ b/src/recon_trace.erl @@ -1,27 +1,81 @@ +%%% @author Fred Hebert +%%% [http://ferd.ca/] %%% @doc %%% `recon_trace' is a module that handles tracing in a safe manner for single -%%% Erlang nodes. -%%% Functionality includes: -%%% - Nicer to use interface -%%% - Protection against dumb decisions (matching all calls being traced, -%%% adding rate or trace limits) -%%% - Nicer formatting +%%% Erlang nodes, currently for function calls only. Functionality includes: %%% -%%% The advantages are given by taking the following structure for tracing: +%%% %%% +%%% == Tracing Erlang Code == +%%% +%%% The Erlang Trace BIFs allow to trace any Erlang code at all. They work in +%%% two parts: pid specifications, and trace patterns. +%%% +%%% Pid specifications let you decide which processes to target. They can be +%%% specific pids, `all' pids, `existing' pids, or `new' pids (those not +%%% spawned at the time of the function call). +%%% +%%% The trace patterns represent functions. Functions can be specified in two +%%% parts: specifying the modules, functions, and arguments, and then with +%%% Erlang match specifications to add constraints to arguments (see +%%% {@link calls/3} for details). +%%% +%%% What defines whether you get traced or not is the intersection of both: +%%% +%%% 
+%%%         _,--------,_      _,--------,_
+%%%      ,-'            `-,,-'            `-,
+%%%   ,-'              ,-'  '-,              `-,
+%%%  |   Matching    -'        '-   Matching    |
+%%%  |     Pids     |  Getting   |    Trace     |
+%%%  |              |   Traced   |  Patterns    |
+%%%  |               -,        ,-               |
+%%%   '-,              '-,  ,-'              ,-'
+%%%      '-,_          _,-''-,_          _,-'
+%%%          '--------'        '--------' 
+%%%
+%%% +%%% If either the pid specification excludes a process or a trace pattern +%%% excludes a given call, no trace will be received. +%%% +%%% == Structure == +%%% +%%% This library is production-safe due to taking the following structure for +%%% tracing: +%%% +%%% 
 %%% [IO/Group leader] <---------------------,
 %%%   |                                     |
 %%% [shell] ---> [tracer process] ----> [formatter]
+%%%
+%%% +%%% The tracer process receives trace messages from the node, and enforces +%%% limits in absolute terms or trace rates, before forwarding the messages +%%% to the formatter. This is done so the tracer can do as little work as +%%% possible and never block while building up a large mailbox. %%% %%% The tracer process is linked to the shell, and the formatter to the %%% tracer process. The formatter also traps exits to be able to handle %%% all received trace messages until the tracer termination, but will then %%% shut down as soon as possible. +%%% +%%% In case the operator is tracing from a remote shell which gets +%%% disconnected, the links between the shell and the tracer should make it +%%% so tracing is automatically turned off once you disconnect. +%%% @end -module(recon_trace). --export([clear/0, - calls/2, calls/3, - calls/4, calls/5]). -%% internal exports + +%% API +-export([clear/0, calls/2, calls/3]). + +%% Internal exports -export([count_tracer/1, rate_tracer/2, formatter/3]). -type matchspec() :: [{[term()], [term()], [term()]}]. @@ -46,24 +100,113 @@ -type max() :: max_traces() | max_rate(). -type num_matches() :: non_neg_integer(). --spec clear() -> num_matches(). +-export_type([mod/0, fn/0, args/0, mfa/0, num_matches/0, options/0, + max_traces/0, max_rate/0]). + +%%%%%%%%%%%%%% +%%% PUBLIC %%% +%%%%%%%%%%%%%% + +%% @doc Stops all tracing at once. +-spec clear() -> ok. clear() -> erlang:trace(all, false, [all]), erlang:trace_pattern({'_','_','_'}, false, [local,meta,call_count,call_time]), - erlang:trace_pattern({'_','_','_'}, false, []). % unsets global - --spec calls(mod(), fn(), args(), max()) -> num_matches(). -calls(Mod, Fun, Args, Max) -> - calls([{Mod,Fun,Args}], Max, []). - --spec calls(mod(), fn(), args(), max(), options()) -> num_matches(). -calls(Mod, Fun, Args, Max, Opts) -> - calls([{Mod,Fun,Args}], Max, Opts). + erlang:trace_pattern({'_','_','_'}, false, []), % unsets global + maybe_kill(recon_trace_tracer), + maybe_kill(recon_trace_formatter), + ok. +%% @doc Equivalent to `calls({Mod, Fun, Args}, Max, [])'. -spec calls(mfa(), max()) -> num_matches(). calls({Mod, Fun, Args}, Max) -> calls([{Mod,Fun,Args}], Max, []). +%% @doc Allows to set trace patterns and pid specifications to trace +%% function calls. +%% +%% The basic calls take the trace patterns as tuples of the form +%% `{Module, Function, Args}' where: +%% +%% +%% +%% There is also an argument specifying either a maximal count (a number) +%% of trace messages to be received, or a maximal frequency (`{Num, Millisecs}'). +%% +%% Here are examples of things to trace: +%% +%% +%% +%% There's a few more combination possible, with multiple trace patterns per call, and more +%% options: +%% +%% +%% +%% Also note that putting extremely large `Max' values (i.e. `99999999' or +%% `{10000,1}') will probably negate most of the safe-guarding this library +%% does and be dangerous to your node. Similarly, tracing extremely large +%% amounts of function calls (all of them, or all of `io' for example) +%% can be risky if more trace messages are generated than any process on +%% the node could ever handle, despite the precautions taken by this library. +%% @end -spec calls(mfa() | [mfa(),...], max(), options()) -> num_matches(). calls({Mod, Fun, Args}, Max, Opts) -> calls([{Mod,Fun,Args}], Max,Opts); @@ -74,6 +217,79 @@ calls(MFAs = [_|_], Max, Opts) -> Pid = setup(count_tracer, [Max]), trace_calls(MFAs, Pid, Opts). +%%%%%%%%%%%%%%%%%%%%%%% +%%% PRIVATE EXPORTS %%% +%%%%%%%%%%%%%%%%%%%%%%% +%% Stops when N trace messages have been received +count_tracer(0) -> + exit(normal); +count_tracer(N) -> + receive + Msg -> + recon_trace_formatter ! Msg, + count_tracer(N-1) + end. + +%% Stops whenever the trace message rates goes higher than +%% `Max' messages in `Time' milliseconds. Note that if the rate +%% proposed is higher than what the IO system of the formatter +%% can handle, this can still put a node at risk. +%% +%% It is recommended to try stricter rates to begin with. +rate_tracer(Max, Time) -> rate_tracer(Max, Time, 0, os:timestamp()). + +rate_tracer(Max, Time, Count, Start) -> + receive + Msg -> + recon_trace_formatter ! Msg, + Now = os:timestamp(), + Delay = timer:now_diff(Now, Start) div 1000, + if Delay > Time -> rate_tracer(Max, Time, 0, Now) + ; Max > Count -> rate_tracer(Max, Time, Count+1, Start) + ; Max =:= Count -> exit(normal) + end + end. + +%% Formats traces to be output +formatter(Tracer, Parent, Ref) -> + process_flag(trap_exit, true), + link(Tracer), + Parent ! {Ref, linked}, + formatter(Tracer, group_leader()). + +formatter(Tracer, Leader) -> + receive + {'EXIT', Tracer, normal} -> + io:format("Recon tracer rate limit tripped.~n"), + exit(normal); + {'EXIT', Tracer, Reason} -> + exit(Reason); + TraceMsg -> + io:format(Leader, format(TraceMsg), []), + formatter(Tracer, Leader) + end. + + +%%%%%%%%%%%%%%%%%%%%%%% +%%% SETUP FUNCTIONS %%% +%%%%%%%%%%%%%%%%%%%%%%% + +%% starts the tracer and formatter processes, and +%% cleans them up before each call. +setup(TracerFun, TracerArgs) -> + clear(), + Ref = make_ref(), + Tracer = spawn_link(?MODULE, TracerFun, TracerArgs), + register(recon_trace_tracer, Tracer), + Format = spawn(?MODULE, formatter, [Tracer, self(), Ref]), + register(recon_trace_formatter, Format), + receive + {Ref, linked} -> Tracer + after 5000 -> + error(setup_failed) + end. + +%% Sets the traces in action trace_calls(MFAs, Pid, Opts) -> {PidSpecs, TraceOpts, MatchOpts} = validate_opts(Opts), Matches = [begin @@ -84,6 +300,11 @@ trace_calls(MFAs, Pid, Opts) -> || PidSpec <- PidSpecs], lists:sum(Matches). + +%%%%%%%%%%%%%%%%%% +%%% VALIDATION %%% +%%%%%%%%%%%%%%%%%% + validate_opts(Opts) -> PidSpecs = validate_pid_specs(proplists:get_value(pid, Opts, all)), TraceOpts = case proplists:get_value(timestamp, Opts, formatter) of @@ -134,70 +355,10 @@ validate_mfa(Mod, Fun, Args) -> _ when Args >= 0, Args =< 255 -> {Args, true} end. -setup(TracerFun, TracerArgs) -> - clear(), - maybe_kill(recon_trace_tracer), - maybe_kill(recon_trace_formatter), - Ref = make_ref(), - Tracer = spawn_link(?MODULE, TracerFun, TracerArgs), - register(recon_trace_tracer, Tracer), - Format = spawn(?MODULE, formatter, [Tracer, self(), Ref]), - register(recon_trace_formatter, Format), - receive - {Ref, linked} -> Tracer - after 5000 -> - error(setup_failed) - end. - -%% Stops when N trace messages have been received -count_tracer(0) -> - exit(normal); -count_tracer(N) -> - receive - Msg -> - recon_trace_formatter ! Msg, - count_tracer(N-1) - end. - -%% Stops whenever the trace message rates goes higher than -%% `Max' messages in `Time' milliseconds. Note that if the rate -%% proposed is higher than what the IO system of the formatter -%% can handle, this can still put a node at risk. -%% -%% It is recommended to try stricter rates to begin with. -rate_tracer(Max, Time) -> rate_tracer(Max, Time, 0, os:timestamp()). - -rate_tracer(Max, Time, Count, Start) -> - receive - Msg -> - recon_trace_formatter ! Msg, - Now = os:timestamp(), - Delay = timer:now_diff(Now, Start) div 1000, - if Delay > Time -> rate_tracer(Max, Time, 0, Now) - ; Max > Count -> rate_tracer(Max, Time, Count+1, Start) - ; Max =:= Count -> exit(normal) - end - end. - -formatter(Tracer, Parent, Ref) -> - process_flag(trap_exit, true), - link(Tracer), - Parent ! {Ref, linked}, - formatter(Tracer, group_leader()). - -formatter(Tracer, Leader) -> - receive - {'EXIT', Tracer, normal} -> - io:format("Recon tracer rate limit tripped.~n"), - exit(normal); - {'EXIT', Tracer, Reason} -> - exit(Reason); - TraceMsg -> - io:format(Leader, format(TraceMsg), []), - formatter(Tracer, Leader) - end. - - +%%%%%%%%%%%%%%%%%%%%%%%% +%%% TRACE FORMATTING %%% +%%%%%%%%%%%%%%%%%%%%%%%% +%% Thanks Geoff Cant for the foundations for this. format(TraceMsg) -> {Type, Pid, {Hour,Min,Sec}, TraceInfo} = extract_info(TraceMsg), {FormatStr, FormatArgs} = case {Type, TraceInfo} of @@ -289,6 +450,16 @@ to_hms(Stamp = {_, _, Micro}) -> to_hms(_) -> {0,0,0}. +format_args(Arity) when is_integer(Arity) -> + "/"++integer_to_list(Arity); +format_args(Args) when is_list(Args) -> + "("++string:join([io_lib:format("~p", [Arg]) || Arg <- Args], ", ")++")". + + +%%%%%%%%%%%%%%% +%%% HELPERS %%% +%%%%%%%%%%%%%%% + maybe_kill(Name) -> case whereis(Name) of undefined -> @@ -308,11 +479,6 @@ wait_for_death(Pid) -> ok end. -format_args(Arity) when is_integer(Arity) -> - "/"++integer_to_list(Arity); -format_args(Args) when is_list(Args) -> - "("++string:join([io_lib:format("~p", [Arg]) || Arg <- Args], ", ")++")". - %% Borrowed from dbg fun_to_ms(ShellFun) when is_function(ShellFun) -> case erl_eval:fun_data(ShellFun) of