aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel
diff options
context:
space:
mode:
authorJohn Högberg <[email protected]>2019-03-19 17:39:14 +0100
committerJohn Högberg <[email protected]>2019-03-21 16:25:32 +0100
commit2f75782815441a161e6157c941b7f482f96bdbcb (patch)
tree1636fd286073f1fe669a9e3f6a477e23c62ea9bc /lib/kernel
parent92bd7d3e43b7142d991f15594d783c1031547df5 (diff)
downloadotp-2f75782815441a161e6157c941b7f482f96bdbcb.tar.gz
otp-2f75782815441a161e6157c941b7f482f96bdbcb.tar.bz2
otp-2f75782815441a161e6157c941b7f482f96bdbcb.zip
seq_trace: Inherit trace token on spawn
Trace tokens can be lost when a process delegates message sending to a child process, which is pretty surprising and limits the usefulness of seq tracing. One example of this is gen_statem:call/4 which uses a child process to implement timeouts without the risk of a late message arriving to the caller. This commit attempts to remedy this by propagating the trace token to spawned processes, and adds optional tracing for process spawning as well.
Diffstat (limited to 'lib/kernel')
-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
3 files changed, 140 insertions, 33 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,