1%% 2%% %CopyrightBegin% 3%% 4%% Copyright Ericsson AB 1998-2017. All Rights Reserved. 5%% 6%% Licensed under the Apache License, Version 2.0 (the "License"); 7%% you may not use this file except in compliance with the License. 8%% You may obtain a copy of the License at 9%% 10%% http://www.apache.org/licenses/LICENSE-2.0 11%% 12%% Unless required by applicable law or agreed to in writing, software 13%% distributed under the License is distributed on an "AS IS" BASIS, 14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 15%% See the License for the specific language governing permissions and 16%% limitations under the License. 17%% 18%% %CopyrightEnd% 19%% 20 21-module(trace_bif_SUITE). 22 23-include_lib("common_test/include/ct.hrl"). 24 25-export([all/0, suite/0]). 26-export([trace_bif/1, trace_bif_timestamp/1, trace_on_and_off/1, 27 trace_bif_local/1, 28 trace_bif_timestamp_local/1, trace_bif_return/1, not_run/1, 29 trace_info_old_code/1]). 30 31-export([bif_process/0]). 32 33suite() -> [{ct_hooks,[ts_install_cth]}]. 34 35all() -> 36 case test_server:is_native(trace_bif_SUITE) of 37 true -> [not_run]; 38 false -> 39 [trace_bif, trace_bif_timestamp, trace_on_and_off, 40 trace_bif_local, trace_bif_timestamp_local, 41 trace_bif_return, trace_info_old_code] 42 end. 43 44 45not_run(Config) when is_list(Config) -> 46 {skipped,"Native code"}. 47 48%% Tests switching tracing on and off. 49trace_on_and_off(Config) when is_list(Config) -> 50 Pid = spawn_link(?MODULE, bif_process, []), 51 Self = self(), 52 1 = erlang:trace(Pid, true, [call,timestamp]), 53 {flags, Flags} = erlang:trace_info(Pid,flags), 54 [call,timestamp] = lists:sort(Flags), 55 {tracer, Self} = erlang:trace_info(Pid,tracer), 56 1 = erlang:trace(Pid, false, [timestamp]), 57 {flags,[call]} = erlang:trace_info(Pid,flags), 58 {tracer, Self} = erlang:trace_info(Pid,tracer), 59 1 = erlang:trace(Pid, false, [call]), 60 {flags,[]} = erlang:trace_info(Pid,flags), 61 {tracer, []} = erlang:trace_info(Pid,tracer), 62 unlink(Pid), 63 exit(Pid,kill), 64 ok. 65 66%% Test tracing BIFs. 67trace_bif(Config) when is_list(Config) -> 68 do_trace_bif([]). 69 70%% Test tracing BIFs with local flag. 71trace_bif_local(Config) when is_list(Config) -> 72 do_trace_bif([local]). 73 74do_trace_bif(Flags) -> 75 Pid = spawn_link(?MODULE, bif_process, []), 76 1 = erlang:trace(Pid, true, [call]), 77 erlang:trace_pattern({erlang,'_','_'}, [], Flags), 78 Pid ! {do_bif, time, []}, 79 receive_trace_msg({trace,Pid,call,{erlang,time, []}}), 80 Pid ! {do_bif, statistics, [runtime]}, 81 receive_trace_msg({trace,Pid,call, 82 {erlang,statistics, [runtime]}}), 83 84 Pid ! {do_time_bif}, 85 receive_trace_msg({trace,Pid,call, 86 {erlang,time, []}}), 87 88 Pid ! {do_statistics_bif}, 89 receive_trace_msg({trace,Pid,call, 90 {erlang,statistics, [runtime]}}), 91 92 1 = erlang:trace(Pid, false, [call]), 93 erlang:trace_pattern({erlang,'_','_'}, false, Flags), 94 unlink(Pid), 95 exit(Pid, die), 96 ok. 97 98%% Test tracing BIFs with timestamps. 99trace_bif_timestamp(Config) when is_list(Config) -> 100 do_trace_bif_timestamp([], timestamp, [timestamp]), 101 do_trace_bif_timestamp([], timestamp, 102 [timestamp, 103 monotonic_timestamp, 104 strict_monotonic_timestamp]), 105 do_trace_bif_timestamp([], strict_monotonic_timestamp, 106 [strict_monotonic_timestamp]), 107 do_trace_bif_timestamp([], strict_monotonic_timestamp, 108 [monotonic_timestamp, strict_monotonic_timestamp]), 109 do_trace_bif_timestamp([], monotonic_timestamp, [monotonic_timestamp]). 110 111%% Test tracing BIFs with timestamps and local flag. 112trace_bif_timestamp_local(Config) when is_list(Config) -> 113 do_trace_bif_timestamp([local], timestamp, [timestamp]), 114 do_trace_bif_timestamp([local], timestamp, 115 [timestamp, 116 monotonic_timestamp, 117 strict_monotonic_timestamp]), 118 do_trace_bif_timestamp([local], strict_monotonic_timestamp, 119 [strict_monotonic_timestamp]), 120 do_trace_bif_timestamp([local], strict_monotonic_timestamp, 121 [monotonic_timestamp, strict_monotonic_timestamp]), 122 do_trace_bif_timestamp([local], monotonic_timestamp, [monotonic_timestamp]). 123 124do_trace_bif_timestamp(Flags, TsType, TsFlags) -> 125 io:format("Testing with TsType=~p TsFlags=~p~n", [TsType, TsFlags]), 126 Pid = spawn_link(?MODULE, bif_process, []), 127 1 = erlang:trace(Pid, true, [call]++TsFlags), 128 erlang:trace_pattern({erlang,'_','_'}, [], Flags), 129 130 Ts0 = make_ts(TsType), 131 Pid ! {do_bif, time, []}, 132 Ts1 = receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}, 133 Ts0,TsType), 134 135 Pid ! {do_bif, statistics, [runtime]}, 136 Ts2 = receive_trace_msg_ts({trace_ts,Pid,call, 137 {erlang,statistics, [runtime]}}, 138 Ts1, TsType), 139 140 Pid ! {do_time_bif}, 141 Ts3 = receive_trace_msg_ts({trace_ts,Pid,call, 142 {erlang,time, []}}, 143 Ts2, TsType), 144 145 Pid ! {do_statistics_bif}, 146 Ts4 = receive_trace_msg_ts({trace_ts,Pid,call, 147 {erlang,statistics, [runtime]}}, 148 Ts3, TsType), 149 150 check_ts(TsType, Ts4, make_ts(TsType)), 151 152 %% We should be able to turn off the timestamp. 153 1 = erlang:trace(Pid, false, TsFlags), 154 155 Pid ! {do_statistics_bif}, 156 receive_trace_msg({trace,Pid,call, 157 {erlang,statistics, [runtime]}}), 158 159 Pid ! {do_bif, statistics, [runtime]}, 160 receive_trace_msg({trace,Pid,call, 161 {erlang,statistics, [runtime]}}), 162 163 1 = erlang:trace(Pid, false, [call]), 164 erlang:trace_pattern({erlang,'_','_'}, false, Flags), 165 166 unlink(Pid), 167 exit(Pid, die), 168 ok. 169 170%% Test tracing BIF's with return/return_to trace. 171trace_bif_return(Config) when is_list(Config) -> 172 do_trace_bif_return(timestamp, [timestamp]), 173 do_trace_bif_return(timestamp, 174 [timestamp, 175 monotonic_timestamp, 176 strict_monotonic_timestamp]), 177 do_trace_bif_return(strict_monotonic_timestamp, 178 [strict_monotonic_timestamp]), 179 do_trace_bif_return(strict_monotonic_timestamp, 180 [monotonic_timestamp, strict_monotonic_timestamp]), 181 do_trace_bif_return(monotonic_timestamp, [monotonic_timestamp]). 182 183do_trace_bif_return(TsType, TsFlags) -> 184 io:format("Testing with TsType=~p TsFlags=~p~n", [TsType, TsFlags]), 185 Pid = spawn_link(?MODULE, bif_process, []), 186 1 = erlang:trace(Pid, true, [call,return_to]++TsFlags), 187 erlang:trace_pattern({erlang,'_','_'}, [{'_',[],[{return_trace}]}], 188 [local]), 189 190 Ts0 = make_ts(TsType), 191 Pid ! {do_bif, time, []}, 192 Ts1 = receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}, 193 Ts0, TsType), 194 Ts2 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, 195 {erlang,time,0}}, 196 Ts1, TsType), 197 Ts3 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 198 {?MODULE, bif_process,0}}, 199 Ts2, TsType), 200 201 202 Pid ! {do_bif, statistics, [runtime]}, 203 Ts4 = receive_trace_msg_ts({trace_ts,Pid,call, 204 {erlang,statistics, [runtime]}}, 205 Ts3, TsType), 206 Ts5 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, 207 {erlang,statistics,1}}, 208 Ts4, TsType), 209 Ts6 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 210 {?MODULE, bif_process,0}}, 211 Ts5, TsType), 212 213 214 Pid ! {do_time_bif}, 215 Ts7 = receive_trace_msg_ts({trace_ts,Pid,call, 216 {erlang,time, []}}, 217 Ts6, TsType), 218 Ts8 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, 219 {erlang,time,0}}, 220 Ts7, TsType), 221 Ts9 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 222 {?MODULE, bif_process,0}}, 223 Ts8, TsType), 224 225 226 227 Pid ! {do_statistics_bif}, 228 Ts10 = receive_trace_msg_ts({trace_ts,Pid,call, 229 {erlang,statistics, [runtime]}}, 230 Ts9, TsType), 231 Ts11 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, 232 {erlang,statistics,1}}, 233 Ts10, TsType), 234 Ts12 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, 235 {?MODULE, bif_process,0}}, 236 Ts11, TsType), 237 check_ts(TsType, Ts12, make_ts(TsType)), 238 erlang:trace_pattern({erlang,'_','_'}, false, [local]), 239 ok. 240 241 242receive_trace_msg(Mess) -> 243 receive 244 Mess -> 245 ok; 246 Other -> 247 ct:fail("Expected: ~p,~nGot: ~p~n", [Mess, Other]) 248 after 5000 -> 249 ct:fail("Expected: ~p,~nGot: timeout~n", [Mess]) 250 end. 251 252receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}, PrevTs, TsType) -> 253 receive 254 {trace_ts, Pid, call, {erlang, F, A}, Ts} = M -> 255 io:format("~p (PrevTs: ~p)~n",[M, PrevTs]), 256 check_ts(TsType, PrevTs, Ts), 257 Ts; 258 Other -> 259 ct:fail("Expected: {trace, ~p, call, {~p, ~p, ~p}, TimeStamp}},~n" 260 "Got: ~p~n", 261 [Pid, erlang, F, A, Other]) 262 after 5000 -> 263 ct:fail("Got timeout~n", []) 264 end. 265 266receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}, PrevTs, TsType) -> 267 receive 268 {trace_ts, Pid, return_from, {erlang, F, A}, _Value, Ts} = M -> 269 io:format("~p (PrevTs: ~p)~n",[M, PrevTs]), 270 check_ts(TsType, PrevTs, Ts), 271 Ts; 272 Other -> 273 ct:fail("Expected: {trace_ts, ~p, return_from, {~p, ~p, ~p}, Value, TimeStamp}},~n" 274 "Got: ~p~n", [Pid, erlang, F, A, Other]) 275 after 5000 -> 276 ct:fail("Got timeout~n", []) 277 end. 278 279receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}, PrevTs, TsType) -> 280 receive 281 {trace_ts, Pid, return_to, {M, F, A}, Ts} = Msg -> 282 io:format("~p (PrevTs: ~p)~n",[Msg, PrevTs]), 283 check_ts(TsType, PrevTs, Ts), 284 Ts; 285 Other -> 286 ct:fail("Expected: {trace_ts, ~p, return_to, {~p, ~p, ~p}, TimeStamp}},~n" 287 "Got: ~p~n", [Pid, M, F, A, Other]) 288 after 5000 -> 289 ct:fail("Got timeout~n", []) 290 end. 291 292make_ts(timestamp) -> 293 erlang:now(); 294make_ts(monotonic_timestamp) -> 295 erlang:monotonic_time(nanosecond); 296make_ts(strict_monotonic_timestamp) -> 297 MT = erlang:monotonic_time(nanosecond), 298 UMI = erlang:unique_integer([monotonic]), 299 {MT, UMI}. 300 301check_ts(timestamp, PrevTs, Ts) -> 302 {Ms, S, Us} = Ts, 303 true = is_integer(Ms), 304 true = is_integer(S), 305 true = is_integer(Us), 306 true = PrevTs < Ts, 307 Ts; 308check_ts(monotonic_timestamp, PrevTs, Ts) -> 309 true = is_integer(Ts), 310 true = PrevTs =< Ts, 311 Ts; 312check_ts(strict_monotonic_timestamp, PrevTs, Ts) -> 313 {MT, UMI} = Ts, 314 true = is_integer(MT), 315 true = is_integer(UMI), 316 true = PrevTs < Ts, 317 Ts. 318 319bif_process() -> 320 receive 321 {do_bif, Name, Args} -> 322 apply(erlang, Name, Args), 323 bif_process(); 324 {do_time_bif} -> 325 %% Match the return value to ensure that the time() call 326 %% is not optimized away. 327 {_,_,_} = time(), 328 bif_process(); 329 {do_statistics_bif} -> 330 statistics(runtime), 331 bif_process(); 332 _Stuff -> 333 bif_process() 334 end. 335 336 337 338%% trace_info on deleted module (OTP-5057). 339trace_info_old_code(Config) when is_list(Config) -> 340 MFA = {M,F,0} = {test,foo,0}, 341 Fname = atom_to_list(M)++".erl", 342 AbsForms = 343 [{attribute,a(1),module,M}, % -module(M). 344 {attribute,a(2),export,[{F,0}]}, % -export([F/0]). 345 {function,a(3),F,0, % F() -> 346 [{clause,a(4),[],[],[{atom,a(4),F}]}]}], % F. 347 %% 348 {ok,M,Mbin} = compile:forms(AbsForms), 349 {module,M} = code:load_binary(M, Fname, Mbin), 350 true = erlang:delete_module(M), 351 {traced,undefined} = erlang:trace_info(MFA, traced), 352 ok. 353 354a(L) -> 355 erl_anno:new(L). 356