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

TRACE MESSAGES SENT TO THE SYSTEM TRACER

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

SEQUENTIAL TRACING

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

TRACE TOKEN

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

SERIAL

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

PERFORMANCE CONSIDERATIONS

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

PORTS

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

DISTRIBUTION

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

EXAMPLE OF USE

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