1seq_trace(3) Erlang Module Definition seq_trace(3)
2
6 seq_trace - Sequential tracing of messages.
7
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 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
20 token() = {integer(), boolean(), term(), term(), term()}
21 An opaque term (a tuple) representing a trace token.
23
25 set_token(Token) -> PreviousToken | ok
26 Types:
28 Token = PreviousToken = [] | token()
30 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 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 Returns the previous value of the trace token.
44 set_token(Component, Val) -> OldVal
46 Types:
48 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 Sets the individual Component of the trace token to Val. Returns
61 the previous value of the component.
62 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 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 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 set_token(send, Bool):
82 A trace token flag (true | false) which enables/disables
83 tracing on message sending. Default is false.
84 set_token('receive', Bool):
86 A trace token flag (true | false) which enables/disables
87 tracing on message reception. Default is false.
88 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 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 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 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 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 get_token() -> [] | token()
122 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 get_token(Component) -> {Component, Val}
129 Types:
131 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 Returns the value of the trace token component Component. See
144 set_token/2 for possible values of Component and Val.
145 print(TraceInfo) -> ok
147 Types:
149 TraceInfo = term()
151 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 print(Label, TraceInfo) -> ok
157 Types:
159 Label = integer()
161 TraceInfo = term()
162 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 reset_trace() -> true
168 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 set_system_tracer(Tracer) -> OldTracer
176 Types:
178 Tracer = OldTracer = tracer()
180 tracer() =
181 (Pid :: pid()) |
182 port() |
183 (TracerModule :: {module(), term()}) |
184 false
185 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 Failure: {badarg, Info}} if Pid is not an existing local pid.
192 get_system_tracer() -> Tracer
194 Types:
196 Tracer = tracer()
198 tracer() =
199 (Pid :: pid()) |
200 port() |
201 (TracerModule :: {module(), term()}) |
202 false
203 Returns the pid, port identifier or tracer module of the current
205 system tracer or false if no system tracer is activated.
206
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 {seq_trace, Label, SeqTraceInfo, TimeStamp}
212 or
214 {seq_trace, Label, SeqTraceInfo}
216 Where:
218 Label = int()
220 TimeStamp = {Seconds, Milliseconds, Microseconds}
221 Seconds = Milliseconds = Microseconds = int()
222 SeqTraceInfo can have the following formats:
224 {send, Serial, From, To, Message}:
226 Used when a process From with its trace token flag print set to
227 true has sent a message.
228 {'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 {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 Serial is a tuple {PreviousSerial, ThisSerial}, where:
239 * 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 * 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
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 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 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 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 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 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 The following sections describe sequential tracing and its most funda‐
280 mental concepts.
281
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 The current token of a process is set in one of the following two ways:
288 * Explicitly by the process itself, through a call to
290 seq_trace:set_token/1,2
291 * When a message is received
293 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 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
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 The algorithm for updating Serial can be described as follows:
308 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 * When the process is about to send a message and the trace token is
314 not empty.
315 Let the serial of the trace token be tprev and tcurr.
317 curr_cnt := curr_cnt + 1
319 tprev := prev_cnt
320 tcurr := curr_cnt
321 The trace token with tprev and tcurr is then passed along with the
323 message.
324 * 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 The algorithm is the same as for send above.
330 * When a message is received and contains a non-empty trace token.
332 The process trace token is set to the trace token from the message.
334 Let the serial of the trace token be tprev and tcurr.
336 if (curr_cnt < tcurr )
338 curr_cnt := tcurr
339 prev_cnt := tcurr
340 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
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
358 Sequential tracing is not performed across ports.
359 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 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
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
377 This example gives a rough idea of how the new primitives can be used
378 and what kind of output it produces.
379 Assume that you have an initiating process with Pid == <0.30.0> like
381 this:
382 -module(seqex).
384 -compile(export_all).
385 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 And a registered process call_server with Pid == <0.31.0> like this:
400 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 A possible output from the system's sequential_tracer can be like this:
411 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 The implementation of a system tracer process that produces this print‐
422 out can look like this:
423 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 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 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 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 start() ->
454 Pid = spawn(?MODULE,tracer,[]),
455 seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
456 ok.
457 With a function like test/0, the whole example can be started:
459 test() ->
461 P = spawn(?MODULE, loop, [port]),
462 register(call_server, spawn(?MODULE, loop, [])),
463 start(),
464 P ! {port,message}.
465Ericsson AB kernel 6.5 seq_trace(3)