1seq_trace(3)               Erlang Module Definition               seq_trace(3)
2
3
4

NAME

6       seq_trace - Sequential tracing of messages.
7

DESCRIPTION

9       Sequential  tracing  makes  it possible to trace all messages resulting
10       from one initial message. Sequential  tracing  is  independent  of  the
11       ordinary  tracing  in Erlang, which is controlled by the erlang:trace/3
12       BIF. For more information about what sequential tracing is and  how  it
13       can be used, see section Sequential Tracing.
14
15       seq_trace  provides  functions  that  control all aspects of sequential
16       tracing. There are functions for activation, deactivation,  inspection,
17       and for collection of the trace output.
18

DATA TYPES

20       token() = {integer(), boolean(), term(), term(), term()}
21
22              An opaque term (a tuple) representing a trace token.
23

EXPORTS

25       set_token(Token) -> PreviousToken | ok
26
27              Types:
28
29                 Token = PreviousToken = [] | token()
30
31              Sets  the trace token for the calling process to Token. If Token
32              == [] then tracing is disabled, otherwise  Token  should  be  an
33              Erlang   term   returned   from   get_token/0   or  set_token/1.
34              set_token/1 can be used to temporarily exclude  message  passing
35              from the trace by setting the trace token to empty like this:
36
37              OldToken = seq_trace:set_token([]), % set to empty and save
38                                                  % old value
39              % do something that should not be part of the trace
40              io:format("Exclude the signalling caused by this~n"),
41              seq_trace:set_token(OldToken), % activate the trace token again
42
43              Returns the previous value of the trace token.
44
45       set_token(Component, Val) -> OldVal
46
47              Types:
48
49                 Component = component()
50                 Val = OldVal = value()
51                 component() = label | serial | flag()
52                 flag() =
53                     send | 'receive' | print | timestamp | monotonic_timestamp |
54                     strict_monotonic_timestamp
55                 value() =
56                     (Label :: term()) |
57                     {Previous :: integer() >= 0, Current :: integer() >= 0} |
58                     (Bool :: boolean())
59
60              Sets the individual Component of the trace token to Val. Returns
61              the previous value of the component.
62
63                set_token(label, Label):
64                  The label component is a term which  identifies  all  events
65                  belonging  to  the same sequential trace. If several sequen‐
66                  tial traces can be active simultaneously, label is  used  to
67                  identify the separate traces. Default is 0.
68
69            Warning:
70                Labels  were  restricted  to  small  signed integers (28 bits)
71                prior to OTP 21. The trace token will be silenty dropped if it
72                crosses over to a node that does not support the label.
73
74
75                set_token(serial, SerialValue):
76                  SerialValue = {Previous, Current}. The serial component con‐
77                  tains counters which  enables  the  traced  messages  to  be
78                  sorted,  should never be set explicitly by the user as these
79                  counters are updated automatically. Default is {0, 0}.
80
81                set_token(send, Bool):
82                  A trace token flag (true  |  false)  which  enables/disables
83                  tracing on message sending. Default is false.
84
85                set_token('receive', Bool):
86                  A  trace  token  flag  (true | false) which enables/disables
87                  tracing on message reception. Default is false.
88
89                set_token(print, Bool):
90                  A trace token flag (true  |  false)  which  enables/disables
91                  tracing  on  explicit calls to seq_trace:print/1. Default is
92                  false.
93
94                set_token(timestamp, Bool):
95                  A trace token flag (true | false) which  enables/disables  a
96                  timestamp  to be generated for each traced event. Default is
97                  false.
98
99                set_token(strict_monotonic_timestamp, Bool):
100                  A trace token flag (true | false) which  enables/disables  a
101                  strict  monotonic  timestamp to be generated for each traced
102                  event. Default is false. Timestamps will consist  of  Erlang
103                  monotonic  time  and a monotonically increasing integer. The
104                  time-stamp has the same format  and  value  as  produced  by
105                  {erlang:monotonic_time(nanosecond),      erlang:unique_inte‐
106                  ger([monotonic])}.
107
108                set_token(monotonic_timestamp, Bool):
109                  A trace token flag (true | false) which  enables/disables  a
110                  strict  monotonic  timestamp to be generated for each traced
111                  event. Default is false. Timestamps will  use  Erlang  mono‐
112                  tonic  time. The time-stamp has the same format and value as
113                  produced by erlang:monotonic_time(nanosecond).
114
115              If multiple timestamp flags are passed, timestamp has precedence
116              over  strict_monotonic_timestamp  which  in  turn has precedence
117              over monotonic_timestamp. All timestamp flags are remembered, so
118              if  two  are passed and the one with highest precedence later is
119              disabled the other one will become active.
120
121       get_token() -> [] | token()
122
123              Returns the value of the trace token for the calling process. If
124              []  is  returned, it means that tracing is not active. Any other
125              value returned is the value of an active trace token. The  value
126              returned can be used as input to the set_token/1 function.
127
128       get_token(Component) -> {Component, Val}
129
130              Types:
131
132                 Component = component()
133                 Val = value()
134                 component() = label | serial | flag()
135                 flag() =
136                     send | 'receive' | print | timestamp | monotonic_timestamp |
137                     strict_monotonic_timestamp
138                 value() =
139                     (Label :: term()) |
140                     {Previous :: integer() >= 0, Current :: integer() >= 0} |
141                     (Bool :: boolean())
142
143              Returns  the  value  of the trace token component Component. See
144              set_token/2 for possible values of Component and Val.
145
146       print(TraceInfo) -> ok
147
148              Types:
149
150                 TraceInfo = term()
151
152              Puts the Erlang term TraceInfo into the sequential trace  output
153              if  the  calling process currently is executing within a sequen‐
154              tial trace and the print flag of the trace token is set.
155
156       print(Label, TraceInfo) -> ok
157
158              Types:
159
160                 Label = integer()
161                 TraceInfo = term()
162
163              Same as print/1 with the additional condition that TraceInfo  is
164              output  only  if  Label  is  equal to the label component of the
165              trace token.
166
167       reset_trace() -> true
168
169              Sets the trace token to empty for all  processes  on  the  local
170              node. The process internal counters used to create the serial of
171              the trace token is set to 0. The trace token is set to empty for
172              all  messages  in message queues. Together this will effectively
173              stop all ongoing sequential tracing in the local node.
174
175       set_system_tracer(Tracer) -> OldTracer
176
177              Types:
178
179                 Tracer = OldTracer = tracer()
180                 tracer() =
181                     (Pid :: pid()) |
182                     port() |
183                     (TracerModule :: {module(), term()}) |
184                     false
185
186              Sets the system tracer.  The  system  tracer  can  be  either  a
187              process,  port  or  tracer module denoted by Tracer. Returns the
188              previous value (which can  be  false  if  no  system  tracer  is
189              active).
190
191              Failure: {badarg, Info}} if Pid is not an existing local pid.
192
193       get_system_tracer() -> Tracer
194
195              Types:
196
197                 Tracer = tracer()
198                 tracer() =
199                     (Pid :: pid()) |
200                     port() |
201                     (TracerModule :: {module(), term()}) |
202                     false
203
204              Returns the pid, port identifier or tracer module of the current
205              system tracer or false if no system tracer is activated.
206

