%%% @author Fred Hebert <mononcqc@ferd.ca>
%%% [http://ferd.ca/]
%%% @doc
%%% `recon_trace' is a module that handles tracing in a safe manner for single
%%% Erlang nodes, currently for function calls only. Functionality includes:
%%%
%%% <ul>
%%% <li>Nicer to use interface (arguably) than `dbg' or trace BIFs.</li>
%%% <li>Protection against dumb decisions (matching all calls on a node
%%% being traced, for example)</li>
%%% <li>Adding safe guards in terms of absolute trace count or
%%% rate-limitting</li>
%%% <li>Nicer formatting than default traces</li>
%%% </ul>
%%%
%%% == 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.
%%%
%%% == Example Session ==
%%%
%%% First let's trace the `queue:new' functions in any process:
%%%
%%% ```
%%% 1> recon_trace:calls({queue, new, '_'}, 1).
%%% 1
%%% 13:14:34.086078 <0.44.0> queue:new()
%%% Recon tracer rate limit tripped.
%%% '''
%%%
%%% The limit was set to `1' trace message at most, and `recon' let us
%%% know when that limit was reached.
%%%
%%% Let's instead look for all the `queue:in/2' calls, to see what it is
%%% we're inserting in queues:
%%%
%%% ```
%%% 2> recon_trace:calls({queue, in, 2}, 1).
%%% 1
%%% 13:14:55.365157 <0.44.0> queue:in(a, {[],[]})
%%% Recon tracer rate limit tripped.
%%% '''
%%%
%%% In order to see the content we want, we should change the trace patterns
%%% to use a `fun' that matches on all arguments in a list (`_') and returns
%%% `return_trace()'. This last part will generate a second trace for each
%%% call that includes the return value:
%%%
%%% ```
%%% 3> recon_trace:calls({queue, in, fun(_) -> return_trace() end}, 3).
%%% 1
%%%
%%% 13:15:27.655132 <0.44.0> queue:in(a, {[],[]})
%%%
%%% 13:15:27.655467 <0.44.0> queue:in/2 --> {[a],[]}
%%%
%%% 13:15:27.757921 <0.44.0> queue:in(a, {[],[]})
%%% Recon tracer rate limit tripped.
%%% '''
%%%
%%% Matching on argument lists can be done in a more complex manner:
%%%
%%% ```
%%% 4> recon_trace:calls(
%%% 4> {queue, '_', fun([A,_]) when is_list(A); is_integer(A) andalso A > 1 -> return_trace() end},
%%% 4> {10,100}
%%% 4> ).
%%% 32
%%%
%%% 13:24:21.324309 <0.38.0> queue:in(3, {[],[]})
%%%
%%% 13:24:21.371473 <0.38.0> queue:in/2 --> {[3],[]}
%%%
%%% 13:25:14.694865 <0.53.0> queue:split(4, {[10,9,8,7],[1,2,3,4,5,6]})
%%%
%%% 13:25:14.695194 <0.53.0> queue:split/2 --> {{[4,3,2],[1]},{[10,9,8,7],[5,6]}}
%%%
%%% 5> recon_trace:clear().
%%% ok
%%% '''
%%%
%%% Note that in the pattern above, no specific function (<code>'_'</code>) was
%%% matched against. Instead, the `fun' used restricted functions to those
%%% having two arguments, the first of which is either a list or an integer
%%% greater than `1'.
%%%
%%% The limit was also set using `{10,100}' instead of an integer, making the
%%% rate-limitting at 10 messages per 100 milliseconds, instead of an absolute
%%% value.
%%%
%%% Any tracing can be manually interrupted by calling `recon_trace:clear()',
%%% or killing the shell process.
%%%
%%% Be aware that extremely broad patterns with lax rate-limitting (or very
%%% high absolute limits) may impact your node's stability in ways
%%% `recon_trace' cannot easily help you with.
%%%
%%% In doubt, start with the most restrictive tracing possible, with low
%%% limits, and progressively increase your scope.
%%%
%%% See {@link calls/3} for more details and tracing possibilities.
%%%
%%% == 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.
%%%
%%% If sending output to the Group Leader is not desired, you may specify
%%% a different pid() via the option `io_server' in the {@link calls/3} function.
%%% For instance to write the traces to a file you can do something like
%%%
%%% ```
%%% 1> {ok, Dev} = file:open("/tmp/trace",[write]).
%%% 2> recon_trace:calls({queue, in, fun(_) -> return_trace() end}, 3, [{io_server, Dev}]).
%%% 1
%%% 3>
%%% Recon tracer rate limit tripped.
%%% 4> file:close(Dev).
%%% '''
%%%
%%% The only output still sent to the Group Leader is the rate limit being
%%% tripped, and any errors. The rest will be sent to the other IO
%%% server (see [http://erlang.org/doc/apps/stdlib/io_protocol.html]).
%%%
%%% == Record Printing ==
%%%
%%% Thanks to code contributed by Bartek Górny, record printing can be added
%%% to traces by first importing records in an active session with
%%% `recon_rec:import([Module, ...])', after which the records declared in
%%% the module list will be supported.
%%% @end
-module(recon_trace).
%% API
-export([clear/0, calls/2, calls/3]).
-export([format/1]).
%% Internal exports
-export([count_tracer/1, rate_tracer/2, formatter/5, format_trace_output/1, format_trace_output/2]).
-type matchspec() :: [{[term()] | '_', [term()], [term()]}].
-type shellfun() :: fun((_) -> term()).
-type formatterfun() :: fun((_) -> iodata()).
-type millisecs() :: non_neg_integer().
-type pidspec() :: all | existing | new | recon:pid_term().
-type max_traces() :: non_neg_integer().
-type max_rate() :: {max_traces(), millisecs()}.
%% trace options
-type options() :: [ {pid, pidspec() | [pidspec(),...]} % default: all
| {timestamp, formatter | trace} % default: formatter
| {args, args | arity} % default: args
| {io_server, pid() | atom()} % default: group_leader()
| {formatter, formatterfun()} % default: internal formatter
| return_to | {return_to, boolean()} % default: false
%% match pattern options
| {scope, global | local} % default: global
].
-type mod() :: '_' | module().
-type fn() :: '_' | atom().
-type args() :: '_' | 0..255 | return_trace | matchspec() | shellfun().
-type tspec() :: {mod(), fn(), args()}.
-type max() :: max_traces() | max_rate().
-type num_matches() :: non_neg_integer().
-export_type([mod/0, fn/0, args/0, tspec/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
maybe_kill(recon_trace_tracer),
maybe_kill(recon_trace_formatter),
ok.
%% @equiv calls({Mod, Fun, Args}, Max, [])
-spec calls(tspec() | [tspec(),...], max()) -> num_matches().
calls({Mod, Fun, Args}, Max) ->
calls([{Mod,Fun,Args}], Max, []);
calls(TSpecs = [_|_], Max) ->
calls(TSpecs, 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:
%%
%% <ul>
%% <li>`Module' is any atom representing a module</li>
%% <li>`Function' is any atom representing a function, or the wildcard
%% <code>'_'</code></li>
%% <li>`Args' is either the arity of a function (`0..255'), a wildcard
%% pattern (<code>'_'</code>), a
%% <a href="http://learnyousomeerlang.com/ets#you-have-been-selected">match specification</a>,
%% or a function from a shell session that can be transformed into
%% a match specification</li>
%% </ul>
%%
%% 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:
%%
%% <ul>
%% <li>All calls from the `queue' module, with 10 calls printed at most:
%% ``recon_trace:calls({queue, '_', '_'}, 10)''</li>
%% <li>All calls to `lists:seq(A,B)', with 100 calls printed at most:
%% `recon_trace:calls({lists, seq, 2}, 100)'</li>
%% <li>All calls to `lists:seq(A,B)', with 100 calls per second at most:
%% `recon_trace:calls({lists, seq, 2}, {100, 1000})'</li>
%% <li>All calls to `lists:seq(A,B,2)' (all sequences increasing by two)
%% with 100 calls at most:
%% `recon_trace:calls({lists, seq, fun([_,_,2]) -> ok end}, 100)'</li>
%% <li>All calls to `iolist_to_binary/1' made with a binary as an argument
%% already (kind of useless conversion!):
%% `recon_trace:calls({erlang, iolist_to_binary, fun([X]) when is_binary(X) -> ok end}, 10)'</li>
%% <li>Calls to the queue module only in a given process `Pid', at a rate
%% of 50 per second at most:
%% ``recon_trace:calls({queue, '_', '_'}, {50,1000}, [{pid, Pid}])''</li>
%% <li>Print the traces with the function arity instead of literal arguments:
%% `recon_trace:calls(TSpec, Max, [{args, arity}])'</li>
%% <li>Matching the `filter/2' functions of both `dict' and `lists' modules,
%% across new processes only:
%% `recon_trace:calls([{dict,filter,2},{lists,filter,2}], 10, [{pid, new}])'</li>
%% <li>Tracing the `handle_call/3' functions of a given module for all new processes,
%% and those of an existing one registered with `gproc':
%% `recon_trace:calls({Mod,handle_call,3}, {10,100}, [{pid, [{via, gproc, Name}, new]}'</li>
%% <li>Show the result of a given function call:
%% `recon_trace:calls({Mod,Fun,fun(_) -> return_trace() end}, Max, Opts)'
%% or
%% ``recon_trace:calls({Mod,Fun,[{'_', [], [{return_trace}]}]}, Max, Opts)'',
%% the important bit being the `return_trace()' call or the
%% `{return_trace}' match spec value.
%% A short-hand version for this pattern of 'match anything, trace everything'
%% for a function is `recon_trace:calls({Mod, Fun, return_trace})'. </li>
%% </ul>
%%
%% There's a few more combination possible, with multiple trace patterns per call, and more
%% options:
%%
%% <ul>
%% <li>`{pid, PidSpec}': which processes to trace. Valid options is any of
%% `all', `new', `existing', or a process descriptor (`{A,B,C}',
%% `"<A.B.C>"', an atom representing a name, `{global, Name}',
%% `{via, Registrar, Name}', or a pid). It's also possible to specify
%% more than one by putting them in a list.</li>
%% <li>`{timestamp, formatter | trace}': by default, the formatter process
%% adds timestamps to messages received. If accurate timestamps are
%% required, it's possible to force the usage of timestamps within
%% trace messages by adding the option `{timestamp, trace}'.</li>
%% <li>`{args, arity | args}': whether to print arity in function calls
%% or their (by default) literal representation.</li>
%% <li>`{scope, global | local}': by default, only 'global' (fully qualified
%% function calls) are traced, not calls made internally. To force tracing
%% of local calls, pass in `{scope, local}'. This is useful whenever
%% you want to track the changes of code in a process that isn't called
%% with `Module:Fun(Args)', but just `Fun(Args)'.</li>
%% <li>`{formatter, fun(Term) -> io_data() end}': override the default
%% formatting functionality provided by recon.</li>
%% <li>`{io_server, pid() | atom()}': by default, recon logs to the current
%% group leader, usually the shell. This option allows to redirect
%% trace output to a different IO server (such as a file handle).</li>
%% <li>`return_to': If this option is set (in conjunction with the match
%% option `{scope, local}'), the function to which the value is returned
%% is output in a trace. Note that this is distinct from giving the
%% *caller* since exception handling or calls in tail position may
%% hide the original caller.</li>
%% </ul>
%%
%% 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(tspec() | [tspec(),...], max(), options()) -> num_matches().
calls({Mod, Fun, Args}, Max, Opts) ->
calls([{Mod,Fun,Args}], Max, Opts);
calls(TSpecs = [_|_], {Max, Time}, Opts) ->
Pid = setup(rate_tracer, [Max, Time],
validate_formatter(Opts), validate_io_server(Opts)),
trace_calls(TSpecs, Pid, Opts);
calls(TSpecs = [_|_], Max, Opts) ->
Pid = setup(count_tracer, [Max],
validate_formatter(Opts), validate_io_server(Opts)),
trace_calls(TSpecs, Pid, Opts).
%%%%%%%%%%%%%%%%%%%%%%%
%%% PRIVATE EXPORTS %%%
%%%%%%%%%%%%%%%%%%%%%%%
%% @private 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.
%% @private 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.
%% @private Formats traces to be output
formatter(Tracer, Parent, Ref, FormatterFun, IOServer) ->
process_flag(trap_exit, true),
link(Tracer),
Parent ! {Ref, linked},
formatter(Tracer, IOServer, FormatterFun).
formatter(Tracer, IOServer, FormatterFun) ->
receive
{'EXIT', Tracer, normal} ->
io:format("Recon tracer rate limit tripped.~n"),
exit(normal);
{'EXIT', Tracer, Reason} ->
exit(Reason);
TraceMsg ->
io:format(IOServer, FormatterFun(TraceMsg), []),
formatter(Tracer, IOServer, FormatterFun)
end.
%%%%%%%%%%%%%%%%%%%%%%%
%%% SETUP FUNCTIONS %%%
%%%%%%%%%%%%%%%%%%%%%%%
%% starts the tracer and formatter processes, and
%% cleans them up before each call.
setup(TracerFun, TracerArgs, FormatterFun, IOServer) ->
clear(),
Ref = make_ref(),
Tracer = spawn_link(?MODULE, TracerFun, TracerArgs),
register(recon_trace_tracer, Tracer),
Format = spawn(?MODULE, formatter, [Tracer, self(), Ref, FormatterFun, IOServer]),
register(recon_trace_formatter, Format),
receive
{Ref, linked} -> Tracer
after 5000 ->
error(setup_failed)
end.
%% Sets the traces in action
trace_calls(TSpecs, Pid, Opts) ->
{PidSpecs, TraceOpts, MatchOpts} = validate_opts(Opts),
Matches = [begin
{Arity, Spec} = validate_tspec(Mod, Fun, Args),
erlang:trace_pattern({Mod, Fun, Arity}, Spec, MatchOpts)
end || {Mod, Fun, Args} <- TSpecs],
[erlang:trace(PidSpec, true, [call, {tracer, Pid} | TraceOpts])
|| PidSpec <- PidSpecs],
lists:sum(Matches).
%%%%%%%%%%%%%%%%%%
%%% VALIDATION %%%
%%%%%%%%%%%%%%%%%%
validate_opts(Opts) ->
PidSpecs = validate_pid_specs(proplists:get_value(pid, Opts, all)),
Scope = proplists:get_value(scope, Opts, global),
TraceOpts = case proplists:get_value(timestamp, Opts, formatter) of
formatter -> [];
trace -> [timestamp]
end ++
case proplists:get_value(args, Opts, args) of
args -> [];
arity -> [arity]
end ++
case proplists:get_value(return_to, Opts, undefined) of
true when Scope =:= local ->
[return_to];
true when Scope =:= global ->
io:format("Option return_to only works with option {scope, local}~n"),
%% Set it anyway
[return_to];
_ ->
[]
end,
MatchOpts = [Scope],
{PidSpecs, TraceOpts, MatchOpts}.
%% Support the regular specs, but also allow `recon:pid_term()' and lists
%% of further pid specs.
-spec validate_pid_specs(pidspec() | [pidspec(),...]) ->
[all | new | existing | pid(), ...].
validate_pid_specs(all) -> [all];
validate_pid_specs(existing) -> [existing];
validate_pid_specs(new) -> [new];
validate_pid_specs([Spec]) -> validate_pid_specs(Spec);
validate_pid_specs(PidTerm = [Spec|Rest]) ->
%% can be "<a.b.c>" or [pidspec()]
try
[recon_lib:term_to_pid(PidTerm)]
catch
error:function_clause ->
validate_pid_specs(Spec) ++ validate_pid_specs(Rest)
end;
validate_pid_specs(PidTerm) ->
%% has to be `recon:pid_term()'.
[recon_lib:term_to_pid(PidTerm)].
validate_tspec(Mod, Fun, Args) when is_function(Args) ->
validate_tspec(Mod, Fun, fun_to_ms(Args));
%% helper to save typing for common actions
validate_tspec(Mod, Fun, return_trace) ->
validate_tspec(Mod, Fun, [{'_', [], [{return_trace}]}]);
validate_tspec(Mod, Fun, Args) ->
BannedMods = ['_', ?MODULE, io, lists],
%% The banned mod check can be bypassed by using
%% match specs if you really feel like being dumb.
case {lists:member(Mod, BannedMods), Args} of
{true, '_'} -> error({dangerous_combo, {Mod,Fun,Args}});
{true, []} -> error({dangerous_combo, {Mod,Fun,Args}});
_ -> ok
end,
case Args of
'_' -> {'_', true};
_ when is_list(Args) -> {'_', Args};
_ when Args >= 0, Args =< 255 -> {Args, true}
end.
validate_formatter(Opts) ->
case proplists:get_value(formatter, Opts) of
F when is_function(F, 1) -> F;
_ -> fun format/1
end.
validate_io_server(Opts) ->
proplists:get_value(io_server, Opts, group_leader()).
%%%%%%%%%%%%%%%%%%%%%%%%
%%% 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
%% {trace, Pid, 'receive', Msg}
{'receive', [Msg]} ->
{"< ~p", [Msg]};
%% {trace, Pid, send, Msg, To}
{send, [Msg, To]} ->
{" > ~p: ~p", [To, Msg]};
%% {trace, Pid, send_to_non_existing_process, Msg, To}
{send_to_non_existing_process, [Msg, To]} ->
{" > (non_existent) ~p: ~p", [To, Msg]};
%% {trace, Pid, call, {M, F, Args}}
{call, [{M,F,Args}]} ->
{"~p:~p~s", [M,F,format_args(Args)]};
%% {trace, Pid, call, {M, F, Args}, Msg}
{call, [{M,F,Args}, Msg]} ->
{"~p:~p~s ~s", [M,F,format_args(Args), format_trace_output(Msg)]};
%% {trace, Pid, return_to, {M, F, Arity}}
{return_to, [{M,F,Arity}]} ->
{" '--> ~p:~p/~p", [M,F,Arity]};
%% {trace, Pid, return_from, {M, F, Arity}, ReturnValue}
{return_from, [{M,F,Arity}, Return]} ->
{"~p:~p/~p --> ~s", [M,F,Arity, format_trace_output(Return)]};
%% {trace, Pid, exception_from, {M, F, Arity}, {Class, Value}}
{exception_from, [{M,F,Arity}, {Class,Val}]} ->
{"~p:~p/~p ~p ~p", [M,F,Arity, Class, Val]};
%% {trace, Pid, spawn, Spawned, {M, F, Args}}
{spawn, [Spawned, {M,F,Args}]} ->
{"spawned ~p as ~p:~p~s", [Spawned, M, F, format_args(Args)]};
%% {trace, Pid, exit, Reason}
{exit, [Reason]} ->
{"EXIT ~p", [Reason]};
%% {trace, Pid, link, Pid2}
{link, [Linked]} ->
{"link(~p)", [Linked]};
%% {trace, Pid, unlink, Pid2}
{unlink, [Linked]} ->
{"unlink(~p)", [Linked]};
%% {trace, Pid, getting_linked, Pid2}
{getting_linked, [Linker]} ->
{"getting linked by ~p", [Linker]};
%% {trace, Pid, getting_unlinked, Pid2}
{getting_unlinked, [Unlinker]} ->
{"getting unlinked by ~p", [Unlinker]};
%% {trace, Pid, register, RegName}
{register, [Name]} ->
{"registered as ~p", [Name]};
%% {trace, Pid, unregister, RegName}
{unregister, [Name]} ->
{"no longer registered as ~p", [Name]};
%% {trace, Pid, in, {M, F, Arity} | 0}
{in, [{M,F,Arity}]} ->
{"scheduled in for ~p:~p/~p", [M,F,Arity]};
{in, [0]} ->
{"scheduled in", []};
%% {trace, Pid, out, {M, F, Arity} | 0}
{out, [{M,F,Arity}]} ->
{"scheduled out from ~p:~p/~p", [M, F, Arity]};
{out, [0]} ->
{"scheduled out", []};
%% {trace, Pid, gc_start, Info}
{gc_start, [Info]} ->
HeapSize = proplists:get_value(heap_size, Info),
OldHeapSize = proplists:get_value(old_heap_size, Info),
MbufSize = proplists:get_value(mbuf_size, Info),
{"gc beginning -- heap ~p bytes",
[HeapSize + OldHeapSize + MbufSize]};
%% {trace, Pid, gc_end, Info}
{gc_end, [Info]} ->
HeapSize = proplists:get_value(heap_size, Info),
OldHeapSize = proplists:get_value(old_heap_size, Info),
MbufSize = proplists:get_value(mbuf_size, Info),
{"gc finished -- heap ~p bytes",
[HeapSize + OldHeapSize + MbufSize]};
_ ->
{"unknown trace type ~p -- ~p", [Type, TraceInfo]}
end,
io_lib:format("~n~p:~p:~9.6.0f ~p " ++ FormatStr ++ "~n",
[Hour, Min, Sec, Pid] ++ FormatArgs).
extract_info(TraceMsg) ->
case tuple_to_list(TraceMsg) of
[trace_ts, Pid, Type | Info] ->
{TraceInfo, [Timestamp]} = lists:split(length(Info)-1, Info),
{Type, Pid, to_hms(Timestamp), TraceInfo};
[trace, Pid, Type | TraceInfo] ->
{Type, Pid, to_hms(os:timestamp()), TraceInfo}
end.
to_hms(Stamp = {_, _, Micro}) ->
{_,{H, M, Secs}} = calendar:now_to_local_time(Stamp),
Seconds = Secs rem 60 + (Micro / 1000000),
{H,M,Seconds};
to_hms(_) ->
{0,0,0}.
format_args(Arity) when is_integer(Arity) ->
[$/, integer_to_list(Arity)];
format_args(Args) when is_list(Args) ->
[$(, join(", ", [format_trace_output(Arg) || Arg <- Args]), $)].
%% @doc formats call arguments and return values - most types are just printed out, except for
%% tuples recognised as records, which mimic the source code syntax
%% @end
format_trace_output(Args) ->
format_trace_output(recon_rec:is_active(), recon_map:is_active(), Args).
format_trace_output(Recs, Args) ->
format_trace_output(Recs, recon_map:is_active(), Args).
format_trace_output(true, _, Args) when is_tuple(Args) ->
recon_rec:format_tuple(Args);
format_trace_output(false, true, Args) when is_tuple(Args) ->
format_tuple(false, true, Args);
format_trace_output(Recs, Maps, Args) when is_list(Args), Recs orelse Maps ->
case io_lib:printable_list(Args) of
true ->
io_lib:format("~p", [Args]);
false ->
format_maybe_improper_list(Recs, Maps, Args)
end;
format_trace_output(Recs, true, Args) when is_map(Args) ->
{Label, Map} = case recon_map:process_map(Args) of
{L, M} -> {atom_to_list(L), M};
M -> {"", M}
end,
ItemList = maps:to_list(Map),
[Label,
"#{",
join(", ", [format_kv(Recs, true, Key, Val) || {Key, Val} <- ItemList]),
"}"];
format_trace_output(Recs, false, Args) when is_map(Args) ->
ItemList = maps:to_list(Args),
["#{",
join(", ", [format_kv(Recs, false, Key, Val) || {Key, Val} <- ItemList]),
"}"];
format_trace_output(_, _, Args) ->
io_lib:format("~p", [Args]).
format_kv(Recs, Maps, Key, Val) ->
[format_trace_output(Recs, Maps, Key), "=>", format_trace_output(Recs, Maps, Val)].
format_tuple(Recs, Maps, Tup) ->
[${ | format_tuple_(Recs, Maps, tuple_to_list(Tup))].
format_tuple_(_Recs, _Maps, []) ->
"}";
format_tuple_(Recs, Maps, [H|T]) ->
[format_trace_output(Recs, Maps, H), $,,
format_tuple_(Recs, Maps, T)].
format_maybe_improper_list(Recs, Maps, List) ->
[$[ | format_maybe_improper_list_(Recs, Maps, List)].
format_maybe_improper_list_(_, _, []) ->
"]";
format_maybe_improper_list_(Recs, Maps, [H|[]]) ->
[format_trace_output(Recs, Maps, H), $]];
format_maybe_improper_list_(Recs, Maps, [H|T]) when is_list(T) ->
[format_trace_output(Recs, Maps, H), $,,
format_maybe_improper_list_(Recs, Maps, T)];
format_maybe_improper_list_(Recs, Maps, [H|T]) when not is_list(T) ->
%% Handling improper lists
[format_trace_output(Recs, Maps, H), $|,
format_trace_output(Recs, Maps, T), $]].
%%%%%%%%%%%%%%%
%%% HELPERS %%%
%%%%%%%%%%%%%%%
maybe_kill(Name) ->
case whereis(Name) of
undefined ->
ok;
Pid ->
unlink(Pid),
exit(Pid, kill),
wait_for_death(Pid, Name)
end.
wait_for_death(Pid, Name) ->
case is_process_alive(Pid) orelse whereis(Name) =:= Pid of
true ->
timer:sleep(10),
wait_for_death(Pid, Name);
false ->
ok
end.
%% Borrowed from dbg
fun_to_ms(ShellFun) when is_function(ShellFun) ->
case erl_eval:fun_data(ShellFun) of
{fun_data,ImportList,Clauses} ->
case ms_transform:transform_from_shell(
dbg,Clauses,ImportList) of
{error,[{_,[{_,_,Code}|_]}|_],_} ->
io:format("Error: ~s~n",
[ms_transform:format_error(Code)]),
{error,transform_error};
Else ->
Else
end;
false ->
exit(shell_funs_only)
end.
-ifdef(OTP_RELEASE).
-spec join(term(), [term()]) -> [term()].
join(Sep, List) ->
lists:join(Sep, List).
-else.
-spec join(string(), [string()]) -> string().
join(Sep, List) ->
string:join(List, Sep).
-endif.
