diff options
Diffstat (limited to 'erts/emulator/test')
-rw-r--r-- | erts/emulator/test/bs_construct_SUITE.erl | 40 | ||||
-rw-r--r-- | erts/emulator/test/nif_SUITE.erl | 153 | ||||
-rw-r--r-- | erts/emulator/test/nif_SUITE_data/nif_SUITE.c | 94 | ||||
-rw-r--r-- | erts/emulator/test/process_SUITE.erl | 47 | ||||
-rw-r--r-- | erts/emulator/test/statistics_SUITE.erl | 120 | ||||
-rw-r--r-- | erts/emulator/test/system_profile_SUITE.erl | 155 | ||||
-rw-r--r-- | erts/emulator/test/trace_bif_SUITE.erl | 249 |
7 files changed, 730 insertions, 128 deletions
diff --git a/erts/emulator/test/bs_construct_SUITE.erl b/erts/emulator/test/bs_construct_SUITE.erl index cadb30e1a4..7ed99f5b4e 100644 --- a/erts/emulator/test/bs_construct_SUITE.erl +++ b/erts/emulator/test/bs_construct_SUITE.erl @@ -29,7 +29,7 @@ mem_leak/1, coerce_to_float/1, bjorn/1, huge_float_field/1, huge_binary/1, system_limit/1, badarg/1, copy_writable_binary/1, kostis/1, dynamic/1, bs_add/1, - otp_7422/1, zero_width/1, bad_append/1]). + otp_7422/1, zero_width/1, bad_append/1, bs_add_overflow/1]). -include_lib("test_server/include/test_server.hrl"). @@ -40,7 +40,7 @@ all() -> in_guard, mem_leak, coerce_to_float, bjorn, huge_float_field, huge_binary, system_limit, badarg, copy_writable_binary, kostis, dynamic, bs_add, otp_7422, zero_width, - bad_append]. + bad_append, bs_add_overflow]. groups() -> []. @@ -551,10 +551,24 @@ huge_binary(Config) when is_list(Config) -> ?line 16777216 = size(<<0:(id(1 bsl 26)),(-1):(id(1 bsl 26))>>), ?line garbage_collect(), {Shift,Return} = case free_mem() of - undefined -> {32,ok}; - Mb when Mb > 600 -> {32,ok}; - Mb when Mb > 300 -> {31,"Limit huge binaries to 256 Mb"}; - _ -> {30,"Limit huge binary to 128 Mb"} + undefined -> + %% This test has to be inlined inside the case to + %% use a literal Shift + ?line garbage_collect(), + ?line id(<<0:((1 bsl 32)-1)>>), + {32,ok}; + Mb when Mb > 600 -> + ?line garbage_collect(), + ?line id(<<0:((1 bsl 32)-1)>>), + {32,ok}; + Mb when Mb > 300 -> + ?line garbage_collect(), + ?line id(<<0:((1 bsl 31)-1)>>), + {31,"Limit huge binaries to 256 Mb"}; + _ -> + ?line garbage_collect(), + ?line id(<<0:((1 bsl 30)-1)>>), + {30,"Limit huge binary to 128 Mb"} end, ?line garbage_collect(), ?line id(<<0:((1 bsl Shift)-1)>>), @@ -911,5 +925,19 @@ append_unit_8(Bin) -> append_unit_16(Bin) -> <<Bin/binary-unit:16,0:1>>. +%% Produce a large result of bs_add that, if cast to signed int, would overflow +%% into a negative number that fits a smallnum. +bs_add_overflow(Config) -> + case erlang:system_info(wordsize) of + 8 -> + {skip, "64-bit architecture"}; + 4 -> + Large = <<0:((1 bsl 30)-1)>>, + {'EXIT',{system_limit,_}} = + (catch <<Large/bits, Large/bits, Large/bits, Large/bits, + Large/bits, Large/bits, Large/bits, Large/bits, + Large/bits>>), + ok + end. id(I) -> I. diff --git a/erts/emulator/test/nif_SUITE.erl b/erts/emulator/test/nif_SUITE.erl index 56b36d2626..b02a090103 100644 --- a/erts/emulator/test/nif_SUITE.erl +++ b/erts/emulator/test/nif_SUITE.erl @@ -42,7 +42,8 @@ otp_9668/1, consume_timeslice/1, dirty_nif/1, dirty_nif_send/1, dirty_nif_exception/1, call_dirty_nif_exception/1, nif_schedule/1, nif_exception/1, call_nif_exception/1, - nif_nan_and_inf/1, nif_atom_too_long/1 + nif_nan_and_inf/1, nif_atom_too_long/1, + nif_monotonic_time/1, nif_time_offset/1, nif_convert_time_unit/1 ]). -export([many_args_100/100]). @@ -72,7 +73,8 @@ all() -> otp_9828, otp_9668, consume_timeslice, nif_schedule, dirty_nif, dirty_nif_send, dirty_nif_exception, - nif_exception, nif_nan_and_inf, nif_atom_too_long + nif_exception, nif_nan_and_inf, nif_atom_too_long, + nif_monotonic_time, nif_time_offset, nif_convert_time_unit ]. groups() -> @@ -1780,6 +1782,148 @@ nif_raise_exceptions(NifFunc) -> end end, ok, ExcTerms). +-define(ERL_NIF_TIME_ERROR, -9223372036854775808). +-define(TIME_UNITS, [seconds, milli_seconds, micro_seconds, nano_seconds]). + +nif_monotonic_time(Config) -> + ?ERL_NIF_TIME_ERROR = monotonic_time(invalid_time_unit), + mtime_loop(1000000). + +mtime_loop(0) -> + ok; +mtime_loop(N) -> + chk_mtime(?TIME_UNITS), + mtime_loop(N-1). + +chk_mtime([]) -> + ok; +chk_mtime([TU|TUs]) -> + A = erlang:monotonic_time(TU), + B = monotonic_time(TU), + C = erlang:monotonic_time(TU), + try + true = A =< B, + true = B =< C + catch + _ : _ -> + ?t:fail({monotonic_time_missmatch, TU, A, B, C}) + end, + chk_mtime(TUs). + +nif_time_offset(Config) -> + ?ERL_NIF_TIME_ERROR = time_offset(invalid_time_unit), + toffs_loop(1000000). + +toffs_loop(0) -> + ok; +toffs_loop(N) -> + chk_toffs(?TIME_UNITS), + toffs_loop(N-1). + +chk_toffs([]) -> + ok; +chk_toffs([TU|TUs]) -> + TO = erlang:time_offset(TU), + NifTO = time_offset(TU), + case TO =:= NifTO of + true -> + ok; + false -> + case erlang:system_info(time_warp_mode) of + no_time_warp -> + ?t:fail({time_offset_mismatch, TU, TO, NifTO}); + _ -> + %% Most frequent time offset change + %% is currently only every 15:th + %% second so this should currently + %% work... + NTO = erlang:time_offset(TU), + case NifTO =:= NTO of + true -> + ok; + false -> + ?t:fail({time_offset_mismatch, TU, TO, NifTO, NTO}) + end + end + end, + chk_toffs(TUs). + +nif_convert_time_unit(Config) -> + ?ERL_NIF_TIME_ERROR = convert_time_unit(0, seconds, invalid_time_unit), + ?ERL_NIF_TIME_ERROR = convert_time_unit(0, invalid_time_unit, seconds), + ?ERL_NIF_TIME_ERROR = convert_time_unit(0, invalid_time_unit, invalid_time_unit), + lists:foreach(fun (Offset) -> + lists:foreach(fun (Diff) -> + chk_ctu(Diff+(Offset*1000*1000*1000)) + end, + [999999999999, + 99999999999, + 9999999999, + 999999999, + 99999999, + 9999999, + 999999, + 99999, + 999, + 99, + 9, + 1, + 11, + 101, + 1001, + 10001, + 100001, + 1000001, + 10000001, + 100000001, + 1000000001, + 100000000001, + 1000000000001, + 5, + 50, + 500, + 5000, + 50000, + 500000, + 5000000, + 50000000, + 500000000, + 5000000000, + 50000000000, + 500000000000]) + end, + [-4711, -1000, -475, -5, -4, -3, -2, -1, 0, + 1, 2, 3, 4, 5, 475, 1000, 4711]), + ctu_loop(1000000). + +ctu_loop(0) -> + ok; +ctu_loop(N) -> + chk_ctu(erlang:monotonic_time(nano_seconds)), + ctu_loop(N-1). + +chk_ctu(Time) -> + chk_ctu(Time, ?TIME_UNITS). + +chk_ctu(_Time, []) -> + ok; +chk_ctu(Time, [FromTU|FromTUs]) -> + chk_ctu(Time, FromTU, ?TIME_UNITS), + chk_ctu(Time, FromTUs). + +chk_ctu(_Time, _FromTU, []) -> + ok; +chk_ctu(Time, FromTU, [ToTU|ToTUs]) -> + T = erlang:convert_time_unit(Time, nano_seconds, FromTU), + TE = erlang:convert_time_unit(T, FromTU, ToTU), + TN = convert_time_unit(T, FromTU, ToTU), + case TE =:= TN of + false -> + ?t:fail({conversion_mismatch, FromTU, T, ToTU, TE, TN}); + true -> + chk_ctu(Time, FromTU, ToTUs) + end. + %% The NIFs: lib_version() -> undefined. call_history() -> ?nif_stub. @@ -1849,6 +1993,11 @@ make_map_remove_nif(_,_) -> ?nif_stub. maps_from_list_nif(_) -> ?nif_stub. sorted_list_from_maps_nif(_) -> ?nif_stub. +%% Time +monotonic_time(_) -> ?nif_stub. +time_offset(_) -> ?nif_stub. +convert_time_unit(_,_,_) -> ?nif_stub. + nif_stub_error(Line) -> exit({nif_not_loaded,module,?MODULE,line,Line}). diff --git a/erts/emulator/test/nif_SUITE_data/nif_SUITE.c b/erts/emulator/test/nif_SUITE_data/nif_SUITE.c index 98e1efe18f..8ebce4fef4 100644 --- a/erts/emulator/test/nif_SUITE_data/nif_SUITE.c +++ b/erts/emulator/test/nif_SUITE_data/nif_SUITE.c @@ -34,6 +34,10 @@ static ERL_NIF_TERM atom_self; static ERL_NIF_TERM atom_ok; static ERL_NIF_TERM atom_join; static ERL_NIF_TERM atom_binary_resource_type; +static ERL_NIF_TERM atom_seconds; +static ERL_NIF_TERM atom_milli_seconds; +static ERL_NIF_TERM atom_micro_seconds; +static ERL_NIF_TERM atom_nano_seconds; typedef struct @@ -138,6 +142,10 @@ static int load(ErlNifEnv* env, void** priv_data, ERL_NIF_TERM load_info) atom_ok = enif_make_atom(env,"ok"); atom_join = enif_make_atom(env,"join"); atom_binary_resource_type = enif_make_atom(env,"binary_resource_type"); + atom_seconds = enif_make_atom(env,"seconds"); + atom_milli_seconds = enif_make_atom(env,"milli_seconds"); + atom_micro_seconds = enif_make_atom(env,"micro_seconds"); + atom_nano_seconds = enif_make_atom(env,"nano_seconds"); *priv_data = data; return 0; @@ -1885,6 +1893,87 @@ static ERL_NIF_TERM sorted_list_from_maps_nif(ErlNifEnv* env, int argc, const ER return enif_make_tuple2(env, list_f, list_b); } + +static ERL_NIF_TERM monotonic_time(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) +{ + ErlNifTimeUnit time_unit; + + if (argc != 1) + return atom_false; + + if (enif_compare(argv[0], atom_seconds) == 0) + time_unit = ERL_NIF_SEC; + else if (enif_compare(argv[0], atom_milli_seconds) == 0) + time_unit = ERL_NIF_MSEC; + else if (enif_compare(argv[0], atom_micro_seconds) == 0) + time_unit = ERL_NIF_USEC; + else if (enif_compare(argv[0], atom_nano_seconds) == 0) + time_unit = ERL_NIF_NSEC; + else + time_unit = 4711; /* invalid time unit */ + + return enif_make_int64(env, enif_monotonic_time(time_unit)); +} + +static ERL_NIF_TERM time_offset(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) +{ + ErlNifTimeUnit time_unit; + + if (argc != 1) + return atom_false; + + if (enif_compare(argv[0], atom_seconds) == 0) + time_unit = ERL_NIF_SEC; + else if (enif_compare(argv[0], atom_milli_seconds) == 0) + time_unit = ERL_NIF_MSEC; + else if (enif_compare(argv[0], atom_micro_seconds) == 0) + time_unit = ERL_NIF_USEC; + else if (enif_compare(argv[0], atom_nano_seconds) == 0) + time_unit = ERL_NIF_NSEC; + else + time_unit = 4711; /* invalid time unit */ + return enif_make_int64(env, enif_time_offset(time_unit)); +} + +static ERL_NIF_TERM convert_time_unit(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) +{ + ErlNifSInt64 i64; + ErlNifTime val; + ErlNifTimeUnit from, to; + + if (argc != 3) + return atom_false; + + if (!enif_get_int64(env, argv[0], &i64)) + return enif_make_badarg(env); + + val = (ErlNifTime) i64; + + if (enif_compare(argv[1], atom_seconds) == 0) + from = ERL_NIF_SEC; + else if (enif_compare(argv[1], atom_milli_seconds) == 0) + from = ERL_NIF_MSEC; + else if (enif_compare(argv[1], atom_micro_seconds) == 0) + from = ERL_NIF_USEC; + else if (enif_compare(argv[1], atom_nano_seconds) == 0) + from = ERL_NIF_NSEC; + else + from = 4711; /* invalid time unit */ + + if (enif_compare(argv[2], atom_seconds) == 0) + to = ERL_NIF_SEC; + else if (enif_compare(argv[2], atom_milli_seconds) == 0) + to = ERL_NIF_MSEC; + else if (enif_compare(argv[2], atom_micro_seconds) == 0) + to = ERL_NIF_USEC; + else if (enif_compare(argv[2], atom_nano_seconds) == 0) + to = ERL_NIF_NSEC; + else + to = 4711; /* invalid time unit */ + + return enif_make_int64(env, enif_convert_time_unit(val, from, to)); +} + static ErlNifFunc nif_funcs[] = { {"lib_version", 0, lib_version}, @@ -1954,7 +2043,10 @@ static ErlNifFunc nif_funcs[] = {"make_map_update_nif", 3, make_map_update_nif}, {"make_map_remove_nif", 2, make_map_remove_nif}, {"maps_from_list_nif", 1, maps_from_list_nif}, - {"sorted_list_from_maps_nif", 1, sorted_list_from_maps_nif} + {"sorted_list_from_maps_nif", 1, sorted_list_from_maps_nif}, + {"monotonic_time", 1, monotonic_time}, + {"time_offset", 1, time_offset}, + {"convert_time_unit", 3, convert_time_unit} }; ERL_NIF_INIT(nif_SUITE,nif_funcs,load,reload,upgrade,unload) diff --git a/erts/emulator/test/process_SUITE.erl b/erts/emulator/test/process_SUITE.erl index 97aa5e573e..bfd1e78bf0 100644 --- a/erts/emulator/test/process_SUITE.erl +++ b/erts/emulator/test/process_SUITE.erl @@ -41,6 +41,7 @@ process_info_2_list/1, process_info_lock_reschedule/1, process_info_lock_reschedule2/1, process_info_lock_reschedule3/1, + process_info_garbage_collection/1, bump_reductions/1, low_prio/1, binary_owner/1, yield/1, yield2/1, process_status_exiting/1, otp_4725/1, bad_register/1, garbage_collect/1, otp_6237/1, @@ -75,7 +76,9 @@ all() -> process_info_other_dist_msg, process_info_2_list, process_info_lock_reschedule, process_info_lock_reschedule2, - process_info_lock_reschedule3, process_status_exiting, + process_info_lock_reschedule3, + process_info_garbage_collection, + process_status_exiting, bump_reductions, low_prio, yield, yield2, otp_4725, bad_register, garbage_collect, process_info_messages, process_flag_badarg, process_flag_heap_size, @@ -932,6 +935,48 @@ start_spawner() -> stop_spawner() -> ok. +%% Tests erlang:process_info(Pid, garbage_collection_info) +process_info_garbage_collection(_Config) -> + Parent = self(), + Pid = spawn_link( + fun() -> + receive go -> ok end, + (fun F(0) -> + Parent ! deep, + receive ok -> ok end, + []; + F(N) -> + timer:sleep(1), + [lists:seq(1,100) | F(N-1)] + end)(1000), + Parent ! shallow, + receive done -> ok end + end), + {garbage_collection_info, Before} = + erlang:process_info(Pid, garbage_collection_info), + Pid ! go, receive deep -> ok end, + {_, Deep} = erlang:process_info(Pid, garbage_collection_info), + Pid ! ok, receive shallow -> ok end, + {_, After} = erlang:process_info(Pid, garbage_collection_info), + Pid ! done, + + %% Do some general checks to see if everything seems to be roughly correct + ct:log("Before: ~p",[Before]), + ct:log("Deep: ~p",[Deep]), + ct:log("After: ~p",[After]), + + %% Check stack_size + true = proplists:get_value(stack_size, Before) < proplists:get_value(stack_size, Deep), + true = proplists:get_value(stack_size, After) < proplists:get_value(stack_size, Deep), + + %% Check used heap size + true = proplists:get_value(heap_size, Before) + proplists:get_value(old_heap_size, Before) + < proplists:get_value(heap_size, Deep) + proplists:get_value(old_heap_size, Deep), + true = proplists:get_value(heap_size, Before) + proplists:get_value(old_heap_size, Before) + < proplists:get_value(heap_size, After) + proplists:get_value(old_heap_size, After), + + ok. + %% Tests erlang:bump_reductions/1. bump_reductions(Config) when is_list(Config) -> erlang:garbage_collect(), diff --git a/erts/emulator/test/statistics_SUITE.erl b/erts/emulator/test/statistics_SUITE.erl index 53c9ba8715..aab3d3e3d2 100644 --- a/erts/emulator/test/statistics_SUITE.erl +++ b/erts/emulator/test/statistics_SUITE.erl @@ -32,7 +32,7 @@ run_queue_one/1, scheduler_wall_time/1, reductions/1, reductions_big/1, garbage_collection/1, io/1, - badarg/1, run_queues_lengths_active_tasks/1]). + badarg/1, run_queues_lengths_active_tasks/1, msacc/1]). %% Internal exports. @@ -55,7 +55,8 @@ all() -> [{group, wall_clock}, {group, runtime}, reductions, reductions_big, {group, run_queue}, scheduler_wall_time, garbage_collection, io, badarg, - run_queues_lengths_active_tasks]. + run_queues_lengths_active_tasks, + msacc]. groups() -> [{wall_clock, [], @@ -440,6 +441,10 @@ run_queues_lengths_active_tasks(Config) -> SO = erlang:system_flag(schedulers_online, 1), + %% Give newly suspended schedulers some time to + %% migrate away work from their run queues... + receive after 1000 -> ok end, + TRQLs1 = statistics(total_run_queue_lengths), TATs1 = statistics(total_active_tasks), true = TRQLs1 >= 10, @@ -466,3 +471,114 @@ run_queues_lengths_active_tasks(Config) -> TokLoops), ok. + +msacc(doc) -> + "Tests that statistics(microstate_statistics) works."; +msacc(Config) -> + + %% Test if crypto nif is available + Niff = try crypto:strong_rand_bytes(1), ok catch _:_ -> nok end, + TmpFile = filename:join(proplists:get_value(priv_dir,Config),"file.tmp"), + + false = erlang:system_flag(microstate_accounting, true), + + msacc_test(TmpFile), + + true = erlang:system_flag(microstate_accounting, false), + + MsaccStats = erlang:statistics(microstate_accounting), + + case os:type() of + {win32, _} -> + %% Some windows have a very poor accuracy on their + %% timing primitives, so we just make sure that + %% some state besides sleep has been triggered. + Sum = lists:sum( + lists:map(fun({sleep, _V}) -> 0; + ({_, V}) -> V + end, maps:to_list(msacc_sum_states())) + ), + if Sum > 0 -> + ok; + true -> + ct:fail({no_states_triggered, MsaccStats}) + end; + _ -> + + %% Make sure that all states were triggered at least once + maps:map(fun(nif, 0) -> + case Niff of + ok -> + ct:fail({zero_state,nif}); + nok -> + ok + end; + (aux, 0) -> + %% aux will be zero if we do not have smp support + %% or no async threads + case erlang:system_info(smp_support) orelse + erlang:system_info(thread_pool_size) > 0 + of + false -> + ok; + true -> + ct:log("msacc: ~p",[MsaccStats]), + ct:fail({zero_state,aux}) + end; + (Key, 0) -> + ct:log("msacc: ~p",[MsaccStats]), + ct:fail({zero_state,Key}); + (_,_) -> ok + end, msacc_sum_states()) + end, + + erlang:system_flag(microstate_accounting, reset), + + msacc_test(TmpFile), + + %% Make sure all counters are zero after stopping and resetting + maps:map(fun(_Key, 0) -> ok; + (Key,_) -> + ct:log("msacc: ~p",[erlang:statistics(microstate_accounting)]), + ct:fail({non_zero_state,Key}) + end,msacc_sum_states()). + +%% This test tries to make sure to trigger all of the different available states +msacc_test(TmpFile) -> + + %% We write some data + [file:write_file(TmpFile,<<0:(1024*1024*8)>>,[raw]) || _ <- lists:seq(1,100)], + + %% Do some ETS operations + Tid = ets:new(table, []), + ets:insert(Tid, {1, hello}), + ets:delete(Tid), + + %% Collect some garbage + [erlang:garbage_collect() || _ <- lists:seq(1,100)], + + %% Send some messages + [begin self() ! {hello},receive _ -> ok end end || _ <- lists:seq(1,100)], + + %% Setup some timers + Refs = [erlang:send_after(10000,self(),ok) || _ <- lists:seq(1,100)], + + %% Do some nif work + catch [crypto:strong_rand_bytes(128) || _ <- lists:seq(1,100)], + + %% Cancel some timers + [erlang:cancel_timer(R) || R <- Refs], + + %% Wait for a while + timer:sleep(100). + +msacc_sum_states() -> + Stats = erlang:statistics(microstate_accounting), + [#{ counters := C }|_] = Stats, + InitialCounters = maps:map(fun(_,_) -> 0 end,C), + lists:foldl(fun(#{ counters := Counters }, Cnt) -> + maps:fold(fun(Key, Value, Acc) -> + NewValue = Value+maps:get(Key,Acc), + maps:update(Key, NewValue, Acc) + end, Cnt, Counters) + end,InitialCounters,Stats). diff --git a/erts/emulator/test/system_profile_SUITE.erl b/erts/emulator/test/system_profile_SUITE.erl index 0a0784337f..6e85f8c54e 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..96b7dd159f 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(nano_seconds); +make_ts(strict_monotonic_timestamp) -> + MT = erlang:monotonic_time(nano_seconds), + 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} -> |