TRACE MESSAGES SENT TO THE SYSTEM TRACER

208       The format of the messages is one of the  following,  depending  on  if
209       flag timestamp of the trace token is set to true or false:
210
211       {seq_trace, Label, SeqTraceInfo, TimeStamp}
212
213       or
214
215       {seq_trace, Label, SeqTraceInfo}
216
217       Where:
218
219       Label = int()
220       TimeStamp = {Seconds, Milliseconds, Microseconds}
221         Seconds = Milliseconds = Microseconds = int()
222
223       SeqTraceInfo can have the following formats:
224
225         {send, Serial, From, To, Message}:
226           Used when a process From with its trace token flag send set to true
227           has sent a message.
228
229         {'receive', Serial, From, To, Message}:
230           Used when a process To receives a message with a trace  token  that
231           has flag 'receive' set to true.
232
233         {print, Serial, From, _, Info}:
234           Used  when  a process From has called seq_trace:print(Label, Trace‐
235           Info) and has a trace token with flag print set to true, and  label
236           set to Label.
237
238       Serial is a tuple {PreviousSerial, ThisSerial}, where:
239
240         * Integer  PreviousSerial  denotes  the  serial counter passed in the
241           last received message that carried a trace token. If the process is
242           the  first  in a new sequential trace, PreviousSerial is set to the
243           value of the process internal "trace clock".
244
245         * Integer ThisSerial is the serial counter that  a  process  sets  on
246           outgoing  messages.  It  is  based  on  the process internal "trace
247           clock", which is incremented by one before it is  attached  to  the
248           trace token in the message.
249

