aboutsummaryrefslogtreecommitdiffstats
path: root/lib
diff options
context:
space:
mode:
Diffstat (limited to 'lib')
-rw-r--r--lib/kernel/doc/src/seq_trace.xml55
-rw-r--r--lib/kernel/src/seq_trace.erl20
-rw-r--r--lib/kernel/test/seq_trace_SUITE.erl98
-rw-r--r--lib/observer/test/ttb_SUITE.erl10
4 files changed, 146 insertions, 37 deletions
diff --git a/lib/kernel/doc/src/seq_trace.xml b/lib/kernel/doc/src/seq_trace.xml
index 9aef748594..aa9067f082 100644
--- a/lib/kernel/doc/src/seq_trace.xml
+++ b/lib/kernel/doc/src/seq_trace.xml
@@ -107,6 +107,12 @@ seq_trace:set_token(OldToken), % activate the trace token again
enables/disables tracing on message sending. Default is
<c>false</c>.</p>
</item>
+ <tag><c>set_token('spawn', <anno>Bool</anno>)</c></tag>
+ <item>
+ <p>A trace token flag (<c>true | false</c>) which
+ enables/disables tracing on process spawning. Default is
+ <c>false</c>.</p>
+ </item>
<tag><c>set_token('receive', <anno>Bool</anno>)</c></tag>
<item>
<p>A trace token flag (<c>true | false</c>) which
@@ -259,6 +265,11 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}
<p>Used when a process <c>From</c> with its trace token flag
<c>send</c> set to <c>true</c> has sent a message.</p>
</item>
+ <tag><c>{spawn, Serial, Parent, Child, _}</c></tag>
+ <item>
+ <p>Used when a process <c>Parent</c> with its trace token flag
+ <c>spawn</c> set to <c>true</c> has spawned a process.</p>
+ </item>
<tag><c>{'receive', Serial, From, To, Message}</c></tag>
<item>
<p>Used when a process <c>To</c> receives a message with a
@@ -295,8 +306,8 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}
is initiated by a single message. In short, it works as follows:</p>
<p>Each process has a <em>trace token</em>, which can be empty or
not empty. When not empty, the trace token can be seen as
- the tuple <c>{Label, Flags, Serial, From}</c>. The trace token is
- passed invisibly with each message.</p>
+ the tuple <c>{Label, Flags, Serial, From}</c>. The trace token is passed
+ invisibly to spawned processes and with each message sent.</p>
<p>To start a sequential trace, the user must explicitly set
the trace token in the process that will send the first message
in a sequence.</p>
@@ -306,9 +317,10 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}
<p>On each Erlang node, a process can be set as the <em>system tracer</em>.
This process will receive trace messages each time
a message with a trace token is sent or received (if the trace
- token flag <c>send</c> or <c>'receive'</c> is set). The system
- tracer can then print each trace event, write it to a file, or
- whatever suitable.</p>
+ token flag <c>send</c> or <c>'receive'</c> is set), and when a process
+ with a non-empty trace token spawns another (if the trace token flag
+ <c>spawn</c> is set). The system tracer can then print each trace event,
+ write it to a file, or whatever suitable.</p>
<note>
<p>The system tracer only receives those trace events that
occur locally within the Erlang node. To get the whole picture
@@ -322,10 +334,9 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}
<section>
<title>Trace Token</title>
- <p>Each process has a current trace token. Initially, the token is
- empty. When the process sends a message to another process, a
- copy of the current token is sent "invisibly" along with
- the message.</p>
+ <p>Each process has a current trace token, which is copied from the process
+ that spawned it. When a process sends a message to another process, a
+ copy of the current token is sent "invisibly" along with the message.</p>
<p>The current token of a process is set in one of the following two
ways:</p>
<list type="bulleted">
@@ -354,8 +365,9 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}
<p>The algorithm for updating <c>Serial</c> can be described as
follows:</p>
<p>Let each process have two counters, <c>prev_cnt</c> and
- <c>curr_cnt</c>, both are set to <c>0</c> when a process is created.
- The counters are updated at the following occasions:</p>
+ <c>curr_cnt</c>, both are set to <c>0</c> when a process is created
+ outside of a trace sequence. The counters are updated at the following
+ occasions:</p>
<list type="bulleted">
<item>
<p><em>When the process is about to send a message and the trace token
@@ -370,6 +382,16 @@ tcurr := curr_cnt</pre>
passed along with the message.</p>
</item>
<item>
+ <p><em>When the process is about to spawn another process and the trace
+ token is not empty.</em></p>
+ <p>The counters of the parent process are updated in the same way as
+ for send above. The trace token is then passed to the child process,
+ whose counters will be set as follows:</p>
+ <code>
+curr_cnt := tcurr
+prev_cnt := tcurr</code>
+ </item>
+ <item>
<p><em>When the process calls</em> <c>seq_trace:print(Label, Info)</c>,
<c>Label</c> <em>matches the label part of the trace token and the
trace token print flag is <c>true</c>.</em></p>
@@ -487,9 +509,9 @@ tracer() ->
print_trace(Label,TraceInfo,false);
{seq_trace,Label,TraceInfo,Ts} ->
print_trace(Label,TraceInfo,Ts);
- Other -> ignore
+ _Other -> ignore
end,
- tracer().
+ tracer().
print_trace(Label,TraceInfo,false) ->
io:format("~p:",[Label]),
@@ -504,8 +526,11 @@ print_trace({'receive',Serial,From,To,Message}) ->
io:format("~p Received ~p FROM ~p WITH~n~p~n",
[To,Serial,From,Message]);
print_trace({send,Serial,From,To,Message}) ->
- io:format("~p Sent ~p TO ~p WITH~n~p~n",
- [From,Serial,To,Message]).</code>
+ io:format("~p Sent ~p TO ~p WITH~n~p~n",
+ [From,Serial,To,Message]);
+print_trace({spawn,Serial,Parent,Child,_}) ->
+ io:format("~p Spawned ~p AT ~p~n",
+ [Parent,Child,Serial]).</code>
<p>The code that creates a process that runs this tracer function
and sets that process as the system tracer can look like this:</p>
<code type="none">
diff --git a/lib/kernel/src/seq_trace.erl b/lib/kernel/src/seq_trace.erl
index 4f9d7b3e5c..327754d9ac 100644
--- a/lib/kernel/src/seq_trace.erl
+++ b/lib/kernel/src/seq_trace.erl
@@ -20,12 +20,14 @@
-module(seq_trace).
--define(SEQ_TRACE_SEND, 1). %(1 << 0)
--define(SEQ_TRACE_RECEIVE, 2). %(1 << 1)
--define(SEQ_TRACE_PRINT, 4). %(1 << 2)
--define(SEQ_TRACE_NOW_TIMESTAMP, 8). %(1 << 3)
--define(SEQ_TRACE_STRICT_MON_TIMESTAMP, 16). %(1 << 4)
--define(SEQ_TRACE_MON_TIMESTAMP, 32). %(1 << 5)
+%% Don't forget to update seq_trace_SUITE after changing these.
+-define(SEQ_TRACE_SEND, 1). %(1 << 0)
+-define(SEQ_TRACE_RECEIVE, 2). %(1 << 1)
+-define(SEQ_TRACE_PRINT, 4). %(1 << 2)
+-define(SEQ_TRACE_NOW_TIMESTAMP, 8). %(1 << 3)
+-define(SEQ_TRACE_STRICT_MON_TIMESTAMP, 16). %(1 << 4)
+-define(SEQ_TRACE_MON_TIMESTAMP, 32). %(1 << 5)
+-define(SEQ_TRACE_SPAWN, 64). %(1 << 6)
-export([set_token/1,
set_token/2,
@@ -39,7 +41,8 @@
%%---------------------------------------------------------------------------
--type flag() :: 'send' | 'receive' | 'print' | 'timestamp' | 'monotonic_timestamp' | 'strict_monotonic_timestamp'.
+-type flag() :: 'send' | 'spawn' | 'receive' | 'print' | 'timestamp' |
+ 'monotonic_timestamp' | 'strict_monotonic_timestamp'.
-type component() :: 'label' | 'serial' | flag().
-type value() :: (Label :: term())
| {Previous :: non_neg_integer(),
@@ -142,10 +145,11 @@ set_token2([]) ->
decode_flags(Flags) ->
Print = (Flags band ?SEQ_TRACE_PRINT) > 0,
Send = (Flags band ?SEQ_TRACE_SEND) > 0,
+ Spawn = (Flags band ?SEQ_TRACE_SPAWN) > 0,
Rec = (Flags band ?SEQ_TRACE_RECEIVE) > 0,
NowTs = (Flags band ?SEQ_TRACE_NOW_TIMESTAMP) > 0,
StrictMonTs = (Flags band ?SEQ_TRACE_STRICT_MON_TIMESTAMP) > 0,
MonTs = (Flags band ?SEQ_TRACE_MON_TIMESTAMP) > 0,
- [{print,Print},{send,Send},{'receive',Rec},{timestamp,NowTs},
+ [{print,Print},{send,Send},{spawn,Spawn},{'receive',Rec},{timestamp,NowTs},
{strict_monotonic_timestamp, StrictMonTs},
{monotonic_timestamp, MonTs}].
diff --git a/lib/kernel/test/seq_trace_SUITE.erl b/lib/kernel/test/seq_trace_SUITE.erl
index 663f910751..3256b6e9ad 100644
--- a/lib/kernel/test/seq_trace_SUITE.erl
+++ b/lib/kernel/test/seq_trace_SUITE.erl
@@ -29,7 +29,7 @@
send/1, distributed_send/1, recv/1, distributed_recv/1,
trace_exit/1, distributed_exit/1, call/1, port/1,
match_set_seq_token/1, gc_seq_token/1, label_capability_mismatch/1,
- send_literal/1]).
+ send_literal/1,inherit_on_spawn/1,spawn_flag/1]).
%% internal exports
-export([simple_tracer/2, one_time_receiver/0, one_time_receiver/1,
@@ -51,7 +51,8 @@ all() ->
[token_set_get, tracer_set_get, print, send, send_literal,
distributed_send, recv, distributed_recv, trace_exit,
distributed_exit, call, port, match_set_seq_token,
- gc_seq_token, label_capability_mismatch].
+ gc_seq_token, label_capability_mismatch,
+ inherit_on_spawn, spawn_flag].
groups() ->
[].
@@ -81,14 +82,29 @@ token_set_get(Config) when is_list(Config) ->
do_token_set_get(timestamp),
do_token_set_get(monotonic_timestamp),
do_token_set_get(strict_monotonic_timestamp).
-
+
+-define(SEQ_TRACE_SEND, 1). %(1 << 0)
+-define(SEQ_TRACE_RECEIVE, 2). %(1 << 1)
+-define(SEQ_TRACE_PRINT, 4). %(1 << 2)
+-define(SEQ_TRACE_NOW_TIMESTAMP, 8). %(1 << 3)
+-define(SEQ_TRACE_STRICT_MON_TIMESTAMP, 16). %(1 << 4)
+-define(SEQ_TRACE_MON_TIMESTAMP, 32). %(1 << 5)
+-define(SEQ_TRACE_SPAWN, 64). %(1 << 6)
+
do_token_set_get(TsType) ->
- io:format("Testing ~p~n", [TsType]),
+ BaseOpts = ?SEQ_TRACE_SEND bor
+ ?SEQ_TRACE_RECEIVE bor
+ ?SEQ_TRACE_PRINT bor
+ ?SEQ_TRACE_SPAWN,
Flags = case TsType of
- timestamp -> 15;
- strict_monotonic_timestamp -> 23;
- monotonic_timestamp -> 39
- end,
+ timestamp ->
+ BaseOpts bor ?SEQ_TRACE_NOW_TIMESTAMP;
+ strict_monotonic_timestamp ->
+ BaseOpts bor ?SEQ_TRACE_STRICT_MON_TIMESTAMP;
+ monotonic_timestamp ->
+ BaseOpts bor ?SEQ_TRACE_MON_TIMESTAMP
+ end,
+ ct:pal("Type ~p, flags = ~p~n", [TsType, Flags]),
Self = self(),
seq_trace:reset_trace(),
%% Test that initial seq_trace is disabled
@@ -100,6 +116,8 @@ do_token_set_get(TsType) ->
{print,true} = seq_trace:get_token(print),
false = seq_trace:set_token(send,true),
{send,true} = seq_trace:get_token(send),
+ false = seq_trace:set_token(spawn,true),
+ {spawn,true} = seq_trace:get_token(spawn),
false = seq_trace:set_token('receive',true),
{'receive',true} = seq_trace:get_token('receive'),
false = seq_trace:set_token(TsType,true),
@@ -462,8 +480,6 @@ call(Config) when is_list(Config) ->
1 =
erlang:trace(Self, true,
[call, set_on_spawn, {tracer, TrB(pid)}]),
- Label = 17,
- seq_trace:set_token(label, Label), % Token enters here!!
RefB = make_ref(),
Pid2B = spawn_link(
fun() ->
@@ -477,6 +493,12 @@ call(Config) when is_list(Config) ->
RefB = call_tracee_1(RefB),
Pid2B ! {self(), msg, RefB}
end),
+
+ %% The token is set *AFTER* spawning to make sure we're testing that the
+ %% token follows on send and not that it inherits on spawn.
+ Label = 17,
+ seq_trace:set_token(label, Label),
+
Pid1B ! {Self, msg, RefB},
%% The message is passed Self -> Pid1B -> Pid2B -> Self, and the
%% seq_trace token follows invisibly. Traced functions are
@@ -497,6 +519,62 @@ call(Config) when is_list(Config) ->
seq_trace:reset_trace(),
ok.
+%% The token should follow spawn, just like it follows messages.
+inherit_on_spawn(Config) when is_list(Config) ->
+ seq_trace:reset_trace(),
+ start_tracer(),
+
+ Ref = make_ref(),
+ seq_trace:set_token(label,Ref),
+ set_token_flags([send]),
+
+ Self = self(),
+ Other = spawn(fun() -> Self ! {gurka,Ref} end),
+
+ receive {gurka,Ref} -> ok end,
+ seq_trace:reset_trace(),
+
+ [{Ref,{send,_,Other,Self,{gurka,Ref}}, _Ts}] = stop_tracer(1),
+
+ ok.
+
+spawn_flag(Config) when is_list(Config) ->
+ seq_trace:reset_trace(),
+ start_tracer(),
+
+ Ref = make_ref(),
+ seq_trace:set_token(label,Ref),
+ set_token_flags([spawn]),
+
+ Self = self(),
+
+ {serial,{0,0}} = seq_trace:get_token(serial),
+
+ %% The serial number is bumped on spawning (just like message passing), so
+ %% our child should inherit a counter of 1.
+ ProcessA = spawn(fun() ->
+ {serial,{0,1}} = seq_trace:get_token(serial),
+ Self ! {a,Ref}
+ end),
+ receive {a,Ref} -> ok end,
+
+ {serial,{1,2}} = seq_trace:get_token(serial),
+
+ ProcessB = spawn(fun() ->
+ {serial,{2,3}} = seq_trace:get_token(serial),
+ Self ! {b,Ref}
+ end),
+ receive {b,Ref} -> ok end,
+
+ {serial,{3,4}} = seq_trace:get_token(serial),
+
+ seq_trace:reset_trace(),
+
+ [{Ref,{spawn,{0,1},Self,ProcessA,[]}, _Ts},
+ {Ref,{spawn,{2,3},Self,ProcessB,[]}, _Ts}] = stop_tracer(2),
+
+ ok.
+
%% Send trace messages to a port.
port(Config) when is_list(Config) ->
lists:foreach(fun (TsType) -> do_port(TsType, Config) end,
diff --git a/lib/observer/test/ttb_SUITE.erl b/lib/observer/test/ttb_SUITE.erl
index 33133dd78d..f8bb2e5eb0 100644
--- a/lib/observer/test/ttb_SUITE.erl
+++ b/lib/observer/test/ttb_SUITE.erl
@@ -658,11 +658,13 @@ seq_trace(Config) when is_list(Config) ->
?line ok = ttb:format(
[filename:join(Privdir,atom_to_list(Node)++"-seq_trace")]),
?line [{trace_ts,StartProc,call,{?MODULE,seq,[]},{_,_,_}},
- {seq_trace,0,{send,{0,1},StartProc,P1Proc,{Start,P2}}},
- {seq_trace,0,{send,{1,2},P1Proc,P2Proc,{P1,Start}}},
- {seq_trace,0,{send,{2,3},P2Proc,StartProc,{P2,P1}}},
+ {seq_trace,0,{send,{First, Seq0},StartProc,P1Proc,{Start,P2}}},
+ {seq_trace,0,{send,{Seq0, Seq1},P1Proc,P2Proc,{P1,Start}}},
+ {seq_trace,0,{send,{Seq1, Last},P2Proc,StartProc,{P2,P1}}},
end_of_trace] = flush(),
-
+ true = First < Seq0,
+ true = Seq0 < Seq1,
+ true = Seq1 < Last,
%% Additional test for metatrace
case StartProc of
{Start,_,_} -> ok;
generated by cgit v1.2.3 (git 2.25.1) at 2024-07-17 15:54:31 +0000