Introduce time warp safe trace timestamp formats

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

1 files changed, 166 insertions, 83 deletions

diff --git a/erts/emulator/test/trace_bif_SUITE.erl b/erts/emulator/test/trace_bif_SUITE.erl
index a12c41a3aa..760666d077 100644
--- a/erts/emulator/test/trace_bif_SUITE.erl
+++ b/erts/emulator/test/trace_bif_SUITE.erl
@@ -67,7 +67,8 @@ trace_on_and_off(Config) when is_list(Config) ->
     ?line Pid = spawn(?MODULE, bif_process, []),
     ?line Self = self(),
     ?line 1 = erlang:trace(Pid, true, [call,timestamp]),
-    ?line {flags,[timestamp,call]} =  erlang:trace_info(Pid,flags),
+    ?line {flags, Flags} = erlang:trace_info(Pid,flags),
+    ?line [call,timestamp] = lists:sort(Flags),
     ?line {tracer, Self} = erlang:trace_info(Pid,tracer),
     ?line 1 = erlang:trace(Pid, false, [timestamp]),
     ?line {flags,[call]} =  erlang:trace_info(Pid,flags),
@@ -111,93 +112,145 @@ do_trace_bif(Flags) ->
 
 trace_bif_timestamp(doc) -> "Test tracing BIFs with timestamps.";
 trace_bif_timestamp(Config) when is_list(Config) ->
-    do_trace_bif_timestamp([]).
-
+    do_trace_bif_timestamp([], timestamp, [timestamp]),
+    do_trace_bif_timestamp([], timestamp,
+			   [timestamp,
+			    monotonic_timestamp,
+			    strict_monotonic_timestamp]),
+    do_trace_bif_timestamp([], strict_monotonic_timestamp,
+			   [strict_monotonic_timestamp]),
+    do_trace_bif_timestamp([], strict_monotonic_timestamp,
+			   [monotonic_timestamp, strict_monotonic_timestamp]),
+    do_trace_bif_timestamp([], monotonic_timestamp, [monotonic_timestamp]).
+    
 trace_bif_timestamp_local(doc) -> 
     "Test tracing BIFs with timestamps and local flag.";
 trace_bif_timestamp_local(Config) when is_list(Config) ->
-    do_trace_bif_timestamp([local]).
-
-do_trace_bif_timestamp(Flags) ->
-    ?line Pid=spawn(?MODULE, bif_process, []),
-    ?line 1 = erlang:trace(Pid, true, [call,timestamp]),
-    ?line erlang:trace_pattern({erlang,'_','_'}, [], Flags),
-
-    ?line Pid ! {do_bif, time, []},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}),
-
-    ?line Pid ! {do_bif, statistics, [runtime]},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,
-			     {erlang,statistics, [runtime]}}),
-
-    ?line Pid ! {do_time_bif},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,
-			     {erlang,time, []}}),
-
-    ?line Pid ! {do_statistics_bif},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,
-			     {erlang,statistics, [runtime]}}),
+    do_trace_bif_timestamp([local], timestamp, [timestamp]),
+    do_trace_bif_timestamp([local], timestamp,
+			   [timestamp,
+			    monotonic_timestamp,
+			    strict_monotonic_timestamp]),
+    do_trace_bif_timestamp([local], strict_monotonic_timestamp,
+			   [strict_monotonic_timestamp]),
+    do_trace_bif_timestamp([local], strict_monotonic_timestamp,
+			   [monotonic_timestamp, strict_monotonic_timestamp]),
+    do_trace_bif_timestamp([local], monotonic_timestamp, [monotonic_timestamp]).
+
+do_trace_bif_timestamp(Flags, TsType, TsFlags) ->
+    io:format("Testing with TsType=~p TsFlags=~p~n", [TsType, TsFlags]),
+    Pid=spawn(?MODULE, bif_process, []),
+    1 = erlang:trace(Pid, true, [call]++TsFlags),
+    erlang:trace_pattern({erlang,'_','_'}, [], Flags),
+
+    Ts0 = make_ts(TsType),
+    Pid ! {do_bif, time, []},
+    Ts1 = receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}},
+			       Ts0,TsType),
+
+    Pid ! {do_bif, statistics, [runtime]},
+    Ts2 = receive_trace_msg_ts({trace_ts,Pid,call,
+				{erlang,statistics, [runtime]}},
+			       Ts1, TsType),
+
+    Pid ! {do_time_bif},
+    Ts3 = receive_trace_msg_ts({trace_ts,Pid,call,
+				{erlang,time, []}},
+			       Ts2, TsType),
+
+    Pid ! {do_statistics_bif},
+    Ts4 = receive_trace_msg_ts({trace_ts,Pid,call,
+				{erlang,statistics, [runtime]}},
+			       Ts3, TsType),
+
+    check_ts(TsType, Ts4, make_ts(TsType)),
 
     %% We should be able to turn off the timestamp.
