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
34 Erlang term returned from get_token/0 or set_token/1.
35 set_token/1 can be used to temporarily exclude message passing
36 from the 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
106 {erlang: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
190 active).
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,
269 Serial, 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
272 between processes by other means. For example, by spawning a new
273 process. An information transfer between two processes is represented
274 by a send event and a receive event regardless of how it is passed.
275 To start a sequential trace, the user must explicitly set the trace
277 token in the process that will send the first information in a
278 sequence.
279 The trace token of a process is set each time the process receives
281 information. This is typically when the process matches a message in a
282 receive statement, according to the trace token carried by the received
283 message, empty or not.
284 On each Erlang node, a process can be set as the system tracer. This
286 process will receive trace messages each time information with a trace
287 token is sent or received (if the trace token flag send or 'receive' is
288 set). The system tracer can then print each trace event, write it to a
289 file, or whatever suitable.
290 Note:
292 The system tracer only receives those trace events that occur locally
293 within the Erlang node. To get the whole picture of a sequential trace,
294 involving processes on many Erlang nodes, the output from the system
295 tracer on each involved node must be merged (offline).
296 The following sections describe sequential tracing and its most funda‐
299 mental concepts.
300
302 Information flows between processes in a lot of different ways. Not all
303 flows of information will be covered by sequential tracing. One example
304 is information passed via ETS tables. Below is a list of information
305 paths that are covered by sequential tracing:
306 Message Passing:
308 All ordinary messages passed between Erlang processes.
309 Exit signals:
311 An exit signal is represented as an {'EXIT', Pid, Reason} tuple.
312 Process Spawn:
314 A process spawn is represented as multiple information transfers.
315 At least one spawn request and one spawn reply. The actual amount
316 of information transfers depends on what type of spawn it is and
317 may also change in future implementations. Note that this is more
318 or less an internal protocol that you are peeking at. The spawn
319 request will be represented as a tuple with the first element con‐
320 taining the atom spawn_request, but this is more or less all that
321 you can depend on.
322 Note:
324 If you do ordinary send or receive trace on the system, you will only
325 see ordinary message passing, not the other information transfers
326 listed above.
327 Note:
330 When a send event and corresponding receive event do not both corre‐
331 spond to ordinary Erlang messages, the Message part of the trace mes‐
332 sages may not be identical. This since all information not necessarily
333 are available when generating the trace messages.
334
337 Each process has a current trace token which is "invisibly" passed from
338 the parent process on creation of the process.
339 The current token of a process is set in one of the following two ways:
341 * Explicitly by the process itself, through a call to
343 seq_trace:set_token/1,2
344 * When information is received. This is typically when a received
346 message is matched out in a receive expression, but also when
347 information is received in other ways.
348 In both cases, the current token is set. In particular, if the token of
350 a received message is empty, the current token of the process is set to
351 empty.
352 A trace token contains a label and a set of flags. Both the label and
354 the flags are set in both alternatives above.
355
357 The trace token contains a component called serial. It consists of two
358 integers, Previous and Current. The purpose is to uniquely identify
359 each traced event within a trace sequence, as well as to order the mes‐
360 sages chronologically and in the different branches, if any.
361 The algorithm for updating Serial can be described as follows:
363 Let each process have two counters, prev_cnt and curr_cnt, both are set
365 to 0 when a process is created outside of a trace sequence. The coun‐
366 ters are updated at the following occasions:
367 * When the process is about to pass along information to another
369 process and the trace token is not empty. This typically occurs
370 when sending a message, but also, for example, when spawning
371 another process.
372 Let the serial of the trace token be tprev and tcurr.
374 curr_cnt := curr_cnt + 1
376 tprev := prev_cnt
377 tcurr := curr_cnt
378 The trace token with tprev and tcurr is then passed along with the
380 information passed to the other process.
381 * When the process calls seq_trace:print(Label, Info), Label matches
383 the label part of the trace token and the trace token print flag is
384 true.
385 The algorithm is the same as for send above.
387 * When information is received that also contains a non-empty trace
389 token. For example, when a message is matched out in a receive
390 expression, or when a new process is spawned.
391 The process trace token is set to the trace token from the message.
393 Let the serial of the trace token be tprev and tcurr.
395 if (curr_cnt < tcurr )
397 curr_cnt := tcurr
398 prev_cnt := tcurr
399 curr_cnt of a process is incremented each time the process is involved
401 in a sequential trace. The counter can reach its limit (27 bits) if a
402 process is very long-lived and is involved in much sequential tracing.
403 If the counter overflows, the serial for ordering of the trace events
404 cannot be used. To prevent the counter from overflowing in the middle
405 of a sequential trace, function seq_trace:reset_trace/0 can be called
406 to reset prev_cnt and curr_cnt of all processes in the Erlang node.
407 This function also sets all trace tokens in processes and their message
408 queues to empty, and thus stops all ongoing sequential tracing.
409
411 The performance degradation for a system that is enabled for sequential
412 tracing is negligible as long as no tracing is activated. When tracing
413 is activated, there is an extra cost for each traced message, but all
414 other messages are unaffected.
415
417 Sequential tracing is not performed across ports.
418 If the user for some reason wants to pass the trace token to a port,
420 this must be done manually in the code of the port controlling process.
421 The port controlling processes have to check the appropriate sequential
422 trace settings (as obtained from seq_trace:get_token/1) and include
423 trace information in the message data sent to their respective ports.
424 Similarly, for messages received from a port, a port controller has to
426 retrieve trace-specific information, and set appropriate sequential
427 trace flags through calls to seq_trace:set_token/2.
428
430 Sequential tracing between nodes is performed transparently. This
431 applies to C-nodes built with Erl_Interface too. A C-node built with
432 Erl_Interface only maintains one trace token, which means that the C-
433 node appears as one process from the sequential tracing point of view.
434
436 This example gives a rough idea of how the new primitives can be used
437 and what kind of output it produces.
438 Assume that you have an initiating process with Pid == <0.30.0> like
440 this:
441 -module(seqex).
443 -compile(export_all).
444 loop(Port) ->
446 receive
447 {Port,Message} ->
448 seq_trace:set_token(label,17),
449 seq_trace:set_token('receive',true),
450 seq_trace:set_token(print,true),
451 seq_trace:print(17,"**** Trace Started ****"),
452 call_server ! {self(),the_message};
453 {ack,Ack} ->
454 ok
455 end,
456 loop(Port).
457 And a registered process call_server with Pid == <0.31.0> like this:
459 loop() ->
461 receive
462 {PortController,Message} ->
463 Ack = {received, Message},
464 seq_trace:print(17,"We are here now"),
465 PortController ! {ack,Ack}
466 end,
467 loop().
468 A possible output from the system's sequential_tracer can be like this:
470 17:<0.30.0> Info {0,1} WITH
472 "**** Trace Started ****"
473 17:<0.31.0> Received {0,2} FROM <0.30.0> WITH
474 {<0.30.0>,the_message}
475 17:<0.31.0> Info {2,3} WITH
476 "We are here now"
477 17:<0.30.0> Received {2,4} FROM <0.31.0> WITH
478 {ack,{received,the_message}}
479 The implementation of a system tracer process that produces this print‐
481 out can look like this:
482 tracer() ->
484 receive
485 {seq_trace,Label,TraceInfo} ->
486 print_trace(Label,TraceInfo,false);
487 {seq_trace,Label,TraceInfo,Ts} ->
488 print_trace(Label,TraceInfo,Ts);
489 _Other -> ignore
490 end,
491 tracer().
492 print_trace(Label,TraceInfo,false) ->
494 io:format("~p:",[Label]),
495 print_trace(TraceInfo);
496 print_trace(Label,TraceInfo,Ts) ->
497 io:format("~p ~p:",[Label,Ts]),
498 print_trace(TraceInfo).
499 print_trace({print,Serial,From,_,Info}) ->
501 io:format("~p Info ~p WITH~n~p~n", [From,Serial,Info]);
502 print_trace({'receive',Serial,From,To,Message}) ->
503 io:format("~p Received ~p FROM ~p WITH~n~p~n",
504 [To,Serial,From,Message]);
505 print_trace({send,Serial,From,To,Message}) ->
506 io:format("~p Sent ~p TO ~p WITH~n~p~n",
507 [From,Serial,To,Message]).
508 The code that creates a process that runs this tracer function and sets
510 that process as the system tracer can look like this:
511 start() ->
513 Pid = spawn(?MODULE,tracer,[]),
514 seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
515 ok.
516 With a function like test/0, the whole example can be started:
518 test() ->
520 P = spawn(?MODULE, loop, [port]),
521 register(call_server, spawn(?MODULE, loop, [])),
522 start(),
523 P ! {port,message}.
524Ericsson AB kernel 7.3 seq_trace(3)