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) -> {Component, 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 (Integer :: integer() >= 0) |
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, Integer):
68 The label component is an integer which identifies all
69 events belonging to the same sequential trace. If several
70 sequential traces can be active simultaneously, label is
71 used to identify the separate traces. Default is 0.
72 set_token(serial, SerialValue):
74 SerialValue = {Previous, Current}. The serial component con‐
75 tains counters which enables the traced messages to be
76 sorted, should never be set explicitly by the user as these
77 counters are updated automatically. Default is {0, 0}.
78 set_token(send, Bool):
80 A trace token flag (true | false) which enables/disables
81 tracing on message sending. Default is false.
82 set_token('receive', Bool):
84 A trace token flag (true | false) which enables/disables
85 tracing on message reception. Default is false.
86 set_token(print, Bool):
88 A trace token flag (true | false) which enables/disables
89 tracing on explicit calls to seq_trace:print/1. Default is
90 false.
91 set_token(timestamp, Bool):
93 A trace token flag (true | false) which enables/disables a
94 timestamp to be generated for each traced event. Default is
95 false.
96 set_token(strict_monotonic_timestamp, Bool):
98 A trace token flag (true | false) which enables/disables a
99 strict monotonic timestamp to be generated for each traced
100 event. Default is false. Timestamps will consist of Erlang
101 monotonic time and a monotonically increasing integer. The
102 time-stamp has the same format and value as produced by
103 {erlang:monotonic_time(nanosecond), erlang:unique_inte‐
104 ger([monotonic])}.
105 set_token(monotonic_timestamp, Bool):
107 A trace token flag (true | false) which enables/disables a
108 strict monotonic timestamp to be generated for each traced
109 event. Default is false. Timestamps will use Erlang mono‐
110 tonic time. The time-stamp has the same format and value as
111 produced by erlang:monotonic_time(nanosecond).
112 If multiple timestamp flags are passed, timestamp has precedence
114 over strict_monotonic_timestamp which in turn has precedence
115 over monotonic_timestamp. All timestamp flags are remembered, so
116 if two are passed and the one with highest precedence later is
117 disabled the other one will become active.
118 get_token() -> [] | token()
120 Returns the value of the trace token for the calling process. If
122 [] is returned, it means that tracing is not active. Any other
123 value returned is the value of an active trace token. The value
124 returned can be used as input to the set_token/1 function.
125 get_token(Component) -> {Component, Val}
127 Types:
129 Component = component()
131 Val = value()
132 component() = label | serial | flag()
133 flag() =
134 send |
135 'receive' |
136 print |
137 timestamp |
138 monotonic_timestamp |
139 strict_monotonic_timestamp
140 value() =
141 (Integer :: integer() >= 0) |
142 {Previous :: integer() >= 0, Current :: integer() >= 0} |
143 (Bool :: boolean())
144 Returns the value of the trace token component Component. See
146 set_token/2 for possible values of Component and Val.
147 print(TraceInfo) -> ok
149 Types:
151 TraceInfo = term()
153 Puts the Erlang term TraceInfo into the sequential trace output
155 if the calling process currently is executing within a sequen‐
156 tial trace and the print flag of the trace token is set.
157 print(Label, TraceInfo) -> ok
159 Types:
161 Label = integer()
163 TraceInfo = term()
164 Same as print/1 with the additional condition that TraceInfo is
166 output only if Label is equal to the label component of the
167 trace token.
168 reset_trace() -> true
170 Sets the trace token to empty for all processes on the local
172 node. The process internal counters used to create the serial of
173 the trace token is set to 0. The trace token is set to empty for
174 all messages in message queues. Together this will effectively
175 stop all ongoing sequential tracing in the local node.
176 set_system_tracer(Tracer) -> OldTracer
178 Types:
180 Tracer = OldTracer = tracer()
182 tracer() =
183 (Pid :: pid()) |
184 port() |
185 (TracerModule :: {module(), term()}) |
186 false
187 Sets the system tracer. The system tracer can be either a
189 process, port or tracer module denoted by Tracer. Returns the
190 previous value (which can be false if no system tracer is
191 active).
192 Failure: {badarg, Info}} if Pid is not an existing local pid.
194 get_system_tracer() -> Tracer
196 Types:
198 Tracer = tracer()
200 tracer() =
201 (Pid :: pid()) |
202 port() |
203 (TracerModule :: {module(), term()}) |
204 false
205 Returns the pid, port identifier or tracer module of the current
207 system tracer or false if no system tracer is activated.
208
210 The format of the messages is one of the following, depending on if
211 flag timestamp of the trace token is set to true or false:
212 {seq_trace, Label, SeqTraceInfo, TimeStamp}
214 or
216 {seq_trace, Label, SeqTraceInfo}
218 Where:
220 Label = int()
222 TimeStamp = {Seconds, Milliseconds, Microseconds}
223 Seconds = Milliseconds = Microseconds = int()
224 SeqTraceInfo can have the following formats:
226 {send, Serial, From, To, Message}:
228 Used when a process From with its trace token flag print set to
229 true has sent a message.
230 {'receive', Serial, From, To, Message}:
232 Used when a process To receives a message with a trace token that
233 has flag 'receive' set to true.
234 {print, Serial, From, _, Info}:
236 Used when a process From has called seq_trace:print(Label, Trace‐
237 Info) and has a trace token with flag print set to true, and label
238 set to Label.
239 Serial is a tuple {PreviousSerial, ThisSerial}, where:
241 * Integer PreviousSerial denotes the serial counter passed in the
243 last received message that carried a trace token. If the process is
244 the first in a new sequential trace, PreviousSerial is set to the
245 value of the process internal "trace clock".
246 * Integer ThisSerial is the serial counter that a process sets on
248 outgoing messages. It is based on the process internal "trace
249 clock", which is incremented by one before it is attached to the
250 trace token in the message.
251
253 Sequential tracing is a way to trace a sequence of messages sent
254 between different local or remote processes, where the sequence is ini‐
255 tiated by a single message. In short, it works as follows:
256 Each process has a trace token, which can be empty or not empty. When
258 not empty, the trace token can be seen as the tuple {Label, Flags,
259 Serial, From}. The trace token is passed invisibly with each message.
260 To start a sequential trace, the user must explicitly set the trace
262 token in the process that will send the first message in a sequence.
263 The trace token of a process is set each time the process matches a
265 message in a receive statement, according to the trace token carried by
266 the received message, empty or not.
267 On each Erlang node, a process can be set as the system tracer. This
269 process will receive trace messages each time a message with a trace
270 token is sent or received (if the trace token flag send or 'receive' is
271 set). The system tracer can then print each trace event, write it to a
272 file, or whatever suitable.
273 Note:
275 The system tracer only receives those trace events that occur locally
276 within the Erlang node. To get the whole picture of a sequential trace,
277 involving processes on many Erlang nodes, the output from the system
278 tracer on each involved node must be merged (offline).
279 The following sections describe sequential tracing and its most funda‐
282 mental concepts.
283
285 Each process has a current trace token. Initially, the token is empty.
286 When the process sends a message to another process, a copy of the cur‐
287 rent token is sent "invisibly" along with the message.
288 The current token of a process is set in one of the following two ways:
290 * Explicitly by the process itself, through a call to
292 seq_trace:set_token/1,2
293 * When a message is received
295 In both cases, the current token is set. In particular, if the token of
297 a received message is empty, the current token of the process is set to
298 empty.
299 A trace token contains a label and a set of flags. Both the label and
301 the flags are set in both alternatives above.
302
304 The trace token contains a component called serial. It consists of two
305 integers, Previous and Current. The purpose is to uniquely identify
306 each traced event within a trace sequence, as well as to order the mes‐
307 sages chronologically and in the different branches, if any.
308 The algorithm for updating Serial can be described as follows:
310 Let each process have two counters, prev_cnt and curr_cnt, both are set
312 to 0 when a process is created. The counters are updated at the follow‐
313 ing occasions:
314 * When the process is about to send a message and the trace token is
316 not empty.
317 Let the serial of the trace token be tprev and tcurr.
319 curr_cnt := curr_cnt + 1
321 tprev := prev_cnt
322 tcurr := curr_cnt
323 The trace token with tprev and tcurr is then passed along with the
325 message.
326 * When the process calls seq_trace:print(Label, Info), Label matches
328 the label part of the trace token and the trace token print flag is
329 true.
330 The algorithm is the same as for send above.
332 * When a message is received and contains a non-empty trace token.
334 The process trace token is set to the trace token from the message.
336 Let the serial of the trace token be tprev and tcurr.
338 if (curr_cnt < tcurr )
340 curr_cnt := tcurr
341 prev_cnt := tcurr
342 curr_cnt of a process is incremented each time the process is involved
344 in a sequential trace. The counter can reach its limit (27 bits) if a
345 process is very long-lived and is involved in much sequential tracing.
346 If the counter overflows, the serial for ordering of the trace events
347 cannot be used. To prevent the counter from overflowing in the middle
348 of a sequential trace, function seq_trace:reset_trace/0 can be called
349 to reset prev_cnt and curr_cnt of all processes in the Erlang node.
350 This function also sets all trace tokens in processes and their message
351 queues to empty, and thus stops all ongoing sequential tracing.
352
354 The performance degradation for a system that is enabled for sequential
355 tracing is negligible as long as no tracing is activated. When tracing
356 is activated, there is an extra cost for each traced message, but all
357 other messages are unaffected.
358
360 Sequential tracing is not performed across ports.
361 If the user for some reason wants to pass the trace token to a port,
363 this must be done manually in the code of the port controlling process.
364 The port controlling processes have to check the appropriate sequential
365 trace settings (as obtained from seq_trace:get_token/1) and include
366 trace information in the message data sent to their respective ports.
367 Similarly, for messages received from a port, a port controller has to
369 retrieve trace-specific information, and set appropriate sequential
370 trace flags through calls to seq_trace:set_token/2.
371
373 Sequential tracing between nodes is performed transparently. This
374 applies to C-nodes built with Erl_Interface too. A C-node built with
375 Erl_Interface only maintains one trace token, which means that the C-
376 node appears as one process from the sequential tracing point of view.
377
379 This example gives a rough idea of how the new primitives can be used
380 and what kind of output it produces.
381 Assume that you have an initiating process with Pid == <0.30.0> like
383 this:
384 -module(seqex).
386 -compile(export_all).
387 loop(Port) ->
389 receive
390 {Port,Message} ->
391 seq_trace:set_token(label,17),
392 seq_trace:set_token('receive',true),
393 seq_trace:set_token(print,true),
394 seq_trace:print(17,"**** Trace Started ****"),
395 call_server ! {self(),the_message};
396 {ack,Ack} ->
397 ok
398 end,
399 loop(Port).
400 And a registered process call_server with Pid == <0.31.0> like this:
402 loop() ->
404 receive
405 {PortController,Message} ->
406 Ack = {received, Message},
407 seq_trace:print(17,"We are here now"),
408 PortController ! {ack,Ack}
409 end,
410 loop().
411 A possible output from the system's sequential_tracer can be like this:
413 17:<0.30.0> Info {0,1} WITH
415 "**** Trace Started ****"
416 17:<0.31.0> Received {0,2} FROM <0.30.0> WITH
417 {<0.30.0>,the_message}
418 17:<0.31.0> Info {2,3} WITH
419 "We are here now"
420 17:<0.30.0> Received {2,4} FROM <0.31.0> WITH
421 {ack,{received,the_message}}
422 The implementation of a system tracer process that produces this print‐
424 out can look like this:
425 tracer() ->
427 receive
428 {seq_trace,Label,TraceInfo} ->
429 print_trace(Label,TraceInfo,false);
430 {seq_trace,Label,TraceInfo,Ts} ->
431 print_trace(Label,TraceInfo,Ts);
432 Other -> ignore
433 end,
434 tracer().
435 print_trace(Label,TraceInfo,false) ->
437 io:format("~p:",[Label]),
438 print_trace(TraceInfo);
439 print_trace(Label,TraceInfo,Ts) ->
440 io:format("~p ~p:",[Label,Ts]),
441 print_trace(TraceInfo).
442 print_trace({print,Serial,From,_,Info}) ->
444 io:format("~p Info ~p WITH~n~p~n", [From,Serial,Info]);
445 print_trace({'receive',Serial,From,To,Message}) ->
446 io:format("~p Received ~p FROM ~p WITH~n~p~n",
447 [To,Serial,From,Message]);
448 print_trace({send,Serial,From,To,Message}) ->
449 io:format("~p Sent ~p TO ~p WITH~n~p~n",
450 [From,Serial,To,Message]).
451 The code that creates a process that runs this tracer function and sets
453 that process as the system tracer can look like this:
454 start() ->
456 Pid = spawn(?MODULE,tracer,[]),
457 seq_trace:set_system_tracer(Pid), % set Pid as the system tracer
458 ok.
459 With a function like test/0, the whole example can be started:
461 test() ->
463 P = spawn(?MODULE, loop, [port]),
464 register(call_server, spawn(?MODULE, loop, [])),
465 start(),
466 P ! {port,message}.
467Ericsson AB kernel 5.4.3.2 seq_trace(3)