-    ?line 1 = erlang:trace(Pid, false, [timestamp]),
+    1 = erlang:trace(Pid, false, TsFlags),
 
-    ?line Pid ! {do_statistics_bif},
-    ?line receive_trace_msg({trace,Pid,call,
-			     {erlang,statistics, [runtime]}}),
+    Pid ! {do_statistics_bif},
+    receive_trace_msg({trace,Pid,call,
+		       {erlang,statistics, [runtime]}}),
 
-    ?line Pid ! {do_bif, statistics, [runtime]},
-    ?line receive_trace_msg({trace,Pid,call,
-			     {erlang,statistics, [runtime]}}),
+    Pid ! {do_bif, statistics, [runtime]},
+    receive_trace_msg({trace,Pid,call,
+		       {erlang,statistics, [runtime]}}),
 
-    ?line 1 = erlang:trace(Pid, false, [call]),
-    ?line erlang:trace_pattern({erlang,'_','_'}, false, Flags),
+    1 = erlang:trace(Pid, false, [call]),
+    erlang:trace_pattern({erlang,'_','_'}, false, Flags),
 
-    ?line exit(Pid, die),
+    exit(Pid, die),
     ok.
 
 trace_bif_return(doc) -> 
     "Test tracing BIF's with return/return_to trace.";
 trace_bif_return(Config) when is_list(Config) ->
-    ?line Pid=spawn(?MODULE, bif_process, []),
-    ?line 1 = erlang:trace(Pid, true, [call,timestamp,return_to]),
-    ?line erlang:trace_pattern({erlang,'_','_'}, [{'_',[],[{return_trace}]}], 
-			       [local]),
-
-
-    ?line Pid ! {do_bif, time, []},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}),
-    ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
-					    {erlang,time,0}}),
-    ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
-					  {?MODULE, bif_process,0}}),
-
-
-    ?line Pid ! {do_bif, statistics, [runtime]},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,
-			     {erlang,statistics, [runtime]}}),
-    ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
-					    {erlang,statistics,1}}),
-    ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
-					  {?MODULE, bif_process,0}}),
-
-
-    ?line Pid ! {do_time_bif},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,
-			     {erlang,time, []}}),
-    ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
-					    {erlang,time,0}}),
-    ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
-					  {?MODULE, bif_process,0}}),
-
-
-
-    ?line Pid ! {do_statistics_bif},
-    ?line receive_trace_msg_ts({trace_ts,Pid,call,
-			     {erlang,statistics, [runtime]}}),
-    ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
-					    {erlang,statistics,1}}),
-    ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
-					  {?MODULE, bif_process,0}}),
+    do_trace_bif_return(timestamp, [timestamp]),
+    do_trace_bif_return(timestamp,
+			[timestamp,
+			 monotonic_timestamp,
+			 strict_monotonic_timestamp]),
+    do_trace_bif_return(strict_monotonic_timestamp,
+			[strict_monotonic_timestamp]),
+    do_trace_bif_return(strict_monotonic_timestamp,
+			[monotonic_timestamp, strict_monotonic_timestamp]),
+    do_trace_bif_return(monotonic_timestamp, [monotonic_timestamp]).
+
+do_trace_bif_return(TsType, TsFlags) ->
+    io:format("Testing with TsType=~p TsFlags=~p~n", [TsType, TsFlags]),
+    Pid=spawn(?MODULE, bif_process, []),
+    1 = erlang:trace(Pid, true, [call,return_to]++TsFlags),
+    erlang:trace_pattern({erlang,'_','_'}, [{'_',[],[{return_trace}]}], 
+			 [local]),
+
+    Ts0 = make_ts(TsType),
+    Pid ! {do_bif, time, []},
+    Ts1 = receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}},
+			       Ts0, TsType),
+    Ts2 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
+					    {erlang,time,0}},
+					   Ts1, TsType),
+    Ts3 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
+					  {?MODULE, bif_process,0}},
+					 Ts2, TsType),
+    
+    
+    Pid ! {do_bif, statistics, [runtime]},
+    Ts4 = receive_trace_msg_ts({trace_ts,Pid,call,
+				{erlang,statistics, [runtime]}},
+			       Ts3, TsType),
+    Ts5 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
+					    {erlang,statistics,1}},
+					   Ts4, TsType),
+    Ts6 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
+					  {?MODULE, bif_process,0}},
+					 Ts5, TsType),
+    
+    
+    Pid ! {do_time_bif},
+    Ts7 = receive_trace_msg_ts({trace_ts,Pid,call,
+				{erlang,time, []}},
+			       Ts6, TsType),
+    Ts8 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
+					    {erlang,time,0}},
+					   Ts7, TsType),
+    Ts9 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
+					  {?MODULE, bif_process,0}},
+					 Ts8, TsType),
+
+
+
+    Pid ! {do_statistics_bif},
+    Ts10 = receive_trace_msg_ts({trace_ts,Pid,call,
+				 {erlang,statistics, [runtime]}},
+				Ts9, TsType),
+    Ts11 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from,
+					     {erlang,statistics,1}},
+					    Ts10, TsType),
+    Ts12 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 
+					   {?MODULE, bif_process,0}},
+					  Ts11, TsType),
+    check_ts(TsType, Ts12, make_ts(TsType)),
     ok.
     
     