SEQUENTIAL TRACING

251       Sequential  tracing  is  a  way  to  trace  a sequence of messages sent
252       between different local or remote processes, where the sequence is ini‐
253       tiated by a single message. In short, it works as follows:
254
255       Each  process  has a trace token, which can be empty or not empty. When
256       not empty, the trace token can be seen  as  the  tuple  {Label,  Flags,
257       Serial, From}. The trace token is passed invisibly with each message.
258
259       To  start  a  sequential  trace, the user must explicitly set the trace
260       token in the process that will send the first message in a sequence.
261
262       The trace token of a process is set each time  the  process  matches  a
263       message in a receive statement, according to the trace token carried by
264       the received message, empty or not.
265
266       On each Erlang node, a process can be set as the  system  tracer.  This
267       process  will  receive  trace messages each time a message with a trace
268       token is sent or received (if the trace token flag send or 'receive' is
269       set).  The system tracer can then print each trace event, write it to a
270       file, or whatever suitable.
271
272   Note:
273       The system tracer only receives those trace events that  occur  locally
274       within the Erlang node. To get the whole picture of a sequential trace,
275       involving processes on many Erlang nodes, the output  from  the  system
276       tracer on each involved node must be merged (offline).
277
278
279       The  following sections describe sequential tracing and its most funda‐
280       mental concepts.
281

TRACE TOKEN

283       Each process has a current trace token. Initially, the token is  empty.
284       When the process sends a message to another process, a copy of the cur‐
285       rent token is sent "invisibly" along with the message.
286
287       The current token of a process is set in one of the following two ways:
288
289         * Explicitly   by   the   process   itself,   through   a   call   to
290           seq_trace:set_token/1,2
291
292         * When a message is received
293
294       In both cases, the current token is set. In particular, if the token of
295       a received message is empty, the current token of the process is set to
296       empty.
297
298       A  trace  token contains a label and a set of flags. Both the label and
299       the flags are set in both alternatives above.
300

SERIAL

302       The trace token contains a component called serial. It consists of  two
303       integers,  Previous  and  Current.  The purpose is to uniquely identify
304       each traced event within a trace sequence, as well as to order the mes‐
305       sages chronologically and in the different branches, if any.
306
307       The algorithm for updating Serial can be described as follows:
308
309       Let each process have two counters, prev_cnt and curr_cnt, both are set
310       to 0 when a process is created. The counters are updated at the follow‐
311       ing occasions:
312
313         * When  the process is about to send a message and the trace token is
314           not empty.
315
316           Let the serial of the trace token be tprev and tcurr.
317
318         curr_cnt := curr_cnt + 1
319         tprev := prev_cnt
320         tcurr := curr_cnt
321
322           The trace token with tprev and tcurr is then passed along with  the
323           message.
324
325         * When  the process calls seq_trace:print(Label, Info), Label matches
326           the label part of the trace token and the trace token print flag is
327           true.
328
329           The algorithm is the same as for send above.
330
331         * When a message is received and contains a non-empty trace token.
332
333           The process trace token is set to the trace token from the message.
334
335           Let the serial of the trace token be tprev and tcurr.
336
337         if (curr_cnt < tcurr )
338            curr_cnt := tcurr
339         prev_cnt := tcurr
340
341       curr_cnt  of a process is incremented each time the process is involved
342       in a sequential trace. The counter can reach its limit (27 bits)  if  a
343       process  is very long-lived and is involved in much sequential tracing.
344       If the counter overflows, the serial for ordering of the  trace  events
345       cannot  be  used. To prevent the counter from overflowing in the middle
346       of a sequential trace, function seq_trace:reset_trace/0 can  be  called
347       to  reset  prev_cnt  and  curr_cnt of all processes in the Erlang node.
348       This function also sets all trace tokens in processes and their message
349       queues to empty, and thus stops all ongoing sequential tracing.
350

