Module recon_trace

recon_trace is a module that handles tracing in a safe manner for single Erlang nodes, currently for function calls only.

Authors: Fred Hebert (mononcqc@ferd.ca) [web site: http://ferd.ca/].

Description

recon_trace is a module that handles tracing in a safe manner for single Erlang nodes, currently for function calls only. Functionality includes:

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 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 ('_') 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 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 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.

Data Types

args()

args() = '_' | 0..255 | return_trace | matchspec() | shellfun()

fn()

fn() = '_' | atom()

formatterfun()

formatterfun() = fun((term()) -> iodata())

matchspec()

matchspec() = [{[term()], [term()], [term()]}]

max()

max() = max_traces() | max_rate()

max_rate()

max_rate() = {max_traces(), millisecs()}

max_traces()

max_traces() = non_neg_integer()

millisecs()

millisecs() = non_neg_integer()

mod()

mod() = '_' | module()

num_matches()

num_matches() = non_neg_integer()

options()

options() = [{pid, pidspec() | [pidspec(), ...]} | {timestamp, formatter | trace} | {args, args | arity} | {io_server, pid()} | {formatter, formatterfun()} | return_to | {return_to, boolean()} | {scope, global | local}]

pidspec()

pidspec() = all | existing | new | recon:pid_term()

shellfun()

shellfun() = fun((term()) -> term())

tspec()

tspec() = {mod(), fn(), args()}

Function Index

calls/2Equivalent to calls({Mod, Fun, Args}, Max, []).
calls/3Allows to set trace patterns and pid specifications to trace function calls.
clear/0Stops all tracing at once.
format/1
format_trace_output/1formats call arguments and return values - most types are just printed out, except for tuples recognised as records, which mimic the source code syntax.
format_trace_output/2

Function Details

calls/2

calls(TSpecs::tspec() | [tspec(), ...], Max::max()) -> num_matches()

Equivalent to calls({Mod, Fun, Args}, Max, []).

calls/3

calls(TSpecs::tspec() | [tspec(), ...], Max::max(), Opts::options()) -> num_matches()

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.

clear/0

clear() -> ok

Stops all tracing at once.

format/1

format(TraceMsg) -> any()

format_trace_output/1

format_trace_output(Args) -> any()

formats call arguments and return values - most types are just printed out, except for tuples recognised as records, which mimic the source code syntax

format_trace_output/2

format_trace_output(Recs, Args) -> any()


Generated by EDoc