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

NAME

6       seq_trace - Sequential tracing of information transfers.
7

DESCRIPTION

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

DATA TYPES

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

EXPORTS

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

TRACE MESSAGES SENT TO THE SYSTEM TRACER

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

SEQUENTIAL TRACING

261       Sequential  tracing  is a way to trace a sequence of information trans‐
262       fers between different local or remote processes, where the sequence is
263       initiated  by a single transfer. The typical information transfer is an
264       ordinary Erlang message passed between two processes,  but  information
265       is transferred also in other ways. In short, it works as follows:
266
267       Each  process  has a trace token, which can be empty or not empty. When
268       not empty, the trace token can be seen as the tuple {Label, Flags,  Se‐
269       rial,  From}.  The  trace token is passed invisibly when information is
270       passed between processes. In most cases the information  is  passed  in
271       ordinary messages between processes, but information is also passed be‐
272       tween processes by other means. For example, by spawning a new process.
273       An  information transfer between two processes is represented by a send
274       event and a receive event regardless of how it is passed.
275
276       To start a sequential trace, the user must explicitly set the trace to‐
277       ken in the process that will send the first information in a sequence.
278
279       The  trace token of a process is set each time the process receives in‐
280       formation. This is typically when the process matches a  message  in  a
281       receive statement, according to the trace token carried by the received
282       message, empty or not.
283
284       On each Erlang node, a process can be set as the  system  tracer.  This
285       process  will receive trace messages each time information with a trace
286       token is sent or received (if the trace token flag send or 'receive' is
287       set).  The system tracer can then print each trace event, write it to a
288       file, or whatever suitable.
289
290   Note:
291       The system tracer only receives those trace events that  occur  locally
292       within the Erlang node. To get the whole picture of a sequential trace,
293       involving processes on many Erlang nodes, the output  from  the  system
294       tracer on each involved node must be merged (offline).
295
296
297       The  following sections describe sequential tracing and its most funda‐
298       mental concepts.
299

DIFFERENT INFORMATION TRANSFERS

301       Information flows between processes in a lot of different ways. Not all
302       flows of information will be covered by sequential tracing. One example
303       is information passed via ETS tables. Below is a  list  of  information
304       paths that are covered by sequential tracing:
305
306         Message Passing:
307           All ordinary messages passed between Erlang processes.
308
309         Exit signals:
310           An exit signal is represented as an {'EXIT', Pid, Reason} tuple.
311
312         Process Spawn:
313           A  process  spawn is represented as multiple information transfers.
314           At least one spawn request and one spawn reply. The  actual  amount
315           of  information  transfers  depends on what type of spawn it is and
316           may also change in future implementations. Note that this  is  more
317           or less an internal protocol that you are peeking at. The spawn re‐
318           quest will be represented as a tuple with the  first  element  con‐
319           taining  the  atom spawn_request, but this is more or less all that
320           you can depend on.
321
322   Note:
323       If you do ordinary send or receive trace on the system, you  will  only
324       see  ordinary  message  passing,  not  the  other information transfers
325       listed above.
326
327
328   Note:
329       When a send event and corresponding receive event do  not  both  corre‐
330       spond  to  ordinary Erlang messages, the Message part of the trace mes‐
331       sages may not be identical. This since all information not  necessarily
332       are available when generating the trace messages.
333
334

TRACE TOKEN

336       Each process has a current trace token which is "invisibly" passed from
337       the parent process on creation of the process.
338
339       The current token of a process is set in one of the following two ways:
340
341         * Explicitly   by   the   process   itself,   through   a   call   to
342           seq_trace:set_token/1,2
343
344         * When  information  is  received.  This is typically when a received
345           message is matched out in a receive expression, but also  when  in‐
346           formation is received in other ways.
347
348       In both cases, the current token is set. In particular, if the token of
349       a received message is empty, the current token of the process is set to
350       empty.
351
352       A  trace  token contains a label and a set of flags. Both the label and
353       the flags are set in both alternatives above.
354

SERIAL