@@ -213,10 +266,11 @@ receive_trace_msg(Mess) ->
 	    ?t:fail()
     end.
 
-receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}) ->
+receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}, PrevTs, TsType) ->
     receive
-	{trace_ts, Pid, call, {erlang, F, A}, _Ts} ->
-	    ok;
+	{trace_ts, Pid, call, {erlang, F, A}, Ts} ->
+	    check_ts(TsType, PrevTs, Ts),
+	    Ts;
 	Other ->
 	    io:format("Expected: {trace, ~p, call, {~p, ~p, ~p}, TimeStamp}},~n"
 		      "Got: ~p~n",
@@ -227,10 +281,11 @@ receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}) ->
 	    ?t:fail()
     end.
 
-receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}) ->
+receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}, PrevTs, TsType) ->
     receive
-	{trace_ts, Pid, return_from, {erlang, F, A}, _Value, _Ts} ->
-	    ok;
+	{trace_ts, Pid, return_from, {erlang, F, A}, _Value, Ts} ->
+	    check_ts(TsType, PrevTs, Ts),
+	    Ts;
 	Other ->
 	    io:format("Expected: {trace_ts, ~p, return_from, {~p, ~p, ~p}, Value, TimeStamp}},~n"
 		      "Got: ~p~n",
@@ -241,10 +296,11 @@ receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}) ->
 	    ?t:fail()
     end.
 
-receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}) ->
+receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}, PrevTs, TsType) ->
     receive
-	{trace_ts, Pid, return_to, {M, F, A}, _Ts} ->
-	    ok;
+	{trace_ts, Pid, return_to, {M, F, A}, Ts} ->
+	    check_ts(TsType, PrevTs, Ts),
+	    Ts;
 	Other ->
 	    io:format("Expected: {trace_ts, ~p, return_to, {~p, ~p, ~p}, TimeStamp}},~n"
 		      "Got: ~p~n",
@@ -255,6 +311,33 @@ receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}) ->
 	    ?t:fail()
     end.
 
+make_ts(timestamp) ->
+    erlang:now();
+make_ts(monotonic_timestamp) ->
+    erlang:monotonic_time();
+make_ts(strict_monotonic_timestamp) ->
+    MT = erlang:monotonic_time(),
+    UMI = erlang:unique_integer([monotonic]),
+    {MT, UMI}.
+
+check_ts(timestamp, PrevTs, Ts) ->
+    {Ms, S, Us} = Ts,
+    true = is_integer(Ms),
+    true = is_integer(S),
+    true = is_integer(Us),
+    true = PrevTs < Ts,
+    Ts;
+check_ts(monotonic_timestamp, PrevTs, Ts) ->
+    true = is_integer(Ts),
+    true = PrevTs =< Ts,
+    Ts;
+check_ts(strict_monotonic_timestamp, PrevTs, Ts) ->
+    {MT, UMI} = Ts,
+    true = is_integer(MT),
+    true = is_integer(UMI),
+    true = PrevTs < Ts,
+    Ts.
+
 bif_process() ->
     receive
 	{do_bif, Name, Args} ->