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 |
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 Sets the individual Component of the trace token to Val. Returns
65 the previous value of the component.
66 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 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 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 set_token(send, Bool):
86 A trace token flag (true | false) which enables/disables
87 tracing on message sending. Default is false.
88 set_token('receive', Bool):
90 A trace token flag (true | false) which enables/disables
91 tracing on message reception. Default is false.
92 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 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 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 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 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 get_token() -> [] | token()
126 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 get_token(Component) -> {Component, Val}
133 Types:
135 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 Returns the value of the trace token component Component. See
152 set_token/2 for possible values of Component and Val.
153 print(TraceInfo) -> ok
155 Types:
157 TraceInfo = term()
159 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 print(Label, TraceInfo) -> ok
165 Types:
167 Label = integer()
169 TraceInfo = term()
170 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 reset_trace() -> true
176 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 set_system_tracer(Tracer) -> OldTracer
184 Types:
186 Tracer = OldTracer = tracer()
188 tracer() =
189 (Pid :: pid()) |
190 port() |
191 (TracerModule :: {module(), term()}) |
192 false
193 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 Failure: {badarg, Info}} if Pid is not an existing local pid.
200 get_system_tracer() -> Tracer
202 Types:
204 Tracer = tracer()
206 tracer() =
207 (Pid :: pid()) |
208 port() |
209 (TracerModule :: {module(), term()}) |
210 false
211 Returns the pid, port identifier or tracer module of the current
213 system tracer or false if no system tracer is activated.
214
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 {seq_trace, Label, SeqTraceInfo, TimeStamp}
220 or
222 {seq_trace, Label, SeqTraceInfo}
224 Where:
226 Label = int()
228 TimeStamp = {Seconds, Milliseconds, Microseconds}
229 Seconds = Milliseconds = Microseconds = int()
230 SeqTraceInfo can have the following formats:
232 {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 {'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 {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 Serial is a tuple {PreviousSerial, ThisSerial}, where:
247 * 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 * 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
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 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 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 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 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 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 The following sections describe sequential tracing and its most funda‐
288 mental concepts.
289
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 The current token of a process is set in one of the following two ways:
296 * Explicitly by the process itself, through a call to
298 seq_trace:set_token/1,2
299 * When a message is received
301 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 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
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 The algorithm for updating Serial can be described as follows:
316 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 * When the process is about to send a message and the trace token is
322 not empty.
323 Let the serial of the trace token be tprev and tcurr.
325 curr_cnt := curr_cnt + 1
327 tprev := prev_cnt
328 tcurr := curr_cnt
329 The trace token with tprev and tcurr is then passed along with the
331 message.
332 * 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 The algorithm is the same as for send above.
338 * When a message is received and contains a non-empty trace token.
340 The process trace token is set to the trace token from the message.
342 Let the serial of the trace token be tprev and tcurr.
344 if (curr_cnt < tcurr )
346 curr_cnt := tcurr
347 prev_cnt := tcurr
348 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
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
366 Sequential tracing is not performed across ports.
367 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 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
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
385 This example gives a rough idea of how the new primitives can be used
386 and what kind of output it produces.
387 Assume that you have an initiating process with Pid == <0.30.0> like
389 this:
390 -module(seqex).
392 -compile(export_all).
393 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 And a registered process call_server with Pid == <0.31.0> like this:
408 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 A possible output from the system's sequential_tracer can be like this:
419 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 The implementation of a system tracer process that produces this print‐
430 out can look like this:
431 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 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 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 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 start() ->
462 Pid = spawn(?MODULE,tracer,[]),
463 seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
464 ok.
465 With a function like test/0, the whole example can be started:
467 test() ->
469 P = spawn(?MODULE, loop, [port]),
470 register(call_server, spawn(?MODULE, loop, [])),
471 start(),
472 P ! {port,message}.
473Ericsson AB kernel 6.3.1.1 seq_trace(3)