356       The trace token contains a component called serial. It consists of  two
357       integers,  Previous  and  Current.  The purpose is to uniquely identify
358       each traced event within a trace sequence, as well as to order the mes‐
359       sages chronologically and in the different branches, if any.
360
361       The algorithm for updating Serial can be described as follows:
362
363       Let each process have two counters, prev_cnt and curr_cnt, both are set
364       to 0 when a process is created outside of a trace sequence.  The  coun‐
365       ters are updated at the following occasions:
366
367         * When  the  process  is  about  to pass along information to another
368           process and the trace token is not  empty.  This  typically  occurs
369           when  sending  a  message, but also, for example, when spawning an‐
370           other process.
371
372           Let the serial of the trace token be tprev and tcurr.
373
374         curr_cnt := curr_cnt + 1
375         tprev := prev_cnt
376         tcurr := curr_cnt
377
378           The trace token with tprev and tcurr is then passed along with  the
379           information passed to the other process.
380
381         * When  the process calls seq_trace:print(Label, Info), Label matches
382           the label part of the trace token and the trace token print flag is
383           true.
384
385           The algorithm is the same as for send above.
386
387         * When  information  is received that also contains a non-empty trace
388           token. For example, when a message is matched out in a receive  ex‐
389           pression, or when a new process is spawned.
390
391           The process trace token is set to the trace token from the message.
392
393           Let the serial of the trace token be tprev and tcurr.
394
395         if (curr_cnt < tcurr )
396            curr_cnt := tcurr
397         prev_cnt := tcurr
398
399       curr_cnt  of a process is incremented each time the process is involved
400       in a sequential trace. The counter can reach its limit (27 bits)  if  a
401       process  is very long-lived and is involved in much sequential tracing.
402       If the counter overflows, the serial for ordering of the  trace  events
403       cannot  be  used. To prevent the counter from overflowing in the middle
404       of a sequential trace, function seq_trace:reset_trace/0 can  be  called
405       to  reset  prev_cnt  and  curr_cnt of all processes in the Erlang node.
406       This function also sets all trace tokens in processes and their message
407       queues to empty, and thus stops all ongoing sequential tracing.
408

PERFORMANCE CONSIDERATIONS

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

PORTS

416       Sequential tracing is not performed across ports.
417
418       If the user for some reason wants to pass the trace token  to  a  port,
419       this must be done manually in the code of the port controlling process.
420       The port controlling processes have to check the appropriate sequential
421       trace  settings  (as  obtained  from seq_trace:get_token/1) and include
422       trace information in the message data sent to their respective ports.
423
424       Similarly, for messages received from a port, a port controller has  to
425       retrieve  trace-specific  information,  and  set appropriate sequential
426       trace flags through calls to seq_trace:set_token/2.
427

DISTRIBUTION

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

EXAMPLE OF USE

435       This  example  gives a rough idea of how the new primitives can be used
436       and what kind of output it produces.
437
438       Assume that you have an initiating process with Pid  ==  <0.30.0>  like
439       this:
440
441       -module(seqex).
442       -compile(export_all).
443
444       loop(Port) ->
445           receive
446               {Port,Message} ->
447                   seq_trace:set_token(label,17),
448                   seq_trace:set_token('receive',true),
449                   seq_trace:set_token(print,true),
450                   seq_trace:print(17,"**** Trace Started ****"),
451                   call_server ! {self(),the_message};
452               {ack,Ack} ->
453                   ok
454           end,
455           loop(Port).
456
457       And a registered process call_server with Pid == <0.31.0> like this:
458
459       loop() ->
460           receive
461               {PortController,Message} ->
462                   Ack = {received, Message},
463                   seq_trace:print(17,"We are here now"),
464                   PortController ! {ack,Ack}
465           end,
466           loop().
467
468       A possible output from the system's sequential_tracer can be like this:
469
470       17:<0.30.0> Info {0,1} WITH
471       "**** Trace Started ****"
472       17:<0.31.0> Received {0,2} FROM <0.30.0> WITH
473       {<0.30.0>,the_message}
474       17:<0.31.0> Info {2,3} WITH
475       "We are here now"
476       17:<0.30.0> Received {2,4} FROM <0.31.0> WITH
477       {ack,{received,the_message}}
478
479       The implementation of a system tracer process that produces this print‐
480       out can look like this:
481
482       tracer() ->
483           receive
484               {seq_trace,Label,TraceInfo} ->
485                  print_trace(Label,TraceInfo,false);
486               {seq_trace,Label,TraceInfo,Ts} ->
487                  print_trace(Label,TraceInfo,Ts);
488               _Other -> ignore
489           end,
490           tracer().
491
492       print_trace(Label,TraceInfo,false) ->
493           io:format("~p:",[Label]),
494           print_trace(TraceInfo);
495       print_trace(Label,TraceInfo,Ts) ->
496           io:format("~p ~p:",[Label,Ts]),
497           print_trace(TraceInfo).
498
499       print_trace({print,Serial,From,_,Info}) ->
500           io:format("~p Info ~p WITH~n~p~n", [From,Serial,Info]);
501       print_trace({'receive',Serial,From,To,Message}) ->
502           io:format("~p Received ~p FROM ~p WITH~n~p~n",
503                     [To,Serial,From,Message]);
504       print_trace({send,Serial,From,To,Message}) ->
505           io:format("~p Sent ~p TO ~p WITH~n~p~n",
506                     [From,Serial,To,Message]).
507
508       The code that creates a process that runs this tracer function and sets
509       that process as the system tracer can look like this:
510
511       start() ->
512           Pid = spawn(?MODULE,tracer,[]),
513           seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
514           ok.
515
516       With a function like test/0, the whole example can be started:
517
518       test() ->
519           P = spawn(?MODULE, loop, [port]),
520           register(call_server, spawn(?MODULE, loop, [])),
521           start(),
522           P ! {port,message}.
523
524
525
526Ericsson AB                      kernel 8.3.2                     seq_trace(3)
Impressum