diff options
Diffstat (limited to 'erts/emulator/test/trace_call_time_SUITE.erl')
| -rw-r--r-- | erts/emulator/test/trace_call_time_SUITE.erl | 690 |
1 files changed, 323 insertions, 367 deletions
diff --git a/erts/emulator/test/trace_call_time_SUITE.erl b/erts/emulator/test/trace_call_time_SUITE.erl index 3036d2957b..26f96a1766 100644 --- a/erts/emulator/test/trace_call_time_SUITE.erl +++ b/erts/emulator/test/trace_call_time_SUITE.erl @@ -1,18 +1,19 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2011. All Rights Reserved. +%% Copyright Ericsson AB 2011-2016. All Rights Reserved. %% -%% The contents of this file are subject to the Erlang Public License, -%% Version 1.1, (the "License"); you may not use this file except in -%% compliance with the License. You should have received a copy of the -%% Erlang Public License along with this software. If not, it can be -%% retrieved online at http://www.erlang.org/. +%% 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 %% -%% Software distributed under the License is distributed on an "AS IS" -%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See -%% the License for the specific language governing rights and limitations -%% under the License. +%% 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% %% @@ -57,32 +58,30 @@ %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% --include_lib("test_server/include/test_server.hrl"). +-include_lib("common_test/include/ct.hrl"). %% When run in test server. --export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1, - init_per_group/2,end_per_group/2, +-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) -> - ?line Dog=test_server:timetrap(test_server:seconds(400)), 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()), - [{watchdog, Dog}|Config]. + Config. -end_per_testcase(_Case, 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]), - Dog=?config(watchdog, Config), - test_server:timetrap_cancel(Dog), ok. -suite() -> [{ct_hooks,[ts_install_cth]}]. +suite() -> + [{ct_hooks,[ts_install_cth]}, + {timetrap, {minutes, 10}}]. all() -> case test_server:is_native(trace_call_time_SUITE) of @@ -92,382 +91,339 @@ all() -> combo, bif, nif, called_function, dead_tracer] end. -groups() -> - []. - -init_per_suite(Config) -> - Config. - -end_per_suite(_Config) -> - ok. - -init_per_group(_GroupName, Config) -> - Config. - -end_per_group(_GroupName, Config) -> - Config. - - not_run(Config) when is_list(Config) -> {skipped,"Native code"}. -basic(suite) -> - []; -basic(doc) -> - ["Tests basic call count trace"]; +%% Tests basic call time trace basic(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 1000, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 1000, %% - ?line 1 = erlang:trace_pattern({?MODULE,seq, '_'}, true, [call_time]), - ?line 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, true, [call_time]), - ?line Pid = setup(), - ?line {L, T1} = execute(Pid, fun() -> seq(1, M, fun(X) -> (X+1) end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T1), - ?line ok = check_trace_info({?MODULE, seq_r, 3}, [], none), - - ?line {Lr, T2} = execute(Pid, fun() -> seq_r(1, M, fun(X) -> (X+1) end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T1), - ?line ok = check_trace_info({?MODULE, seq_r, 3}, [{Pid, 1, 0, 0}], T2/M), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, [{Pid, M, 0, 0}], T2), - ?line L = lists:reverse(Lr), + 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), %% - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line Pid ! quit, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + Pid ! quit, ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -on_and_off(suite) -> - []; -on_and_off(doc) -> - ["Tests turning trace parameters on and off"]; +%% "Tests turning trace parameters on and off on_and_off(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 100, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 100, %% - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, true, [call_time]), - ?line Pid = setup(), - ?line {L, T1} = execute(Pid, {?MODULE, seq, [1, M, fun(X) -> X+1 end]}), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T1), - - ?line N = erlang:trace_pattern({?MODULE,'_','_'}, true, [call_time]), - ?line {L, T2} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T2), - - ?line P = erlang:trace_pattern({'_','_','_'}, true, [call_time]), - ?line {L, T3} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid, M, 0, 0}], T3), - - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, false, [call_time]), - ?line ok = check_trace_info({?MODULE, seq, 3}, false, none), - ?line {L, _T4} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, false, none), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, [], none), - ?line {Lr, T5} = execute(Pid, fun() -> seq_r(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, [{Pid,M,0,0}], T5), - - ?line N = erlang:trace_pattern({?MODULE,'_','_'}, false, [call_time]), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, false, none), - ?line {Lr, _T6} = execute(Pid, fun() -> seq_r(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, false, none), - ?line L = lists:reverse(Lr), + 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), %% - ?line Pid ! quit, - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + Pid ! quit, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -info(suite) -> - []; -info(doc) -> - ["Tests the trace_info BIF"]; +%% Tests the trace_info BIF info(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), %% - ?line 1 = erlang:trace_pattern({?MODULE,seq,3}, true, [call_time]), - ?line {call_time,[]} = erlang:trace_info({?MODULE,seq,3}, call_time), - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, pause, [call_time]), - ?line {call_time,[]} = erlang:trace_info({?MODULE,seq,3}, call_time), - ?line {all,[_|_]=L} = erlang:trace_info({?MODULE,seq,3}, all), - ?line {value,{call_time,[]}} = lists:keysearch(call_time, 1, L), - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, restart, [call_time]), - ?line {call_time,[]} = erlang:trace_info({?MODULE,seq,3}, call_time), - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, false, [call_time]), - ?line {call_time,false} = erlang:trace_info({?MODULE,seq,3}, call_time), - ?line {all,false} = erlang:trace_info({?MODULE,seq,3}, all), + 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), %% - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -pause_and_restart(suite) -> - []; -pause_and_restart(doc) -> - ["Tests pausing and restarting call time counters"]; +%% Tests pausing and restarting call time counters pause_and_restart(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 100, - ?line Pid = setup(), + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 100, + Pid = setup(), %% - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, true, [call_time]), - ?line ok = check_trace_info({?MODULE, seq, 3}, [], none), - ?line {L, T1} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T1), - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, pause, [call_time]), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T1), - ?line {L, T2} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T2), - ?line 1 = erlang:trace_pattern({?MODULE,seq,'_'}, restart, [call_time]), - ?line ok = check_trace_info({?MODULE, seq, 3}, [], none), - ?line {L, T3} = execute(Pid, fun() -> seq(1, M, fun(X) -> X+1 end) end), - ?line ok = check_trace_info({?MODULE, seq, 3}, [{Pid,M,0,0}], T3), + 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), %% - ?line Pid ! quit, - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + Pid ! quit, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -scheduling(suite) -> - []; -scheduling(doc) -> - ["Tests in/out scheduling of call time counters"]; +%% Tests in/out scheduling of call time counters scheduling(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 1000000, - ?line Np = erlang:system_info(schedulers_online), - ?line F = 12, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 1000000, + Np = erlang:system_info(schedulers_online), + F = 12, %% setup load processes %% (single, no internal calls) - ?line erlang:trace_pattern({?MODULE,loaded,1}, true, [call_time]), + erlang:trace_pattern({?MODULE,loaded,1}, true, [call_time]), - ?line Pids = [setup() || _ <- lists:seq(1, F*Np)], - ?line {_Ls,T1} = execute(Pids, {?MODULE,loaded,[M]}), - ?line [Pid ! quit || Pid <- Pids], + 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 - ?line {call_time, CT} = erlang:trace_info({?MODULE,loaded,1}, call_time), - - ?line lists:foreach(fun (Pid) -> - ?line 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), - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -combo(suite) -> - []; -combo(doc) -> - ["Tests combining local call trace and meta trace with call time trace"]; +%% "Tests combining local call trace and meta trace with call time trace combo(Config) when is_list(Config) -> - ?line Self = self(), - ?line Nbc = 3, - ?line MetaMs = [{'_',[],[{return_trace}]}], - ?line Flags = lists:sort([call, return_to]), - ?line LocalTracer = spawn_link(fun () -> relay_n(5 + Nbc + 3, Self) end), - ?line MetaTracer = spawn_link(fun () -> relay_n(9 + Nbc + 3, Self) end), - ?line 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, [], [local]), - ?line 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, true, [call_time]), - ?line 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, MetaMs, [{meta,MetaTracer}]), - ?line 2 = erlang:trace_pattern({?MODULE,seq_r,'_'}, true, [call_count]), + 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 - ?line 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, [], [local]), - ?line 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_time]), - ?line 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, MetaMs, [{meta,MetaTracer}]), + 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 - %?line 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_count]), + %2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_count]), - ?line 1 = erlang:trace(Self, true, [{tracer,LocalTracer} | Flags]), + 1 = erlang:trace(Self, true, [{tracer,LocalTracer} | Flags]), %% - ?line {traced,local} = - erlang:trace_info({?MODULE,seq_r,3}, traced), - ?line {match_spec,[]} = - erlang:trace_info({?MODULE,seq_r,3}, match_spec), - ?line {meta,MetaTracer} = - erlang:trace_info({?MODULE,seq_r,3}, meta), - ?line {meta_match_spec,MetaMs} = - erlang:trace_info({?MODULE,seq_r,3}, meta_match_spec), - ?line ok = check_trace_info({?MODULE, seq_r, 3}, [], none), + {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 - ?line {all,[_|_]=TraceInfo} = erlang:trace_info({?MODULE,seq_r,3}, all), - ?line {value,{traced,local}} = lists:keysearch(traced, 1, TraceInfo), - ?line {value,{match_spec,[]}} = lists:keysearch(match_spec, 1, TraceInfo), - ?line {value,{meta,MetaTracer}} = lists:keysearch(meta, 1, TraceInfo), - ?line {value,{meta_match_spec,MetaMs}} = lists:keysearch(meta_match_spec, 1, TraceInfo), - ?line {value,{call_count,0}} = lists:keysearch(call_count, 1, TraceInfo), - ?line {value,{call_time,[]}} = lists:keysearch(call_time, 1, TraceInfo), + {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 - ?line {all, [_|_] = TraceInfoBif} = erlang:trace_info({erlang, term_to_binary, 1}, all), - ?line {value,{traced,local}} = lists:keysearch(traced, 1, TraceInfoBif), - ?line {value,{match_spec,[]}} = lists:keysearch(match_spec, 1, TraceInfoBif), - ?line {value,{meta, MetaTracer}} = lists:keysearch(meta, 1, TraceInfoBif), - ?line {value,{meta_match_spec,MetaMs}} = lists:keysearch(meta_match_spec, 1, TraceInfoBif), + {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 - ?line {value,{call_count,false}} = lists:keysearch(call_count, 1, TraceInfoBif), - %?line {value,{call_count,0}} = lists:keysearch(call_count, 1, TraceInfoBif), - ?line {value,{call_time,[]}} = lists:keysearch(call_time, 1, TraceInfoBif), + {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), %% - ?line [3,2,1] = seq_r(1, 3, fun(X) -> X+1 end), - ?line T0 = now(), - ?line with_bif(Nbc), - ?line T1 = now(), - ?line TimeB = timer:now_diff(T1,T0), + [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), %% - ?line List = collect(100), - ?line {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), - ?line Meta = lists:reverse(MetaR), - ?line Local = lists:reverse(LocalR), - - ?line [?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, - - ?line [?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, - - ?line ok = check_trace_info({?MODULE, seq_r, 3}, [{Self,1,0,0}], 1), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, [{Self,3,0,0}], 1), - ?line ok = check_trace_info({?MODULE, seq_r, 3}, [{Self,1,0,0}], 1), - ?line ok = check_trace_info({?MODULE, seq_r, 4}, [{Self,3,0,0}], 1), - ?line ok = check_trace_info({erlang, term_to_binary, 1}, [{self(), Nbc - 1, 0, 0}], TimeB), + 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), %% - ?line erlang:trace_pattern({'_','_','_'}, false, [local,meta,call_time]), - ?line erlang:trace_pattern(on_load, false, [local,meta,call_time]), - ?line erlang:trace(all, false, [all]), + erlang:trace_pattern({'_','_','_'}, false, [local,meta,call_time]), + erlang:trace_pattern(on_load, false, [local,meta,call_time]), + erlang:trace(all, false, [all]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -bif(suite) -> - []; -bif(doc) -> - ["Tests tracing of bifs"]; +%% Tests tracing of bifs bif(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 1000000, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 5000000, %% - ?line 2 = erlang:trace_pattern({erlang, binary_to_term, '_'}, true, [call_time]), - ?line 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, true, [call_time]), - ?line Pid = setup(), - ?line {L, T1} = execute(Pid, fun() -> with_bif(M) end), + 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), - ?line ok = check_trace_info({erlang, binary_to_term, 1}, [{Pid, M - 1, 0, 0}], T1/2), - ?line ok = check_trace_info({erlang, term_to_binary, 1}, [{Pid, M - 1, 0, 0}], T1/2), + 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 - ?line 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, false, [call_time]), + 2 = erlang:trace_pattern({erlang, term_to_binary, '_'}, false, [call_time]), - ?line {L, T2} = execute(Pid, fun() -> with_bif(M) end), + {L, T2} = execute(Pid, fun() -> with_bif(M) end), - ?line ok = check_trace_info({erlang, binary_to_term, 1}, [{Pid, M*2 - 2, 0, 0}], T1/2 + T2), - ?line ok = check_trace_info({erlang, term_to_binary, 1}, false, none), + 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), %% - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line Pid ! quit, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + Pid ! quit, ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -nif(suite) -> - []; -nif(doc) -> - ["Tests tracing of nifs"]; +%% Tests tracing of nifs nif(Config) when is_list(Config) -> load_nif(Config), - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 1000000, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 5000000, %% - ?line 1 = erlang:trace_pattern({?MODULE, nif_dec, '_'}, true, [call_time]), - ?line 1 = erlang:trace_pattern({?MODULE, with_nif, '_'}, true, [call_time]), - ?line Pid = setup(), - ?line {_, T1} = execute(Pid, fun() -> with_nif(M) end), + 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. - ?line ok = check_trace_info({?MODULE, nif_dec, 1}, [{Pid, M-1, 0, 0}], T1/5*4), - ?line ok = check_trace_info({?MODULE, with_nif, 1}, [{Pid, M, 0, 0}], T1/5), + 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), %% - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line Pid ! quit, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + Pid ! quit, ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -called_function(suite) -> - []; -called_function(doc) -> - ["Tests combining nested function calls and that the time accumulates to the right function"]; +%% Tests combining nested function calls and that the time accumulates to the right function called_function(Config) when is_list(Config) -> - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), - ?line M = 2100, - ?line Pid = setup(), + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + M = 2100, + Pid = setup(), %% - ?line 1 = erlang:trace_pattern({?MODULE,a_function,'_'}, true, [call_time]), - ?line {L, T1} = execute(Pid, {?MODULE, a_function, [M]}), - ?line ok = check_trace_info({?MODULE, a_function, 1}, [{Pid, M, 0, 0}], T1), + 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), - ?line 1 = erlang:trace_pattern({?MODULE,a_called_function,'_'}, true, [call_time]), - ?line {L, T2} = execute(Pid, {?MODULE, a_function, [M]}), - ?line ok = check_trace_info({?MODULE, a_function, 1}, [{Pid, M+M, 0, 0}], T1 + M*?SINGLE_CALL_US_TIME), - ?line ok = check_trace_info({?MODULE, a_called_function, 1}, [{Pid, M, 0, 0}], T2), + 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), - ?line 1 = erlang:trace_pattern({?MODULE,dec,'_'}, true, [call_time]), - ?line {L, T3} = execute(Pid, {?MODULE, a_function, [M]}), - ?line ok = check_trace_info({?MODULE, a_function, 1}, [{Pid, M+M+M, 0, 0}], T1 + (M+M)*?SINGLE_CALL_US_TIME), - ?line ok = check_trace_info({?MODULE, a_called_function, 1}, [{Pid, M+M, 0, 0}], T2 + M*?SINGLE_CALL_US_TIME ), - ?line ok = check_trace_info({?MODULE, dec, 1}, [{Pid, M, 0, 0}], T3), + 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), - ?line Pid ! quit, - ?line P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), + Pid ! quit, + P = erlang:trace_pattern({'_','_','_'}, false, [call_time]), ok. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% @@ -481,8 +437,8 @@ dead_tracer(Config) when is_list(Config) -> Ref = erlang:monitor(process, FirstTracer), FirstTracer ! quit, receive - {'DOWN',Ref,process,FirstTracer,normal} -> - ok + {'DOWN',Ref,process,FirstTracer,normal} -> + ok end, erlang:yield(), @@ -512,26 +468,26 @@ dead_tracer(Config) when is_list(Config) -> other_than_self(Info) -> [{Pid,MFA} || {MFA,[{Pid,_,_,_}]} <- Info, - Pid =/= self()]. + Pid =/= self()]. tell_tracer(Tracer, Fun) -> Tracer ! {execute,self(),Fun}, receive - {Tracer,executed} -> - ok + {Tracer,executed} -> + ok end. tracer() -> spawn_link(fun Loop() -> - receive - quit -> - ok; - {execute,From,Fun} -> - Fun(), - From ! {self(),executed}, - Loop() - end - end). + 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]), @@ -541,18 +497,18 @@ turn_on_tracing(Pid) -> collect_all_info() -> collect_all_info([{?MODULE,F,A} || {F,A} <- module_info(functions)] ++ - erlang:system_info(snifs)). + 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)] + {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([]) -> []. @@ -565,8 +521,8 @@ collect_all_info([]) -> []. %% Local helpers load_nif(Config) -> - ?line Path = ?config(data_dir, Config), - ?line ok = erlang:load_nif(filename:join(Path,"trace_nif"), 0). + Path = proplists:get_value(data_dir, Config), + ok = erlang:load_nif(filename:join(Path,"trace_nif"), 0). %% Stack recursive seq @@ -613,39 +569,39 @@ seq_r(Start, Stop, Succ, 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 + % 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 + {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) -> - ?line Sum = S*1000000 + Us, + 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 + 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]), @@ -658,8 +614,8 @@ relay_n(0, _) -> ok; relay_n(N, Dest) -> receive Msg -> - Dest ! {self(), Msg}, - relay_n(N-1, Dest) + Dest ! {self(), Msg}, + relay_n(N-1, Dest) end. @@ -673,17 +629,17 @@ collect(Time) -> collect(A, 0) -> receive - Mess -> - collect([Mess | A], 0) + Mess -> + collect([Mess | A], 0) after 0 -> - A + A end; collect(A, Ref) -> receive - {timeout, Ref, done} -> - collect(A, 0); - Mess -> - collect([Mess | A], Ref) + {timeout, Ref, done} -> + collect(A, 0); + Mess -> + collect([Mess | A], Ref) end. setup() -> @@ -695,28 +651,28 @@ setup(Opts) -> Pid. execute(Pids, Mfa) when is_list(Pids) -> - T0 = now(), + T0 = erlang:monotonic_time(), [P ! {self(), execute, Mfa} || P <- Pids], As = [receive {P, answer, Answer} -> Answer end || P <- Pids], - T1 = now(), - {As, timer:now_diff(T1,T0)}; + T1 = erlang:monotonic_time(), + {As, erlang:convert_time_unit(T1-T0, native, microsecond)}; execute(P, Mfa) -> - T0 = now(), + T0 = erlang:monotonic_time(), P ! {self(), execute, Mfa}, A = receive {P, answer, Answer} -> Answer end, - T1 = now(), - {A, timer:now_diff(T1,T0)}. + 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() + 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. |