Introduce time warp safe trace timestamp formats

New timestamp options for trace, sequential trace, and
system profile:
- monotonic_timestamp
- strict_monotonic_timestamp

4 files changed, 176 insertions, 34 deletions

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 <c>false</c>.</p>
           </item>
+          <tag><c>set_token(strict_monotonic_timestamp, <anno>Bool</anno>)</c></tag>
+          <item>
+            <p>A trace token flag (<c>true | false</c>) which
+            enables/disables a strict monotonic timestamp to be generated
+	    for each traced event. Default is <c>false</c>. Timestamps will
+	    consist of
+	    <seealso marker="erts:time_correction#Erlang_Monotonic_Time">Erlang
+	    monotonic time</seealso> and a monotonically increasing
+	    integer. The time-stamp has the same format and value
+	    as produced by <c>{erlang:monotonic_time(),
+	    erlang:unique_integer([monotonic])}</c>.</p>
+          </item>
+          <tag><c>set_token(monotonic_timestamp, <anno>Bool</anno>)</c></tag>
+          <item>
+            <p>A trace token flag (<c>true | false</c>) which
+            enables/disables a strict monotonic timestamp to be generated
+	    for each traced event. Default is <c>false</c>. Timestamps
+	    will use
+	    <seealso marker="erts:time_correction#Erlang_Monotonic_Time">Erlang
+	    monotonic time</seealso>. The time-stamp has the same
+	    format and value as produced by <c>erlang:monotonic_time()</c>.</p>
+          </item>
+	  <p>If multiple timestamp flags are passed, <c>timestamp</c> has
+	  precedence over <c>strict_monotonic_timestamp</c> which
+	  in turn has precedence over <c>monotonic_timestamp</c>. 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.</p>
         </taglist>
       </desc>
     </func>
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}]).