NAME

DESCRIPTION

seq_trace provides functions that control all aspects of sequential tracing. There are functions for activation, deactivation, inspection, and for collection of the trace output.

DATA TYPES

token() = {integer(), boolean(), term(), term(), term()}

EXPORTS

set_token(Token) -> PreviousToken | ok

OldToken = seq_trace:set_token([]), % set to empty and save 
                                    % old value
% do something that should not be part of the trace
io:format("Exclude the signalling caused by this~n"),
seq_trace:set_token(OldToken), % activate the trace token again

set_token(Component, Val) -> OldVal

component() = label | serial | flag()

flag() = 
    send | 'receive' | print | timestamp | monotonic_timestamp |
    strict_monotonic_timestamp

value() = 
    (Label :: term()) |
    {Previous :: integer() >= 0, Current :: integer() >= 0} |
    (Bool :: boolean())

get_token() -> [] | token()

get_token(Component) -> {Component, Val}

component() = label | serial | flag()

flag() = 
    send | 'receive' | print | timestamp | monotonic_timestamp |
    strict_monotonic_timestamp

value() = 
    (Label :: term()) |
    {Previous :: integer() >= 0, Current :: integer() >= 0} |
    (Bool :: boolean())

print(TraceInfo) -> ok

print(Label, TraceInfo) -> ok

reset_trace() -> true

set_system_tracer(Tracer) -> OldTracer

tracer() = 
    (Pid :: pid()) |
    port() |
    (TracerModule :: {module(), term()}) |
    false

get_system_tracer() -> Tracer

tracer() = 
    (Pid :: pid()) |
    port() |
    (TracerModule :: {module(), term()}) |
    false

TRACE MESSAGES SENT TO THE SYSTEM TRACER

{seq_trace, Label, SeqTraceInfo, TimeStamp}

or

{seq_trace, Label, SeqTraceInfo}

Where:

Label = int()
TimeStamp = {Seconds, Milliseconds, Microseconds}  
  Seconds = Milliseconds = Microseconds = int()

SeqTraceInfo can have the following formats:

Serial is a tuple {PreviousSerial, ThisSerial}, where:

SEQUENTIAL TRACING

Each process has a trace token, which can be empty or not empty. When not empty, the trace token can be seen as the tuple {Label, Flags, Serial, From}. The trace token is passed invisibly when information is passed between processes. In most cases the information is passed in ordinary messages between processes, but information is also passed between processes by other means. For example, by spawning a new process. An information transfer between two processes is represented by a send event and a receive event regardless of how it is passed.

To start a sequential trace, the user must explicitly set the trace token in the process that will send the first information in a sequence.

The trace token of a process is set each time the process receives information. This is typically when the process matches a message in a receive statement, according to the trace token carried by the received message, empty or not.

On each Erlang node, a process can be set as the system tracer. This process will receive trace messages each time information with a trace token is sent or received (if the trace token flag send or 'receive' is set). The system tracer can then print each trace event, write it to a file, or whatever suitable.

The following sections describe sequential tracing and its most fundamental concepts.

DIFFERENT INFORMATION TRANSFERS

TRACE TOKEN

The current token of a process is set in one of the following two ways:

In both cases, the current token is set. In particular, if the token of a received message is empty, the current token of the process is set to empty.

A trace token contains a label and a set of flags. Both the label and the flags are set in both alternatives above.

SERIAL

The algorithm for updating Serial can be described as follows:

Let each process have two counters, prev_cnt and curr_cnt, both are set to 0 when a process is created outside of a trace sequence. The counters are updated at the following occasions:

curr_cnt := curr_cnt + 1
tprev := prev_cnt
tcurr := curr_cnt

if (curr_cnt < tcurr )
   curr_cnt := tcurr
prev_cnt := tcurr

curr_cnt of a process is incremented each time the process is involved in a sequential trace. The counter can reach its limit (27 bits) if a process is very long-lived and is involved in much sequential tracing. If the counter overflows, the serial for ordering of the trace events cannot be used. To prevent the counter from overflowing in the middle of a sequential trace, function seq_trace:reset_trace/0 can be called to reset prev_cnt and curr_cnt of all processes in the Erlang node. This function also sets all trace tokens in processes and their message queues to empty, and thus stops all ongoing sequential tracing.

PERFORMANCE CONSIDERATIONS

PORTS

If the user for some reason wants to pass the trace token to a port, this must be done manually in the code of the port controlling process. The port controlling processes have to check the appropriate sequential trace settings (as obtained from seq_trace:get_token/1) and include trace information in the message data sent to their respective ports.

Similarly, for messages received from a port, a port controller has to retrieve trace-specific information, and set appropriate sequential trace flags through calls to seq_trace:set_token/2.

DISTRIBUTION

EXAMPLE OF USE

Assume that you have an initiating process with Pid == <0.30.0> like this:

-module(seqex).
-compile(export_all).
loop(Port) ->
    receive 
        {Port,Message} ->
            seq_trace:set_token(label,17),
            seq_trace:set_token('receive',true),
            seq_trace:set_token(print,true),
            seq_trace:print(17,"**** Trace Started ****"),
            call_server ! {self(),the_message};
        {ack,Ack} ->
            ok
    end,
    loop(Port).

And a registered process call_server with Pid == <0.31.0> like this:

loop() ->
    receive
        {PortController,Message} ->
            Ack = {received, Message},
            seq_trace:print(17,"We are here now"),
            PortController ! {ack,Ack}
    end,
    loop().

A possible output from the system's sequential_tracer can be like this:

17:<0.30.0> Info {0,1} WITH
"**** Trace Started ****"
17:<0.31.0> Received {0,2} FROM <0.30.0> WITH
{<0.30.0>,the_message}
17:<0.31.0> Info {2,3} WITH
"We are here now"
17:<0.30.0> Received {2,4} FROM <0.31.0> WITH
{ack,{received,the_message}}

The implementation of a system tracer process that produces this printout can look like this:

tracer() ->
    receive
        {seq_trace,Label,TraceInfo} ->
           print_trace(Label,TraceInfo,false);
        {seq_trace,Label,TraceInfo,Ts} ->
           print_trace(Label,TraceInfo,Ts);
        _Other -> ignore
    end,
    tracer().
print_trace(Label,TraceInfo,false) ->
    io:format("~p:",[Label]),
    print_trace(TraceInfo);
print_trace(Label,TraceInfo,Ts) ->
    io:format("~p ~p:",[Label,Ts]),
    print_trace(TraceInfo).
print_trace({print,Serial,From,_,Info}) ->
    io:format("~p Info ~p WITH~n~p~n", [From,Serial,Info]);
print_trace({'receive',Serial,From,To,Message}) ->
    io:format("~p Received ~p FROM ~p WITH~n~p~n", 
              [To,Serial,From,Message]);
print_trace({send,Serial,From,To,Message}) ->
    io:format("~p Sent ~p TO ~p WITH~n~p~n",
              [From,Serial,To,Message]).

The code that creates a process that runs this tracer function and sets that process as the system tracer can look like this:

start() ->
    Pid = spawn(?MODULE,tracer,[]),
    seq_trace:set_system_tracer(Pid), % set Pid as the system tracer 
    ok.

With a function like test/0, the whole example can be started:

test() ->
    P = spawn(?MODULE, loop, [port]),
    register(call_server, spawn(?MODULE, loop, [])),
    start(),
    P ! {port,message}.