diff options
Diffstat (limited to 'erts/emulator/test/trace_call_time_SUITE.erl')
| -rw-r--r-- | erts/emulator/test/trace_call_time_SUITE.erl | 580 |
1 files changed, 290 insertions, 290 deletions
diff --git a/erts/emulator/test/trace_call_time_SUITE.erl b/erts/emulator/test/trace_call_time_SUITE.erl index 09eda2845c..38972c9c02 100644 --- a/erts/emulator/test/trace_call_time_SUITE.erl +++ b/erts/emulator/test/trace_call_time_SUITE.erl @@ -96,25 +96,25 @@ not_run(Config) when is_list(Config) -> %% 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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% @@ -122,257 +122,257 @@ basic(Config) when is_list(Config) -> %% "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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% 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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% 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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% 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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% "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 = erlang:monotonic_time(), - ?line with_bif(Nbc), - ?line T1 = erlang:monotonic_time(), - ?line TimeB = erlang:convert_time_unit(T1-T0, native, micro_seconds), + [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, micro_seconds), %% - ?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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% 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 = 1000000, %% - ?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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% @@ -380,50 +380,50 @@ bif(Config) when is_list(Config) -> %% 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 = 1000000, %% - ?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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% 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. %% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% @@ -437,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(), @@ -468,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]), @@ -497,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([]) -> []. @@ -521,8 +521,8 @@ collect_all_info([]) -> []. %% Local helpers load_nif(Config) -> - ?line Path = proplists:get_value(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 @@ -569,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]), @@ -614,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. @@ -629,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() -> @@ -667,12 +667,12 @@ execute(P, Mfa) -> 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. |