%% %% %CopyrightBegin% %% %% Copyright Ericsson AB 2011-2016. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. %% You may obtain a copy of the License at %% %% http://www.apache.org/licenses/LICENSE-2.0 %% %% Unless required by applicable law or agreed to in writing, software %% distributed under the License is distributed on an "AS IS" BASIS, %% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. %% See the License for the specific language governing permissions and %% limitations under the License. %% %% %CopyrightEnd% %% %%% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %%% %%% Define to run outside of test server %%% %%% -define(STANDALONE,1). %%% %%% %%% Define for debug output %%% %%% -define(debug,1). -module(trace_call_time_SUITE). %% Exported end user tests -export([seq/3, seq_r/3]). -export([loaded/1, a_function/1, a_called_function/1, dec/1, nif_dec/1, dead_tracer/1]). -define(US_ERROR, 10000). -define(R_ERROR, 0.8). -define(SINGLE_CALL_US_TIME, 10). %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Result examination macros -define(CT(P,MFA),{trace,P,call,MFA}). -define(CTT(P, MFA),{trace_ts,P,call,MFA,{_,_,_}}). -define(RF(P,MFA,V),{trace,P,return_from,MFA,V}). -define(RFT(P,MFA,V),{trace_ts,P,return_from,MFA,V,{_,_,_}}). -define(RT(P,MFA),{trace,P,return_to,MFA}). -define(RTT(P,MFA),{trace_ts,P,return_to,MFA,{_,_,_}}). -ifdef(debug). -define(dbgformat(A,B),io:format(A,B)). -else. -define(dbgformat(A,B),noop). -endif. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -include_lib("common_test/include/ct.hrl"). %% When run in test server. -export([all/0, suite/0, init_per_testcase/2, end_per_testcase/2, not_run/1]). -export([basic/1, on_and_off/1, info/1, pause_and_restart/1, scheduling/1, called_function/1, combo/1, bif/1, nif/1]). init_per_testcase(_Case, Config) -> erlang:trace_pattern({'_','_','_'}, false, [local,meta,call_time,call_count]), erlang:trace_pattern(on_load, false, [local,meta,call_time,call_count]), timer:now_diff(now(),now()), Config. end_per_testcase(_Case, _Config) -> erlang:trace_pattern({'_','_','_'}, false, [local,meta,call_time,call_count]), erlang:trace_pattern(on_load, false, [local,meta,call_time,call_count]), erlang:trace(all, false, [all]), ok. suite() -> [{ct_hooks,[ts_install_cth]}, {timetrap, {minutes, 10}}]. all() -> case test_server:is_native(trace_call_time_SUITE) of true -> [not_run]; false -> [basic, on_and_off, info, pause_and_restart, scheduling, combo, bif, nif, called_function, dead_tracer] end. not_run(Config) when is_list(Config) -> {skipped,"Native code"}. %% Tests basic call time trace basic(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 1000, %% 1 = erlang:trace_pattern({?MODULE,seq, '_'}, true, [call_time]), 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, true, [call_time]), Pid = setup(), {L, T1} = execute(Pid, fun() -> seq(1, M, fun(X) -> (X+1) end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T1), ok = check_trace_info({?MODULE, seq_r, 3}, [], none), {Lr, T2} = execute(Pid, fun() -> seq_r(1, M, fun(X) -> (X+1) end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T1), ok = check_trace_info({?MODULE, seq_r, 3}, [{Pid, 1, 0, 0}], T2/M), ok = check_trace_info({?MODULE, seq_r, 4}, [{Pid, M, 0, 0}], T2), L = lists:reverse(Lr), %% P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), Pid ! quit, ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% "Tests turning trace parameters on and off on_and_off(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 100, %% 1 = erlang:trace_pattern({?MODULE,seq,'_'}, true, [call_time]), Pid = setup(), {L, T1} = execute(Pid, {?MODULE, seq, [1, M, fun(X) -> X+1 end]}), ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T1), N = erlang:trace_pattern({?MODULE,'_','_'}, true, [call_time]), {L, T2} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T2), P = erlang:trace_pattern({'_','_','_'}, true, [call_time]), {L, T3} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T3), 1 = erlang:trace_pattern({?MODULE,seq,'_'}, false, [call_time]), ok = check_trace_info({?MODULE, seq, 3}, false, none), {L, _T4} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq, 3}, false, none), ok = check_trace_info({?MODULE, seq_r, 4}, [], none), {Lr, T5} = execute(Pid, fun() -> seq_r(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq_r, 4}, [{Pid,M,0,0}], T5), N = erlang:trace_pattern({?MODULE,'_','_'}, false, [call_time]), ok = check_trace_info({?MODULE, seq_r, 4}, false, none), {Lr, _T6} = execute(Pid, fun() -> seq_r(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq_r, 4}, false, none), L = lists:reverse(Lr), %% Pid ! quit, P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Tests the trace_info BIF info(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), %% 1 = erlang:trace_pattern({?MODULE,seq,3}, true, [call_time]), {call_time,[]} = erlang:trace_info({?MODULE,seq,3}, call_time), 1 = erlang:trace_pattern({?MODULE,seq,'_'}, pause, [call_time]), {call_time,[]} = erlang:trace_info({?MODULE,seq,3}, call_time), {all,[_|_]=L} = erlang:trace_info({?MODULE,seq,3}, all), {value,{call_time,[]}} = lists:keysearch(call_time, 1, L), 1 = erlang:trace_pattern({?MODULE,seq,'_'}, restart, [call_time]), {call_time,[]} = erlang:trace_info({?MODULE,seq,3}, call_time), 1 = erlang:trace_pattern({?MODULE,seq,'_'}, false, [call_time]), {call_time,false} = erlang:trace_info({?MODULE,seq,3}, call_time), {all,false} = erlang:trace_info({?MODULE,seq,3}, all), %% P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Tests pausing and restarting call time counters pause_and_restart(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 100, Pid = setup(), %% 1 = erlang:trace_pattern({?MODULE,seq,'_'}, true, [call_time]), ok = check_trace_info({?MODULE, seq, 3}, [], none), {L, T1} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T1), 1 = erlang:trace_pattern({?MODULE,seq,'_'}, pause, [call_time]), ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T1), {L, T2} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T2), 1 = erlang:trace_pattern({?MODULE,seq,'_'}, restart, [call_time]), ok = check_trace_info({?MODULE, seq, 3}, [], none), {L, T3} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T3), %% Pid ! quit, P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Tests in/out scheduling of call time counters scheduling(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 1000000, Np = erlang:system_info(schedulers_online), F = 12, %% setup load processes %% (single, no internal calls) erlang:trace_pattern({?MODULE,loaded,1}, true, [call_time]), Pids = [setup() || _ <- lists:seq(1, F*Np)], {_Ls,T1} = execute(Pids, {?MODULE,loaded,[M]}), [Pid ! quit || Pid <- Pids], %% logic dictates that each process will get ~ 1/F of the schedulers time {call_time, CT} = erlang:trace_info({?MODULE,loaded,1}, call_time), lists:foreach(fun (Pid) -> ok = case check_process_time(lists:keysearch(Pid, 1, CT), M, F, T1) of schedule_time_error -> test_server:comment("Warning: Failed time ratio"), ok; Other -> Other end end, Pids), P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% "Tests combining local call trace and meta trace with call time trace combo(Config) when is_list(Config) -> Self = self(), Nbc = 3, MetaMs = [{'_',[],[{return_trace}]}], Flags = lists:sort([call, return_to]), LocalTracer = spawn_link(fun () -> relay_n(5 + Nbc + 3, Self) end), MetaTracer = spawn_link(fun () -> relay_n(9 + Nbc + 3, Self) end), 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, [], [local]), 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, true, [call_time]), 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, MetaMs, [{meta,MetaTracer}]), 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, true, [call_count]), % bifs 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, [], [local]), 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_time]), 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, MetaMs, [{meta,MetaTracer}]), %% not implemented %2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_count]), 1 = erlang:trace(Self, true, [{tracer,LocalTracer} | Flags]), %% {traced,local} = erlang:trace_info({?MODULE,seq_r,3}, traced), {match_spec,[]} = erlang:trace_info({?MODULE,seq_r,3}, match_spec), {meta,MetaTracer} = erlang:trace_info({?MODULE,seq_r,3}, meta), {meta_match_spec,MetaMs} = erlang:trace_info({?MODULE,seq_r,3}, meta_match_spec), ok = check_trace_info({?MODULE, seq_r, 3}, [], none), %% check empty trace_info for ?MODULE:seq_r/3 {all,[_|_]=TraceInfo} = erlang:trace_info({?MODULE,seq_r,3}, all), {value,{traced,local}} = lists:keysearch(traced, 1, TraceInfo), {value,{match_spec,[]}} = lists:keysearch(match_spec, 1, TraceInfo), {value,{meta,MetaTracer}} = lists:keysearch(meta, 1, TraceInfo), {value,{meta_match_spec,MetaMs}} = lists:keysearch(meta_match_spec, 1, TraceInfo), {value,{call_count,0}} = lists:keysearch(call_count, 1, TraceInfo), {value,{call_time,[]}} = lists:keysearch(call_time, 1, TraceInfo), %% check empty trace_info for erlang:term_to_binary/1 {all, [_|_] = TraceInfoBif} = erlang:trace_info({erlang, term_to_binary, 1}, all), {value,{traced,local}} = lists:keysearch(traced, 1, TraceInfoBif), {value,{match_spec,[]}} = lists:keysearch(match_spec, 1, TraceInfoBif), {value,{meta, MetaTracer}} = lists:keysearch(meta, 1, TraceInfoBif), {value,{meta_match_spec,MetaMs}} = lists:keysearch(meta_match_spec, 1, TraceInfoBif), %% not implemented {value,{call_count,false}} = lists:keysearch(call_count, 1, TraceInfoBif), %{value,{call_count,0}} = lists:keysearch(call_count, 1, TraceInfoBif), {value,{call_time,[]}} = lists:keysearch(call_time, 1, TraceInfoBif), %% [3,2,1] = seq_r(1, 3, fun(X) -> X+1 end), T0 = erlang:monotonic_time(), with_bif(Nbc), T1 = erlang:monotonic_time(), TimeB = erlang:convert_time_unit(T1-T0, native, microsecond), %% List = collect(100), {MetaR, LocalR} = lists:foldl( fun ({P,X}, {M,L}) when P == MetaTracer -> {[X|M],L}; ({P,X}, {M,L}) when P == LocalTracer -> {M,[X|L]} end, {[],[]}, List), Meta = lists:reverse(MetaR), Local = lists:reverse(LocalR), [?CTT(Self,{?MODULE,seq_r,[1,3,_]}), ?CTT(Self,{?MODULE,seq_r,[1,3,_,[]]}), ?CTT(Self,{?MODULE,seq_r,[2,3,_,[1]]}), ?CTT(Self,{?MODULE,seq_r,[3,3,_,[2,1]]}), ?RFT(Self,{?MODULE,seq_r,4},[3,2,1]), ?RFT(Self,{?MODULE,seq_r,4},[3,2,1]), ?RFT(Self,{?MODULE,seq_r,4},[3,2,1]), ?RFT(Self,{?MODULE,seq_r,3},[3,2,1]), ?CTT(Self,{erlang,term_to_binary,[3]}), % bif ?RFT(Self,{erlang,term_to_binary,1},<<131,97,3>>), ?CTT(Self,{erlang,term_to_binary,[2]}), ?RFT(Self,{erlang,term_to_binary,1},<<131,97,2>>) ] = Meta, [?CT(Self,{?MODULE,seq_r,[1,3,_]}), ?CT(Self,{?MODULE,seq_r,[1,3,_,[]]}), ?CT(Self,{?MODULE,seq_r,[2,3,_,[1]]}), ?CT(Self,{?MODULE,seq_r,[3,3,_,[2,1]]}), ?RT(Self,{?MODULE,combo,1}), ?CT(Self,{erlang,term_to_binary,[3]}), % bif ?RT(Self,{?MODULE,with_bif,1}), ?CT(Self,{erlang,term_to_binary,[2]}), ?RT(Self,{?MODULE,with_bif,1}) ] = Local, ok = check_trace_info({?MODULE, seq_r, 3}, [{Self,1,0,0}], 1), ok = check_trace_info({?MODULE, seq_r, 4}, [{Self,3,0,0}], 1), ok = check_trace_info({?MODULE, seq_r, 3}, [{Self,1,0,0}], 1), ok = check_trace_info({?MODULE, seq_r, 4}, [{Self,3,0,0}], 1), ok = check_trace_info({erlang, term_to_binary, 1}, [{self(), Nbc - 1, 0, 0}], TimeB), %% erlang:trace_pattern({'_','_','_'}, false, [local,meta,call_time]), erlang:trace_pattern(on_load, false, [local,meta,call_time]), erlang:trace(all, false, [all]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Tests tracing of bifs bif(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 5000000, %% 2 = erlang:trace_pattern({erlang, binary_to_term, '_'}, true, [call_time]), 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_time]), Pid = setup(), {L, T1} = execute(Pid, fun() -> with_bif(M) end), ok = check_trace_info({erlang, binary_to_term, 1}, [{Pid, M - 1, 0, 0}], T1/2), ok = check_trace_info({erlang, term_to_binary, 1}, [{Pid, M - 1, 0, 0}], T1/2), % disable term2binary 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, false, [call_time]), {L, T2} = execute(Pid, fun() -> with_bif(M) end), ok = check_trace_info({erlang, binary_to_term, 1}, [{Pid, M*2 - 2, 0, 0}], T1/2 + T2), ok = check_trace_info({erlang, term_to_binary, 1}, false, none), %% P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), Pid ! quit, ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Tests tracing of nifs nif(Config) when is_list(Config) -> load_nif(Config), P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 5000000, %% 1 = erlang:trace_pattern({?MODULE, nif_dec, '_'}, true, [call_time]), 1 = erlang:trace_pattern({?MODULE, with_nif, '_'}, true, [call_time]), Pid = setup(), {_, T1} = execute(Pid, fun() -> with_nif(M) end), % the nif is called M - 1 times, the last time the function with 'with_nif' % returns ok and does not call the nif. ok = check_trace_info({?MODULE, nif_dec, 1}, [{Pid, M-1, 0, 0}], T1/5*4), ok = check_trace_info({?MODULE, with_nif, 1}, [{Pid, M, 0, 0}], T1/5), %% P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), Pid ! quit, ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Tests combining nested function calls and that the time accumulates to the right function called_function(Config) when is_list(Config) -> P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), M = 2100, Pid = setup(), %% 1 = erlang:trace_pattern({?MODULE,a_function,'_'}, true, [call_time]), {L, T1} = execute(Pid, {?MODULE, a_function, [M]}), ok = check_trace_info({?MODULE, a_function, 1}, [{Pid, M, 0, 0}], T1), 1 = erlang:trace_pattern({?MODULE,a_called_function,'_'}, true, [call_time]), {L, T2} = execute(Pid, {?MODULE, a_function, [M]}), ok = check_trace_info({?MODULE, a_function, 1}, [{Pid, M+M, 0, 0}], T1 + M*?SINGLE_CALL_US_TIME), ok = check_trace_info({?MODULE, a_called_function, 1}, [{Pid, M, 0, 0}], T2), 1 = erlang:trace_pattern({?MODULE,dec,'_'}, true, [call_time]), {L, T3} = execute(Pid, {?MODULE, a_function, [M]}), ok = check_trace_info({?MODULE, a_function, 1}, [{Pid, M+M+M, 0, 0}], T1 + (M+M)*?SINGLE_CALL_US_TIME), ok = check_trace_info({?MODULE, a_called_function, 1}, [{Pid, M+M, 0, 0}], T2 + M*?SINGLE_CALL_US_TIME ), ok = check_trace_info({?MODULE, dec, 1}, [{Pid, M, 0, 0}], T3), Pid ! quit, P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% dead_tracer(Config) when is_list(Config) -> Self = self(), FirstTracer = tracer(), StartTracing = fun() -> turn_on_tracing(Self) end, tell_tracer(FirstTracer, StartTracing), [1,2,3,4,5,6,7,8] = seq(1, 8, fun(I) -> I + 1 end), Ref = erlang:monitor(process, FirstTracer), FirstTracer ! quit, receive {'DOWN',Ref,process,FirstTracer,normal} -> ok end, erlang:yield(), %% Collect and check that we only get call_time info for the current process. Info1 = collect_all_info(), [] = other_than_self(Info1), io:format("~p\n", [Info1]), %% Note that we have not turned off tracing for the current process, %% but that the tracer has terminated. No more call_time information should be recorded. [1,2,3] = seq(1, 3, fun(I) -> I + 1 end), [] = collect_all_info(), %% When we start a second tracer process, that tracer process must %% not inherit the tracing flags and the dead tracer (even though %% we used set_on_spawn). SecondTracer = tracer(), tell_tracer(SecondTracer, StartTracing), Seq20 = lists:seq(1, 20), Seq20 = seq(1, 20, fun(I) -> I + 1 end), Info2 = collect_all_info(), io:format("~p\n", [Info2]), [] = other_than_self(Info2), SecondTracer ! quit, ok. other_than_self(Info) -> [{Pid,MFA} || {MFA,[{Pid,_,_,_}]} <- Info, Pid =/= self()]. tell_tracer(Tracer, Fun) -> Tracer ! {execute,self(),Fun}, receive {Tracer,executed} -> ok end. tracer() -> spawn_link(fun Loop() -> receive quit -> ok; {execute,From,Fun} -> Fun(), From ! {self(),executed}, Loop() end end). turn_on_tracing(Pid) -> _ = erlang:trace(Pid, true, [call,set_on_spawn]), _ = erlang:trace_pattern({?MODULE,'_','_'}, true, [call_time]), _ = now(), ok. collect_all_info() -> collect_all_info([{?MODULE,F,A} || {F,A} <- module_info(functions)] ++ erlang:system_info(snifs)). collect_all_info([MFA|T]) -> CallTime = erlang:trace_info(MFA, call_time), erlang:trace_pattern(MFA, restart, [call_time]), case CallTime of {call_time,false} -> collect_all_info(T); {call_time,[]} -> collect_all_info(T); {call_time,[_|_]=List} -> [{MFA,List}|collect_all_info(T)] end; collect_all_info([]) -> []. %%% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %%% The Tests %%% %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Local helpers load_nif(Config) -> Path = proplists:get_value(data_dir, Config), ok = erlang:load_nif(filename:join(Path,"trace_nif"), 0). %% Stack recursive seq seq(Stop, Stop, Succ) when is_function(Succ) -> [Stop]; seq(Start, Stop, Succ) when is_function(Succ) -> [Start | seq(Succ(Start), Stop, Succ)]. a_function(1) -> a_called_function(1); a_function(N) when N > 1 -> a_function(a_called_function(N)). a_called_function(N) -> dec(N). with_bif(1) -> ok; with_bif(N) -> with_bif(erlang:binary_to_term(erlang:term_to_binary(N)) - 1). with_nif(0) -> error; with_nif(1) -> ok; with_nif(N) -> with_nif(?MODULE:nif_dec(N)). nif_dec(_) -> 0. dec(N) -> loaded(10000), N - 1. loaded(N) when N > 1 -> loaded(N - 1); loaded(_) -> 5. %% Tail recursive seq, result list is reversed seq_r(Start, Stop, Succ) when is_function(Succ) -> seq_r(Start, Stop, Succ, []). seq_r(Stop, Stop, _, R) -> [Stop | R]; seq_r(Start, Stop, Succ, R) -> seq_r(Succ(Start), Stop, Succ, [Start | R]). % Check call time tracing data and print mismatches check_trace_info(Mfa, [{Pid, C,_,_}] = Expect, Time) -> case erlang:trace_info(Mfa, call_time) of % Time tests are somewhat problematic. We want to know if Time (EXPECTED_TIME) and S*1000000 + Us (ACTUAL_TIME) % is the same. % If the ratio EXPECTED_TIME/ACTUAL_TIME is ~ 1 or if EXPECTED_TIME - ACTUAL_TIME is near zero, the test is ok. {call_time,[{Pid,C,S,Us}]} when S >= 0, Us >= 0, abs(1 - Time/(S*1000000 + Us)) < ?R_ERROR; abs(Time - S*1000000 - Us) < ?US_ERROR -> ok; {call_time,[{Pid,C,S,Us}]} -> Sum = S*1000000 + Us, io:format("Expected ~p -> {call_time, ~p (Time ~p us)}~n - got ~w s. ~w us. = ~w us. - ~w -> delta ~w (ratio ~.2f, should be 1.0)~n", [Mfa, Expect, Time, S, Us, Sum, Time, Sum - Time, Time/Sum]), time_error; Other -> io:format("Expected ~p -> {call_time, ~p (Time ~p us)}~n - got ~p~n", [ Mfa, Expect, Time, Other]), time_count_error end; check_trace_info(Mfa, Expect, _) -> case erlang:trace_info(Mfa, call_time) of {call_time, Expect} -> ok; Other -> io:format("Expected ~p -> {call_time, ~p}~n - got ~p~n", [Mfa, Expect, Other]), result_not_expected_error end. %check process time check_process_time({value,{Pid, M, S, Us}}, M, F, Time) -> Sum = S*1000000 + Us, if abs(1 - (F/(Time/Sum))) < ?R_ERROR -> ok; true -> io:format("- Pid ~p, Got ratio ~.2f, expected ratio ~w~n", [Pid, Time/Sum,F]), schedule_time_error end; check_process_time(Other, M, _, _) -> io:format(" - Got ~p, expected count ~w~n", [Other, M]), error. %% Message relay process relay_n(0, _) -> ok; relay_n(N, Dest) -> receive Msg -> Dest ! {self(), Msg}, relay_n(N-1, Dest) end. %% Collect received messages collect(Time) -> Ref = erlang:start_timer(Time, self(), done), L = lists:reverse(collect([], Ref)), ?dbgformat("Got: ~p~n",[L]), L. collect(A, 0) -> receive Mess -> collect([Mess | A], 0) after 0 -> A end; collect(A, Ref) -> receive {timeout, Ref, done} -> collect(A, 0); Mess -> collect([Mess | A], Ref) end. setup() -> setup([]). setup(Opts) -> Pid = spawn_link(fun() -> loop() end), 1 = erlang:trace(Pid, true, [call|Opts]), Pid. execute(Pids, Mfa) when is_list(Pids) -> T0 = erlang:monotonic_time(), [P ! {self(), execute, Mfa} || P <- Pids], As = [receive {P, answer, Answer} -> Answer end || P <- Pids], T1 = erlang:monotonic_time(), {As, erlang:convert_time_unit(T1-T0, native, microsecond)}; execute(P, Mfa) -> T0 = erlang:monotonic_time(), P ! {self(), execute, Mfa}, A = receive {P, answer, Answer} -> Answer end, T1 = erlang:monotonic_time(), {A, erlang:convert_time_unit(T1-T0, native, microsecond)}. loop() -> receive quit -> ok; {Pid, execute, Fun } when is_function(Fun) -> Pid ! {self(), answer, erlang:apply(Fun, [])}, loop(); {Pid, execute, {M, F, A}} -> Pid ! {self(), answer, erlang:apply(M, F, A)}, loop() end.