From 92bd7d3e43b7142d991f15594d783c1031547df5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?John=20H=C3=B6gberg?= Date: Tue, 19 Mar 2019 21:44:28 +0100 Subject: seq_trace: Fix typo in documentation --- lib/kernel/doc/src/seq_trace.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'lib') diff --git a/lib/kernel/doc/src/seq_trace.xml b/lib/kernel/doc/src/seq_trace.xml index aa29223dd0..9aef748594 100644 --- a/lib/kernel/doc/src/seq_trace.xml +++ b/lib/kernel/doc/src/seq_trace.xml @@ -257,7 +257,7 @@ TimeStamp = {Seconds, Milliseconds, Microseconds} {send, Serial, From, To, Message}

Used when a process From with its trace token flag - print set to true has sent a message.

+ send set to true has sent a message.

 {'receive', Serial, From, To, Message} -- cgit v1.2.3 From 2f75782815441a161e6157c941b7f482f96bdbcb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?John=20H=C3=B6gberg?= Date: Tue, 19 Mar 2019 17:39:14 +0100 Subject: 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. --- lib/kernel/doc/src/seq_trace.xml | 55 +++++++++++++++------ lib/kernel/src/seq_trace.erl | 20 +++++--- lib/kernel/test/seq_trace_SUITE.erl | 98 +++++++++++++++++++++++++++++++++---- lib/observer/test/ttb_SUITE.erl | 10 ++-- 4 files changed, 146 insertions(+), 37 deletions(-) (limited to 'lib') 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 false.

 + set_token('spawn', Bool) + +

A trace token flag (true | false) which + enables/disables tracing on process spawning. Default is + false.

+ set_token('receive', Bool)

A trace token flag (true | false) which @@ -259,6 +265,11 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}

Used when a process From with its trace token flag send set to true has sent a message.

 + {spawn, Serial, Parent, Child, _} + +

Used when a process Parent with its trace token flag + spawn set to true has spawned a process.

+ {'receive', Serial, From, To, Message}

Used when a process To 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:

Each process has a trace token, which can be empty or not empty. When not empty, the trace token can be seen as - the tuple {Label, Flags, Serial, From}. The trace token is - passed invisibly with each message.

+ the tuple {Label, Flags, Serial, From}. The trace token is passed + invisibly to spawned processes and with each message sent.

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.

@@ -306,9 +317,10 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}

On each Erlang node, a process can be set as the system tracer. This process will receive trace messages each time a message with a trace token is sent or received (if the trace - token flag send or 'receive' is set). The system - tracer can then print each trace event, write it to a file, or - whatever suitable.

+ token flag send or 'receive' is set), and when a process + with a non-empty trace token spawns another (if the trace token flag + spawn is set). The system tracer can then print each trace event, + write it to a file, or whatever suitable.

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}

Trace Token -

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.

+

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.

The current token of a process is set in one of the following two ways:

@@ -354,8 +365,9 @@ TimeStamp = {Seconds, Milliseconds, Microseconds}

The algorithm for updating Serial can be described as follows:

Let each process have two counters, prev_cnt and - curr_cnt, both are set to 0 when a process is created. - The counters are updated at the following occasions:

+ curr_cnt, both are set to 0 when a process is created + outside of a trace sequence. The counters are updated at the following + occasions:

When the process is about to send a message and the trace token @@ -369,6 +381,16 @@ tcurr := curr_cnt

The trace token with tprev and tcurr is then passed along with the message.

 + +

When the process is about to spawn another process and the trace + token is not empty.

+

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:

+ +curr_cnt := tcurr +prev_cnt := tcurr +

When the process calls seq_trace:print(Label, Info), Label matches the label part of the trace token and the @@ -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]). + 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]).

The code that creates a process that runs this tracer function and sets that process as the system tracer can look like this:

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; -- cgit v1.2.3 From 3caa7894a0271a656b752c878e82519bf9bd03b8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?John=20H=C3=B6gberg?= Date: Mon, 25 Mar 2019 10:43:30 +0100 Subject: fixup! seq_trace: Inherit trace token on spawn --- lib/kernel/test/seq_trace_SUITE.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'lib') diff --git a/lib/kernel/test/seq_trace_SUITE.erl b/lib/kernel/test/seq_trace_SUITE.erl index 3256b6e9ad..09b4365c8c 100644 --- a/lib/kernel/test/seq_trace_SUITE.erl +++ b/lib/kernel/test/seq_trace_SUITE.erl @@ -994,7 +994,7 @@ stop_tracer(N) when is_integer(N) -> receive {tracerlog,Data} -> Data - after 1000 -> + after 5000 -> {error,timeout} end end. -- cgit v1.2.3