%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 1998-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%
%%
-module(trace_bif_SUITE).
-include_lib("common_test/include/ct.hrl").
-export([all/0, suite/0]).
-export([trace_bif/1, trace_bif_timestamp/1, trace_on_and_off/1,
trace_bif_local/1,
trace_bif_timestamp_local/1, trace_bif_return/1, not_run/1,
trace_info_old_code/1]).
-export([bif_process/0]).
suite() -> [{ct_hooks,[ts_install_cth]}].
all() ->
case test_server:is_native(trace_bif_SUITE) of
true -> [not_run];
false ->
[trace_bif, trace_bif_timestamp, trace_on_and_off,
trace_bif_local, trace_bif_timestamp_local,
trace_bif_return, trace_info_old_code]
end.
not_run(Config) when is_list(Config) ->
{skipped,"Native code"}.
%% Tests switching tracing on and off.
trace_on_and_off(Config) when is_list(Config) ->
Pid = spawn(?MODULE, bif_process, []),
Self = self(),
1 = erlang:trace(Pid, true, [call,timestamp]),
{flags, Flags} = erlang:trace_info(Pid,flags),
[call,timestamp] = lists:sort(Flags),
{tracer, Self} = erlang:trace_info(Pid,tracer),
1 = erlang:trace(Pid, false, [timestamp]),
{flags,[call]} = erlang:trace_info(Pid,flags),
{tracer, Self} = erlang:trace_info(Pid,tracer),
1 = erlang:trace(Pid, false, [call]),
{flags,[]} = erlang:trace_info(Pid,flags),
{tracer, []} = erlang:trace_info(Pid,tracer),
exit(Pid,kill),
ok.
%% Test tracing BIFs.
trace_bif(Config) when is_list(Config) ->
do_trace_bif([]).
%% Test tracing BIFs with local flag.
trace_bif_local(Config) when is_list(Config) ->
do_trace_bif([local]).
do_trace_bif(Flags) ->
Pid = spawn(?MODULE, bif_process, []),
1 = erlang:trace(Pid, true, [call]),
erlang:trace_pattern({erlang,'_','_'}, [], Flags),
Pid ! {do_bif, time, []},
receive_trace_msg({trace,Pid,call,{erlang,time, []}}),
Pid ! {do_bif, statistics, [runtime]},
receive_trace_msg({trace,Pid,call,
{erlang,statistics, [runtime]}}),
Pid ! {do_time_bif},
receive_trace_msg({trace,Pid,call,
{erlang,time, []}}),
Pid ! {do_statistics_bif},
receive_trace_msg({trace,Pid,call,
{erlang,statistics, [runtime]}}),
1 = erlang:trace(Pid, false, [call]),
erlang:trace_pattern({erlang,'_','_'}, false, Flags),
exit(Pid, die),
ok.
%% Test tracing BIFs with timestamps.
trace_bif_timestamp(Config) when is_list(Config) ->
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]).
%% Test tracing BIFs with timestamps and local flag.
trace_bif_timestamp_local(Config) when is_list(Config) ->
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.
1 = erlang:trace(Pid, false, TsFlags),
Pid ! {do_statistics_bif},
receive_trace_msg({trace,Pid,call,
{erlang,statistics, [runtime]}}),
Pid ! {do_bif, statistics, [runtime]},
receive_trace_msg({trace,Pid,call,
{erlang,statistics, [runtime]}}),
1 = erlang:trace(Pid, false, [call]),
erlang:trace_pattern({erlang,'_','_'}, false, Flags),
exit(Pid, die),
ok.
%% Test tracing BIF's with return/return_to trace.
trace_bif_return(Config) when is_list(Config) ->
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.
receive_trace_msg(Mess) ->
receive
Mess ->
ok;
Other ->
ct:fail("Expected: ~p,~nGot: ~p~n", [Mess, Other])
after 5000 ->
ct:fail("Expected: ~p,~nGot: timeout~n", [Mess])
end.
receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}, PrevTs, TsType) ->
receive
{trace_ts, Pid, call, {erlang, F, A}, Ts} = M ->
io:format("~p (PrevTs: ~p)~n",[M, PrevTs]),
check_ts(TsType, PrevTs, Ts),
Ts;
Other ->
ct:fail("Expected: {trace, ~p, call, {~p, ~p, ~p}, TimeStamp}},~n"
"Got: ~p~n",
[Pid, erlang, F, A, Other])
after 5000 ->
ct:fail("Got timeout~n", [])
end.
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} = M ->
io:format("~p (PrevTs: ~p)~n",[M, PrevTs]),
check_ts(TsType, PrevTs, Ts),
Ts;
Other ->
ct:fail("Expected: {trace_ts, ~p, return_from, {~p, ~p, ~p}, Value, TimeStamp}},~n"
"Got: ~p~n", [Pid, erlang, F, A, Other])
after 5000 ->
ct:fail("Got timeout~n", [])
end.
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} = Msg ->
io:format("~p (PrevTs: ~p)~n",[Msg, PrevTs]),
check_ts(TsType, PrevTs, Ts),
Ts;
Other ->
ct:fail("Expected: {trace_ts, ~p, return_to, {~p, ~p, ~p}, TimeStamp}},~n"
"Got: ~p~n", [Pid, M, F, A, Other])
after 5000 ->
ct:fail("Got timeout~n", [])
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} ->
apply(erlang, Name, Args),
bif_process();
{do_time_bif} ->
%% Match the return value to ensure that the time() call
%% is not optimized away.
{_,_,_} = time(),
bif_process();
{do_statistics_bif} ->
statistics(runtime),
bif_process();
_Stuff ->
bif_process()
end.
%% trace_info on deleted module (OTP-5057).
trace_info_old_code(Config) when is_list(Config) ->
MFA = {M,F,0} = {test,foo,0},
Fname = atom_to_list(M)++".erl",
AbsForms =
[{attribute,a(1),module,M}, % -module(M).
{attribute,a(2),export,[{F,0}]}, % -export([F/0]).
{function,a(3),F,0, % F() ->
[{clause,a(4),[],[],[{atom,a(4),F}]}]}], % F.
%%
{ok,M,Mbin} = compile:forms(AbsForms),
{module,M} = code:load_binary(M, Fname, Mbin),
true = erlang:delete_module(M),
{traced,undefined} = erlang:trace_info(MFA, traced),
ok.
a(L) ->
erl_anno:new(L).