PERFORMANCE CONSIDERATIONS

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

PORTS

358       Sequential tracing is not performed across ports.
359
360       If the user for some reason wants to pass the trace token  to  a  port,
361       this must be done manually in the code of the port controlling process.
362       The port controlling processes have to check the appropriate sequential
363       trace  settings  (as  obtained  from seq_trace:get_token/1) and include
364       trace information in the message data sent to their respective ports.
365
366       Similarly, for messages received from a port, a port controller has  to
367       retrieve  trace-specific  information,  and  set appropriate sequential
368       trace flags through calls to seq_trace:set_token/2.
369

DISTRIBUTION

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

EXAMPLE OF USE

377       This  example  gives a rough idea of how the new primitives can be used
378       and what kind of output it produces.
379
380       Assume that you have an initiating process with Pid  ==  <0.30.0>  like
381       this:
382
383       -module(seqex).
384       -compile(export_all).
385
386       loop(Port) ->
387           receive
388               {Port,Message} ->
389                   seq_trace:set_token(label,17),
390                   seq_trace:set_token('receive',true),
391                   seq_trace:set_token(print,true),
392                   seq_trace:print(17,"**** Trace Started ****"),
393                   call_server ! {self(),the_message};
394               {ack,Ack} ->
395                   ok
396           end,
397           loop(Port).
398
399       And a registered process call_server with Pid == <0.31.0> like this:
400
401       loop() ->
402           receive
403               {PortController,Message} ->
404                   Ack = {received, Message},
405                   seq_trace:print(17,"We are here now"),
406                   PortController ! {ack,Ack}
407           end,
408           loop().
409
410       A possible output from the system's sequential_tracer can be like this:
411
412       17:<0.30.0> Info {0,1} WITH
413       "**** Trace Started ****"
414       17:<0.31.0> Received {0,2} FROM <0.30.0> WITH
415       {<0.30.0>,the_message}
416       17:<0.31.0> Info {2,3} WITH
417       "We are here now"
418       17:<0.30.0> Received {2,4} FROM <0.31.0> WITH
419       {ack,{received,the_message}}
420
421       The implementation of a system tracer process that produces this print‐
422       out can look like this:
423
424       tracer() ->
425           receive
426               {seq_trace,Label,TraceInfo} ->
427                  print_trace(Label,TraceInfo,false);
428               {seq_trace,Label,TraceInfo,Ts} ->
429                  print_trace(Label,TraceInfo,Ts);
430               Other -> ignore
431           end,
432           tracer().
433
434       print_trace(Label,TraceInfo,false) ->
435           io:format("~p:",[Label]),
436           print_trace(TraceInfo);
437       print_trace(Label,TraceInfo,Ts) ->
438           io:format("~p ~p:",[Label,Ts]),
439           print_trace(TraceInfo).
440
441       print_trace({print,Serial,From,_,Info}) ->
442           io:format("~p Info ~p WITH~n~p~n", [From,Serial,Info]);
443       print_trace({'receive',Serial,From,To,Message}) ->
444           io:format("~p Received ~p FROM ~p WITH~n~p~n",
445                     [To,Serial,From,Message]);
446       print_trace({send,Serial,From,To,Message}) ->
447           io:format("~p Sent ~p TO ~p WITH~n~p~n",
448                     [From,Serial,To,Message]).
449
450       The code that creates a process that runs this tracer function and sets
451       that process as the system tracer can look like this:
452
453       start() ->
454           Pid = spawn(?MODULE,tracer,[]),
455           seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
456           ok.
457
458       With a function like test/0, the whole example can be started:
459
460       test() ->
461           P = spawn(?MODULE, loop, [port]),
462           register(call_server, spawn(?MODULE, loop, [])),
463           start(),
464           P ! {port,message}.
465
466
467
468Ericsson AB                      kernel 6.5.2                     seq_trace(3)
Impressum