path: root/erts/emulator/test/trace_bif_SUITE.erl

%%
%% %CopyrightBegin%
%% 
%% Copyright Ericsson AB 1998-2017. 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_link(?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),
    unlink(Pid),
    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_link(?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),
    unlink(Pid),
    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_link(?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),

    unlink(Pid),
    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_link(?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)),
    erlang:trace_pattern({erlang,'_','_'}, false, [local]),
    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(nanosecond);
make_ts(strict_monotonic_timestamp) ->
    MT = erlang:monotonic_time(nanosecond),
    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).