diff options
Diffstat (limited to 'erts/emulator/test')
| -rw-r--r-- | erts/emulator/test/system_profile_SUITE.erl | 155 | ||||
| -rw-r--r-- | erts/emulator/test/trace_bif_SUITE.erl | 249 |
2 files changed, 288 insertions, 116 deletions
diff --git a/erts/emulator/test/system_profile_SUITE.erl b/erts/emulator/test/system_profile_SUITE.erl index e4b6511d1f..2ecb4a28a7 100644 --- a/erts/emulator/test/system_profile_SUITE.erl +++ b/erts/emulator/test/system_profile_SUITE.erl @@ -113,13 +113,27 @@ runnable_procs(suite) -> runnable_procs(doc) -> ["Tests system_profiling with runnable_procs."]; runnable_procs(Config) when is_list(Config) -> + lists:foreach(fun (TsType) -> + Arg = case TsType of + no_timestamp -> + {timestamp, []}; + _ -> + {TsType, [TsType]} + end, + do_runnable_procs(Arg), + receive after 1000 -> ok end + end, + [no_timestamp, timestamp, monotonic_timestamp, + strict_monotonic_timestamp]). + +do_runnable_procs({TsType, TsTypeFlag}) -> Pid = start_profiler_process(), % start a ring of processes % FIXME: Set #laps and #nodes in config file Nodes = 10, Laps = 10, Master = ring(Nodes), - undefined = erlang:system_profile(Pid, [runnable_procs]), + undefined = erlang:system_profile(Pid, [runnable_procs]++TsTypeFlag), % loop a message ok = ring_message(Master, message, Laps), Events = get_profiler_events(), @@ -127,9 +141,9 @@ runnable_procs(Config) when is_list(Config) -> erlang:system_profile(undefined, []), put(master, Master), put(laps, Laps), - true = has_runnable_event(Events), + true = has_runnable_event(TsType, Events), Pids = sort_events_by_pid(Events), - ok = check_events(Pids), + ok = check_events(TsType, Pids), erase(), exit(Pid,kill), ok. @@ -139,8 +153,22 @@ runnable_ports(suite) -> runnable_ports(doc) -> ["Tests system_profiling with runnable_port."]; runnable_ports(Config) when is_list(Config) -> + lists:foreach(fun (TsType) -> + Arg = case TsType of + no_timestamp -> + {timestamp, []}; + _ -> + {TsType, [TsType]} + end, + do_runnable_ports(Arg, Config), + receive after 1000 -> ok end + end, + [no_timestamp, timestamp, monotonic_timestamp, + strict_monotonic_timestamp]). + +do_runnable_ports({TsType, TsTypeFlag}, Config) -> Pid = start_profiler_process(), - undefined = erlang:system_profile(Pid, [runnable_ports]), + undefined = erlang:system_profile(Pid, [runnable_ports]++TsTypeFlag), EchoPid = echo(Config), % FIXME: Set config to number_of_echos Laps = 10, @@ -149,9 +177,9 @@ runnable_ports(Config) when is_list(Config) -> Events = get_profiler_events(), kill_em_all = kill_echo(EchoPid), erlang:system_profile(undefined, []), - true = has_runnable_event(Events), + true = has_runnable_event(TsType, Events), Pids = sort_events_by_pid(Events), - ok = check_events(Pids), + ok = check_events(TsType, Pids), erase(), exit(Pid,kill), ok. @@ -166,8 +194,19 @@ scheduler(Config) when is_list(Config) -> {_, 1} -> {skipped, "No need for scheduler test when only one scheduler online."}; _ -> Nodes = 10, - ok = check_block_system(Nodes), - ok = check_multi_scheduling_block(Nodes) + lists:foreach(fun (TsType) -> + Arg = case TsType of + no_timestamp -> + {timestamp, []}; + _ -> + {TsType, [TsType]} + end, + ok = check_block_system(Arg, Nodes), + ok = check_multi_scheduling_block(Arg, Nodes), + receive after 1000 -> ok end + end, + [no_timestamp, timestamp, monotonic_timestamp, + strict_monotonic_timestamp]) end. % the profiler pid should not be profiled @@ -195,9 +234,9 @@ dont_profile_profiler(Config) when is_list(Config) -> %%% Check scheduler profiling -check_multi_scheduling_block(Nodes) -> +check_multi_scheduling_block({TsType, TsTypeFlag}, Nodes) -> Pid = start_profiler_process(), - undefined = erlang:system_profile(Pid, [scheduler]), + undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag), {ok, Supervisor} = start_load(Nodes), wait(600), erlang:system_flag(multi_scheduling, block), @@ -205,23 +244,23 @@ check_multi_scheduling_block(Nodes) -> erlang:system_flag(multi_scheduling, unblock), {Pid, [scheduler]} = erlang:system_profile(undefined, []), Events = get_profiler_events(), - true = has_scheduler_event(Events), + true = has_scheduler_event(TsType, Events), stop_load(Supervisor), exit(Pid,kill), erase(), ok. -check_block_system(Nodes) -> +check_block_system({TsType, TsTypeFlag}, Nodes) -> Dummy = spawn(?MODULE, profiler_process, [[]]), Pid = start_profiler_process(), - undefined = erlang:system_profile(Pid, [scheduler]), + undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag), {ok, Supervisor} = start_load(Nodes), wait(300), undefined = erlang:system_monitor(Dummy, [busy_port]), {Dummy, [busy_port]} = erlang:system_monitor(undefined, []), {Pid, [scheduler]} = erlang:system_profile(undefined, []), Events = get_profiler_events(), - true = has_scheduler_event(Events), + true = has_scheduler_event(TsType, Events), stop_load(Supervisor), exit(Pid,kill), exit(Dummy,kill), @@ -230,40 +269,49 @@ check_block_system(Nodes) -> %%% Check events -check_events([]) -> ok; -check_events([Pid | Pids]) -> +check_events(_TsType, []) -> ok; +check_events(TsType, [Pid | Pids]) -> Master = get(master), Laps = get(laps), CheckPids = get(pids), {Events, N} = get_pid_events(Pid), ok = check_event_flow(Events), - ok = check_event_ts(Events), + ok = check_event_ts(TsType, Events), IsMember = lists:member(Pid, CheckPids), case Pid of Master -> io:format("Expected ~p and got ~p profile events from ~p: ok~n", [Laps*2+2, N, Pid]), N = Laps*2 + 2, - check_events(Pids); + check_events(TsType, Pids); Pid when IsMember == true -> io:format("Expected ~p and got ~p profile events from ~p: ok~n", [Laps*2, N, Pid]), N = Laps*2, - check_events(Pids); + check_events(TsType, Pids); Pid -> - check_events(Pids) + check_events(TsType, Pids) end. %% timestamp consistency check for descending timestamps -check_event_ts(Events) -> - check_event_ts(Events, undefined). -check_event_ts([], _) -> ok; -check_event_ts([Event | Events], undefined) -> - check_event_ts(Events, Event); -check_event_ts([{Pid, _, _, TS1}=Event | Events], {Pid,_,_,TS0}) -> - Time = timer:now_diff(TS1, TS0), +check_event_ts(TsType, Events) -> + check_event_ts(TsType, Events, undefined). +check_event_ts(_TsType, [], _) -> ok; +check_event_ts(TsType, [Event | Events], undefined) -> + check_event_ts(TsType, Events, Event); +check_event_ts(TsType, [{Pid, _, _, TS1}=Event | Events], {Pid,_,_,TS0}) -> + Time = case TsType of + timestamp -> + timer:now_diff(TS1, TS0); + monotonic_timestamp -> + TS1 - TS0; + strict_monotonic_timestamp -> + {MT1, _} = TS1, + {MT0, _} = TS0, + MT1 - MT0 + end, if Time < 0.0 -> timestamp_error; - true -> check_event_ts(Events, Event) + true -> check_event_ts(TsType, Events, Event) end. %% consistency check for active vs. inactive activity (runnable) @@ -428,6 +476,44 @@ port_echo_loop(Port) -> %% Helpers %%% +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_load(N) -> Pid = spawn_link(?MODULE, run_load, [N, []]), {ok, Pid}. @@ -454,21 +540,24 @@ list_load() -> end, list_load(). - -has_scheduler_event(Events) -> +has_scheduler_event(TsType, Events) -> lists:any( fun (Pred) -> case Pred of - {profile, scheduler, _ID, _Activity, _NR, _TS} -> true; + {profile, scheduler, _ID, _Activity, _NR, TS} -> + check_ts(TsType, TS), + true; _ -> false end end, Events). -has_runnable_event(Events) -> +has_runnable_event(TsType, Events) -> lists:any( fun (Pred) -> case Pred of - {profile, _Pid, _Activity, _MFA, _TS} -> true; + {profile, _Pid, _Activity, _MFA, TS} -> + check_ts(TsType, TS), + true; _ -> false end end, Events). 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} -> |