1seq_trace(3) Erlang Module Definition seq_trace(3)
2
6 seq_trace - Sequential tracing of information transfers.
7
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 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
21 token() = {integer(), boolean(), term(), term(), term()}
22 An opaque term (a tuple) representing a trace token.
24
26 set_token(Token) -> PreviousToken | ok
27 Types:
29 Token = PreviousToken = [] | token()
31 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 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 Returns the previous value of the trace token.
45 set_token(Component, Val) -> OldVal
47 Types:
49 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 Sets the individual Component of the trace token to Val. Returns
62 the previous value of the component.
63 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 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 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 set_token(send, Bool):
83 A trace token flag (true | false) which enables/disables
84 tracing on information sending. Default is false.
85 set_token('receive', Bool):
87 A trace token flag (true | false) which enables/disables
88 tracing on information reception. Default is false.
89 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 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 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 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 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 get_token() -> [] | token()
123 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 get_token(Component) -> {Component, Val}
130 Types:
132 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 Returns the value of the trace token component Component. See
145 set_token/2 for possible values of Component and Val.
146 print(TraceInfo) -> ok
148 Types:
150 TraceInfo = term()
152 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 print(Label, TraceInfo) -> ok
158 Types:
160 Label = integer()
162 TraceInfo = term()
163 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 reset_trace() -> true
169 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 set_system_tracer(Tracer) -> OldTracer
177 Types:
179 Tracer = OldTracer = tracer()
181 tracer() =
182 (Pid :: pid()) |
183 port() |
184 (TracerModule :: {module(), term()}) |
185 false
186 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 Failure: {badarg, Info}} if Pid is not an existing local pid.
193 get_system_tracer() -> Tracer
195 Types:
197 Tracer = tracer()
199 tracer() =
200 (Pid :: pid()) |
201 port() |
202 (TracerModule :: {module(), term()}) |
203 false
204 Returns the pid, port identifier or tracer module of the current
206 system tracer or false if no system tracer is activated.
207
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 {seq_trace, Label, SeqTraceInfo, TimeStamp}
213 or
215 {seq_trace, Label, SeqTraceInfo}
217 Where:
219 Label = int()
221 TimeStamp = {Seconds, Milliseconds, Microseconds}
222 Seconds = Milliseconds = Microseconds = int()
223 SeqTraceInfo can have the following formats:
225 {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 {'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 {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 Serial is a tuple {PreviousSerial, ThisSerial}, where:
249 * 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 * 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
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 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 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 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 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 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 The following sections describe sequential tracing and its most funda‐
298 mental concepts.
299
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 Message Passing:
307 All ordinary messages passed between Erlang processes.
308 Exit signals:
310 An exit signal is represented as an {'EXIT', Pid, Reason} tuple.
311 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 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 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
336 Each process has a current trace token which is "invisibly" passed from
337 the parent process on creation of the process.
338 The current token of a process is set in one of the following two ways:
340 * Explicitly by the process itself, through a call to
342 seq_trace:set_token/1,2
343 * 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 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 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
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 The algorithm for updating Serial can be described as follows:
362 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 * 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 Let the serial of the trace token be tprev and tcurr.
373 curr_cnt := curr_cnt + 1
375 tprev := prev_cnt
376 tcurr := curr_cnt
377 The trace token with tprev and tcurr is then passed along with the
379 information passed to the other process.
380 * 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 The algorithm is the same as for send above.
386 * 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 The process trace token is set to the trace token from the message.
392 Let the serial of the trace token be tprev and tcurr.
394 if (curr_cnt < tcurr )
396 curr_cnt := tcurr
397 prev_cnt := tcurr
398 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
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
416 Sequential tracing is not performed across ports.
417 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 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
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
435 This example gives a rough idea of how the new primitives can be used
436 and what kind of output it produces.
437 Assume that you have an initiating process with Pid == <0.30.0> like
439 this:
440 -module(seqex).
442 -compile(export_all).
443 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 And a registered process call_server with Pid == <0.31.0> like this:
458 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 A possible output from the system's sequential_tracer can be like this:
469 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 The implementation of a system tracer process that produces this print‐
480 out can look like this:
481 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 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 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 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 start() ->
512 Pid = spawn(?MODULE,tracer,[]),
513 seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
514 ok.
515 With a function like test/0, the whole example can be started:
517 test() ->
519 P = spawn(?MODULE, loop, [port]),
520 register(call_server, spawn(?MODULE, loop, [])),
521 start(),
522 P ! {port,message}.
523Ericsson AB kernel 7.3.1.1 seq_trace(3)