seq_trace

The format of the messages is one of the following, depending on if flag timestamp of the trace token is set to true or false:

{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:

{send, Serial, From, To, Message}

Used when a process From with its trace token flag send set to true has sent information. To may be a process identifier, a registered name on a node represented as {NameAtom, NodeAtom}, or a node name represented as an atom. From may be a process identifier or a node name represented as an atom. Message contains the information passed along in this information transfer. If the transfer is done via message passing, it is the actual message.

{'receive', Serial, From, To, Message}

Used when a process To receives information with a trace token that has flag 'receive' set to true. To may be a process identifier, or a node name represented as an atom. From may be a process identifier or a node name represented as an atom. Message contains the information passed along in this information transfer. If the transfer is done via message passing, it is the actual message.

{print, Serial, From, _, Info}

Used when a process From has called seq_trace:print(Label, TraceInfo) and has a trace token with flag print set to true, and label set to Label.

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

• Integer PreviousSerial denotes the serial counter passed in the last received information that carried a trace token. If the process is the first in a new sequential trace, PreviousSerial is set to the value of the process internal "trace clock".

• Integer ThisSerial is the serial counter that a process sets on outgoing messages. It is based on the process internal "trace clock", which is incremented by one before it is attached to the trace token in the message.

Sequential tracing is a way to trace a sequence of information transfers between different local or remote processes, where the sequence is initiated by a single transfer. The typical information transfer is an ordinary Erlang message passed between two processes, but information is transferred also in other ways. In short, it works as follows:

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.

Information flows between processes in a lot of different ways. Not all flows of information will be covered by sequential tracing. One example is information passed via ETS tables. Below is a list of information paths that are covered by sequential tracing:

Message Passing

All ordinary messages passed between Erlang processes.

Exit signals

An exit signal is represented as an {'EXIT', Pid, Reason} tuple.

Process Spawn

A process spawn is represented as multiple information transfers. At least one spawn request and one spawn reply. The actual amount of information transfers depends on what type of spawn it is and may also change in future implementations. Note that this is more or less an internal protocol that you are peeking at. The spawn request will be represented as a tuple with the first element containing the atom spawn_request, but this is more or less all that you can depend on.

Each process has a current trace token which is "invisibly" passed from the parent process on creation of the process.

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

• Explicitly by the process itself, through a call to seq_trace:set_token/1,2

• When information is received. This is typically when a received message is matched out in a receive expression, but also when information is received in other 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.

The trace token contains a component called serial. It consists of two integers, Previous and Current. The purpose is to uniquely identify each traced event within a trace sequence, as well as to order the messages chronologically and in the different branches, if any.

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:

• When the process is about to pass along information to another process and the trace token is not empty. This typically occurs when sending a message, but also, for example, when spawning another process.

  Let the serial of the trace token be tprev and tcurr.

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

  The trace token with tprev and tcurr is then passed along with the information passed to the other process.

• When the process calls seq_trace:print(Label, Info), Label matches the label part of the trace token and the trace token print flag is true.

  The algorithm is the same as for send above.

• When information is received that also contains a non-empty trace token. For example, when a message is matched out in a receive expression, or when a new process is spawned.

  The process trace token is set to the trace token from the message.

  Let the serial of the trace token be tprev and tcurr.

  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.

The performance degradation for a system that is enabled for sequential tracing is negligible as long as no tracing is activated. When tracing is activated, there is an extra cost for each traced message, but all other messages are unaffected.

Sequential tracing is not performed across 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.

Sequential tracing between nodes is performed transparently. This applies to C-nodes built with Erl_Interface too. A C-node built with Erl_Interface only maintains one trace token, which means that the C-node appears as one process from the sequential tracing point of view.

This example gives a rough idea of how the new primitives can be used and what kind of output it produces.

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}.