From 858c6f7fa44f7b2dc363b359198d6522dd60e914 Mon Sep 17 00:00:00 2001 From: Rickard Green Date: Tue, 5 Jan 2016 16:55:04 +0100 Subject: Introduce time warp safe trace timestamp formats New timestamp options for trace, sequential trace, and system profile: - monotonic_timestamp - strict_monotonic_timestamp --- lib/kernel/doc/src/seq_trace.xml | 28 ++++++ lib/kernel/src/kernel.app.src | 2 +- lib/kernel/src/seq_trace.erl | 14 ++- lib/kernel/test/seq_trace_SUITE.erl | 166 +++++++++++++++++++++++++++++------- 4 files changed, 176 insertions(+), 34 deletions(-) (limited to 'lib/kernel') diff --git a/lib/kernel/doc/src/seq_trace.xml b/lib/kernel/doc/src/seq_trace.xml index 3439111035..9f191d488d 100644 --- a/lib/kernel/doc/src/seq_trace.xml +++ b/lib/kernel/doc/src/seq_trace.xml @@ -127,6 +127,34 @@ seq_trace:set_token(OldToken), % activate the trace token again enables/disables a timestamp to be generated for each traced event. Default is false.

+ set_token(strict_monotonic_timestamp, Bool) + +

A trace token flag (true | false) which + enables/disables a strict monotonic timestamp to be generated + for each traced event. Default is false. Timestamps will + consist of + Erlang + monotonic time and a monotonically increasing + integer. The time-stamp has the same format and value + as produced by {erlang:monotonic_time(), + erlang:unique_integer([monotonic])}.

+ + set_token(monotonic_timestamp, Bool) + +

A trace token flag (true | false) which + enables/disables a strict monotonic timestamp to be generated + for each traced event. Default is false. Timestamps + will use + Erlang + monotonic time. The time-stamp has the same + format and value as produced by erlang:monotonic_time().

+ +

If multiple timestamp flags are passed, timestamp has + precedence over strict_monotonic_timestamp which + in turn has precedence over monotonic_timestamp. All + timestamp flags are remembered, so if two are passed + and the one with highest precedence later is disabled + the other one will become active.

diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index b5555ca1a5..419dc0a2fc 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -116,6 +116,6 @@ {applications, []}, {env, [{error_logger, tty}]}, {mod, {kernel, []}}, - {runtime_dependencies, ["erts-7.0", "stdlib-2.6", "sasl-2.6"]} + {runtime_dependencies, ["erts-7.3", "stdlib-2.6", "sasl-2.6"]} ] }. diff --git a/lib/kernel/src/seq_trace.erl b/lib/kernel/src/seq_trace.erl index 07ccd3e494..a7a782c29c 100644 --- a/lib/kernel/src/seq_trace.erl +++ b/lib/kernel/src/seq_trace.erl @@ -23,7 +23,9 @@ -define(SEQ_TRACE_SEND, 1). %(1 << 0) -define(SEQ_TRACE_RECEIVE, 2). %(1 << 1) -define(SEQ_TRACE_PRINT, 4). %(1 << 2) --define(SEQ_TRACE_TIMESTAMP, 8). %(1 << 3) +-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) -export([set_token/1, set_token/2, @@ -37,7 +39,7 @@ %%--------------------------------------------------------------------------- --type flag() :: 'send' | 'receive' | 'print' | 'timestamp'. +-type flag() :: 'send' | 'receive' | 'print' | 'timestamp' | 'monotonic_timestamp' | 'strict_monotonic_timestamp'. -type component() :: 'label' | 'serial' | flag(). -type value() :: (Integer :: non_neg_integer()) | {Previous :: non_neg_integer(), @@ -135,5 +137,9 @@ decode_flags(Flags) -> Print = (Flags band ?SEQ_TRACE_PRINT) > 0, Send = (Flags band ?SEQ_TRACE_SEND) > 0, Rec = (Flags band ?SEQ_TRACE_RECEIVE) > 0, - Ts = (Flags band ?SEQ_TRACE_TIMESTAMP) > 0, - [{print,Print},{send,Send},{'receive',Rec},{timestamp,Ts}]. + 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}, + {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 7df0bc3d2f..6a63f7bc9c 100644 --- a/lib/kernel/test/seq_trace_SUITE.erl +++ b/lib/kernel/test/seq_trace_SUITE.erl @@ -35,6 +35,11 @@ %-define(line_trace, 1). -include_lib("test_server/include/test_server.hrl"). +-define(TIMESTAMP_MODES, [no_timestamp, + timestamp, + monotonic_timestamp, + strict_monotonic_timestamp]). + -define(default_timeout, ?t:minutes(1)). suite() -> [{ct_hooks,[ts_install_cth]}]. @@ -75,6 +80,17 @@ end_per_testcase(_Case, Config) -> token_set_get(doc) -> []; token_set_get(suite) -> []; 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). + +do_token_set_get(TsType) -> + io:format("Testing ~p~n", [TsType]), + Flags = case TsType of + timestamp -> 15; + strict_monotonic_timestamp -> 23; + monotonic_timestamp -> 39 + end, ?line Self = self(), ?line seq_trace:reset_trace(), %% Test that initial seq_trace is disabled @@ -88,22 +104,22 @@ token_set_get(Config) when is_list(Config) -> ?line {send,true} = seq_trace:get_token(send), ?line false = seq_trace:set_token('receive',true), ?line {'receive',true} = seq_trace:get_token('receive'), - ?line false = seq_trace:set_token(timestamp,true), - ?line {timestamp,true} = seq_trace:get_token(timestamp), + ?line false = seq_trace:set_token(TsType,true), + ?line {TsType,true} = seq_trace:get_token(TsType), %% Check the whole token - ?line {15,17,0,Self,0} = seq_trace:get_token(), % all flags are set + ?line {Flags,17,0,Self,0} = seq_trace:get_token(), % all flags are set %% Test setting and reading the 'serial' field ?line {0,0} = seq_trace:set_token(serial,{3,5}), ?line {serial,{3,5}} = seq_trace:get_token(serial), %% Check the whole token, test that a whole token can be set and get - ?line {15,17,5,Self,3} = seq_trace:get_token(), - ?line seq_trace:set_token({15,19,7,Self,5}), - ?line {15,19,7,Self,5} = seq_trace:get_token(), + ?line {Flags,17,5,Self,3} = seq_trace:get_token(), + ?line seq_trace:set_token({Flags,19,7,Self,5}), + ?line {Flags,19,7,Self,5} = seq_trace:get_token(), %% Check that receive timeout does not reset token ?line receive after 0 -> ok end, - ?line {15,19,7,Self,5} = seq_trace:get_token(), + ?line {Flags,19,7,Self,5} = seq_trace:get_token(), %% Check that token can be unset - ?line {15,19,7,Self,5} = seq_trace:set_token([]), + ?line {Flags,19,7,Self,5} = seq_trace:set_token([]), ?line [] = seq_trace:get_token(), %% Check that Previous serial counter survived unset token ?line 0 = seq_trace:set_token(label, 17), @@ -139,30 +155,42 @@ tracer_set_get(Config) when is_list(Config) -> print(doc) -> []; print(suite) -> []; print(Config) when is_list(Config) -> + lists:foreach(fun do_print/1, ?TIMESTAMP_MODES). + +do_print(TsType) -> ?line start_tracer(), - ?line seq_trace:set_token(print,true), + ?line set_token_flags([print, TsType]), ?line seq_trace:print(0,print1), ?line seq_trace:print(1,print2), ?line seq_trace:print(print3), ?line seq_trace:reset_trace(), - ?line [{0,{print,_,_,[],print1}}, - {0,{print,_,_,[],print3}}] = stop_tracer(2). + ?line [{0,{print,_,_,[],print1}, Ts0}, + {0,{print,_,_,[],print3}, Ts1}] = stop_tracer(2), + check_ts(TsType, Ts0), + check_ts(TsType, Ts1). send(doc) -> []; send(suite) -> []; send(Config) when is_list(Config) -> + lists:foreach(fun do_send/1, ?TIMESTAMP_MODES). + +do_send(TsType) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn(?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token(send,true), + ?line set_token_flags([send, TsType]), ?line Receiver ! send, ?line Self = self(), ?line seq_trace:reset_trace(), - ?line [{0,{send,_,Self,Receiver,send}}] = stop_tracer(1). + ?line [{0,{send,_,Self,Receiver,send}, Ts}] = stop_tracer(1), + check_ts(TsType, Ts). distributed_send(doc) -> []; distributed_send(suite) -> []; distributed_send(Config) when is_list(Config) -> + lists:foreach(fun do_distributed_send/1, ?TIMESTAMP_MODES). + +do_distributed_send(TsType) -> ?line {ok,Node} = start_node(seq_trace_other,[]), ?line {_,Dir} = code:is_loaded(?MODULE), ?line Mdir = filename:dirname(Dir), @@ -170,30 +198,39 @@ distributed_send(Config) when is_list(Config) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn(Node,?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token(send,true), + ?line set_token_flags([send,TsType]), ?line Receiver ! send, ?line Self = self(), ?line seq_trace:reset_trace(), ?line stop_node(Node), - ?line [{0,{send,_,Self,Receiver,send}}] = stop_tracer(1). + ?line [{0,{send,_,Self,Receiver,send}, Ts}] = stop_tracer(1), + check_ts(TsType, Ts). + recv(doc) -> []; recv(suite) -> []; recv(Config) when is_list(Config) -> + lists:foreach(fun do_recv/1, ?TIMESTAMP_MODES). + +do_recv(TsType) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn(?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token('receive',true), + ?line set_token_flags(['receive',TsType]), ?line Receiver ! 'receive', %% let the other process receive the message: ?line receive after 1 -> ok end, ?line Self = self(), ?line seq_trace:reset_trace(), - ?line [{0,{'receive',_,Self,Receiver,'receive'}}] = stop_tracer(1). + ?line [{0,{'receive',_,Self,Receiver,'receive'}, Ts}] = stop_tracer(1), + check_ts(TsType, Ts). distributed_recv(doc) -> []; distributed_recv(suite) -> []; distributed_recv(Config) when is_list(Config) -> + lists:foreach(fun do_distributed_recv/1, ?TIMESTAMP_MODES). + +do_distributed_recv(TsType) -> ?line {ok,Node} = start_node(seq_trace_other,[]), ?line {_,Dir} = code:is_loaded(?MODULE), ?line Mdir = filename:dirname(Dir), @@ -201,7 +238,7 @@ distributed_recv(Config) when is_list(Config) -> ?line seq_trace:reset_trace(), ?line rpc:call(Node,?MODULE,start_tracer,[]), ?line Receiver = spawn(Node,?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token('receive',true), + ?line set_token_flags(['receive',TsType]), ?line Receiver ! 'receive', %% let the other process receive the message: ?line receive after 1 -> ok end, @@ -210,16 +247,20 @@ distributed_recv(Config) when is_list(Config) -> ?line Result = rpc:call(Node,?MODULE,stop_tracer,[1]), ?line stop_node(Node), ?line ok = io:format("~p~n",[Result]), - ?line [{0,{'receive',_,Self,Receiver,'receive'}}] = Result. + ?line [{0,{'receive',_,Self,Receiver,'receive'}, Ts}] = Result, + check_ts(TsType, Ts). trace_exit(doc) -> []; trace_exit(suite) -> []; trace_exit(Config) when is_list(Config) -> + lists:foreach(fun do_trace_exit/1, ?TIMESTAMP_MODES). + +do_trace_exit(TsType) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn_link(?MODULE, one_time_receiver, [exit]), ?line process_flag(trap_exit, true), - ?line seq_trace:set_token(send,true), + ?line set_token_flags([send, TsType]), ?line Receiver ! {before, exit}, %% let the other process receive the message: ?line receive @@ -233,13 +274,18 @@ trace_exit(Config) when is_list(Config) -> ?line Result = stop_tracer(2), ?line seq_trace:reset_trace(), ?line ok = io:format("~p~n", [Result]), - ?line [{0, {send, {0,1}, Self, Receiver, {before, exit}}}, + ?line [{0, {send, {0,1}, Self, Receiver, {before, exit}}, Ts0}, {0, {send, {1,2}, Receiver, Self, - {'EXIT', Receiver, {exit, {before, exit}}}}}] = Result. + {'EXIT', Receiver, {exit, {before, exit}}}}, Ts1}] = Result, + check_ts(TsType, Ts0), + check_ts(TsType, Ts1). distributed_exit(doc) -> []; distributed_exit(suite) -> []; distributed_exit(Config) when is_list(Config) -> + lists:foreach(fun do_distributed_exit/1, ?TIMESTAMP_MODES). + +do_distributed_exit(TsType) -> ?line {ok, Node} = start_node(seq_trace_other, []), ?line {_, Dir} = code:is_loaded(?MODULE), ?line Mdir = filename:dirname(Dir), @@ -248,7 +294,7 @@ distributed_exit(Config) when is_list(Config) -> ?line rpc:call(Node, ?MODULE, start_tracer,[]), ?line Receiver = spawn_link(Node, ?MODULE, one_time_receiver, [exit]), ?line process_flag(trap_exit, true), - ?line seq_trace:set_token(send, true), + ?line set_token_flags([send, TsType]), ?line Receiver ! {before, exit}, %% let the other process receive the message: ?line receive @@ -264,7 +310,8 @@ distributed_exit(Config) when is_list(Config) -> ?line stop_node(Node), ?line ok = io:format("~p~n", [Result]), ?line [{0, {send, {1, 2}, Receiver, Self, - {'EXIT', Receiver, {exit, {before, exit}}}}}] = Result. + {'EXIT', Receiver, {exit, {before, exit}}}}, Ts}] = Result, + check_ts(TsType, Ts). call(doc) -> "Tests special forms {is_seq_trace} and {get_seq_token} " @@ -361,14 +408,22 @@ port(doc) -> "Send trace messages to a port."; port(suite) -> []; port(Config) when is_list(Config) -> + lists:foreach(fun (TsType) -> do_port(TsType, Config) end, + ?TIMESTAMP_MODES). + +do_port(TsType, Config) -> + io:format("Testing ~p~n",[TsType]), ?line Port = load_tracer(Config), ?line seq_trace:set_system_tracer(Port), - ?line seq_trace:set_token(print, true), + ?line set_token_flags([print, TsType]), ?line Small = [small,term], ?line seq_trace:print(0, Small), ?line case get_port_message(Port) of - {seq_trace,0,{print,_,_,[],Small}} -> + {seq_trace,0,{print,_,_,[],Small}} when TsType == no_timestamp -> + ok; + {seq_trace,0,{print,_,_,[],Small},Ts0} when TsType /= no_timestamp -> + check_ts(TsType, Ts0), ok; Other -> ?line seq_trace:reset_trace(), @@ -382,7 +437,10 @@ port(Config) when is_list(Config) -> ?line seq_trace:print(0, OtherSmall), ?line seq_trace:reset_trace(), ?line case get_port_message(Port) of - {seq_trace,0,{print,_,_,[],OtherSmall}} -> + {seq_trace,0,{print,_,_,[],OtherSmall}} when TsType == no_timestamp -> + ok; + {seq_trace,0,{print,_,_,[],OtherSmall}, Ts1} when TsType /= no_timestamp -> + check_ts(TsType, Ts1), ok; Other1 -> ?line ?t:fail({unexpected,Other1}) @@ -399,6 +457,8 @@ port(Config) when is_list(Config) -> Other2 -> ?line ?t:fail({unexpected,Other2}) end, + unlink(Port), + exit(Port,kill), ok. get_port_message(Port) -> @@ -734,7 +794,7 @@ simple_tracer(Data, DN) -> {seq_trace,Label,Info,Ts} -> simple_tracer([{Label,Info,Ts}|Data], DN+1); {seq_trace,Label,Info} -> - simple_tracer([{Label,Info}|Data], DN+1); + simple_tracer([{Label,Info, no_timestamp}|Data], DN+1); {stop,N,From} when DN >= N -> From ! {tracerlog,lists:reverse(Data)} end. @@ -759,7 +819,55 @@ start_tracer() -> seq_trace:set_system_tracer(Pid), Pid. - + +set_token_flags([]) -> + ok; +set_token_flags([no_timestamp|Flags]) -> + seq_trace:set_token(timestamp, false), + seq_trace:set_token(monotonic_timestamp, false), + seq_trace:set_token(strict_monotonic_timestamp, false), + set_token_flags(Flags); +set_token_flags([Flag|Flags]) -> + seq_trace:set_token(Flag, true), + set_token_flags(Flags). + +check_ts(no_timestamp, Ts) -> + try + no_timestamp = Ts + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(timestamp, Ts) -> + try + {Ms,S,Us} = Ts, + true = is_integer(Ms), + true = is_integer(S), + true = is_integer(Us) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(monotonic_timestamp, Ts) -> + try + true = is_integer(Ts) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(strict_monotonic_timestamp, Ts) -> + try + {MT, UMI} = Ts, + true = is_integer(MT), + true = is_integer(UMI) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok. start_node(Name, Param) -> test_server:start_node(Name, slave, [{args, Param}]). -- cgit v1.2.3