diff options
Diffstat (limited to 'lib/kernel')
-rw-r--r-- | lib/kernel/doc/src/seq_trace.xml | 57 | ||||
-rw-r--r-- | lib/kernel/src/seq_trace.erl | 20 | ||||
-rw-r--r-- | lib/kernel/test/seq_trace_SUITE.erl | 100 |
3 files changed, 142 insertions, 35 deletions
diff --git a/lib/kernel/doc/src/seq_trace.xml b/lib/kernel/doc/src/seq_trace.xml index aa29223dd0..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 @@ -257,7 +263,12 @@ TimeStamp = {Seconds, Milliseconds, Microseconds} <tag><c>{send, Serial, From, To, Message}</c></tag> <item> <p>Used when a process <c>From</c> with its trace token flag - <c>print</c> set to <c>true</c> has sent a message.</p> + <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> @@ -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..09b4365c8c 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, @@ -916,7 +994,7 @@ stop_tracer(N) when is_integer(N) -> receive {tracerlog,Data} -> Data - after 1000 -> + after 5000 -> {error,timeout} end end. |