1%% 2%% %CopyrightBegin% 3%% 4%% Copyright Ericsson AB 1999-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 22-module(trace_port_SUITE). 23 24-export([all/0, suite/0, 25 call_trace/1, 26 return_trace/1, 27 send/1, 28 receive_trace/1, 29 receive_trace_non_scheduler/1, 30 process_events/1, 31 schedule/1, 32 gc/1, 33 default_tracer/1, 34 tracer_port_crash/1]). 35 36-include_lib("common_test/include/ct.hrl"). 37 38suite() -> 39 [{ct_hooks,[ts_install_cth]}, 40 {timetrap, {minutes, 2}}]. 41 42all() -> 43 [call_trace, return_trace, send, receive_trace, 44 receive_trace_non_scheduler, 45 process_events, schedule, gc, 46 default_tracer, tracer_port_crash]. 47 48%% Test sending call trace messages to a port. 49call_trace(Config) when is_list(Config) -> 50 case test_server:is_native(?MODULE) orelse 51 test_server:is_native(lists) of 52 true -> 53 {skip,"Native code"}; 54 false -> 55 start_tracer(Config), 56 Self = self(), 57 trace_func({lists,reverse,1}, []), 58 trace_pid(Self, true, [call]), 59 trace_info(Self, flags), 60 trace_info(Self, tracer), 61 [b,a] = lists:reverse([a,b]), 62 expect({trace,Self,call,{lists,reverse,[[a,b]]}}), 63 64 trace_pid(Self, true, [timestamp]), 65 trace_info(Self, flags), 66 Huge = huge_data(), 67 lists:reverse(Huge), 68 expect({trace_ts,Self,call,{lists,reverse,[Huge]},ts}), 69 70 trace_pid(Self, true, [arity]), 71 trace_info(Self, flags), 72 [y,x] = lists:reverse([x,y]), 73 expect({trace_ts,Self,call,{lists,reverse,1},ts}), 74 75 trace_pid(Self, false, [timestamp]), 76 trace_info(Self, flags), 77 [z,y,x] = lists:reverse([x,y,z]), 78 expect({trace,Self,call,{lists,reverse,1}}), 79 80 %% OTP-7399. Delayed sub-binary creation optimization. 81 trace_pid(Self, false, [arity]), 82 trace_info(Self, flags), 83 trace_func({?MODULE,bs_sum_c,2}, [], [local]), 84 26 = bs_sum_c(<<3:4,5:4,7:4,11:4>>, 0), 85 trace_func({?MODULE,bs_sum_c,2}, false, [local]), 86 expect({trace,Self,call,{?MODULE,bs_sum_c,[<<3:4,5:4,7:4,11:4>>,0]}}), 87 expect({trace,Self,call,{?MODULE,bs_sum_c,[<<5:4,7:4,11:4>>,3]}}), 88 expect({trace,Self,call,{?MODULE,bs_sum_c,[<<7:4,11:4>>,8]}}), 89 expect({trace,Self,call,{?MODULE,bs_sum_c,[<<11:4>>,15]}}), 90 expect({trace,Self,call,{?MODULE,bs_sum_c,[<<>>,26]}}), 91 92 trace_func({lists,reverse,1}, false), 93 ok 94 end. 95 96bs_sum_c(<<H:4,T/bits>>, Acc) -> bs_sum_c(T, H+Acc); 97bs_sum_c(<<>>, Acc) -> Acc. 98 99 100%% Test the new return trace. 101return_trace(Config) when is_list(Config) -> 102 case test_server:is_native(?MODULE) orelse 103 test_server:is_native(lists) of 104 true -> 105 {skip,"Native code"}; 106 false -> 107 start_tracer(Config), 108 Self = self(), 109 MFA = {lists,reverse,1}, 110 111 %% Plain (no timestamp, small data). 112 113 trace_func(MFA, [{['$1'],[],[{return_trace}, 114 {message,false}]}]), 115 trace_pid(Self, true, [call]), 116 trace_info(Self, flags), 117 trace_info(Self, tracer), 118 trace_info(MFA, match_spec), 119 {traced,global} = trace_info(MFA, traced), 120 [b,a] = lists:reverse([a,b]), 121 expect({trace,Self,return_from,MFA,[b,a]}), 122 123 %% Timestamp, huge data. 124 trace_pid(Self, true, [timestamp]), 125 Result = lists:reverse(huge_data()), 126 expect({trace_ts,Self,return_from,MFA,Result,ts}), 127 128 %% Turn off trace. 129 trace_func(MFA, false), 130 trace_info(MFA, match_spec), 131 {traced,false} = trace_info(MFA, traced), 132 ok 133 end. 134 135%% Test sending send trace messages to a port. 136send(Config) when is_list(Config) -> 137 Tracer = start_tracer(Config), 138 Self = self(), 139 Sender = fun_spawn(fun sender/0), 140 trac(Sender, true, [send]), 141 142 %% Simple message, no timestamp. 143 144 Bin = list_to_binary(lists:seq(1, 10)), 145 Msg = {some_data,Bin}, 146 Sender ! {send_please,self(),Msg}, 147 receive Msg -> ok end, 148 expect({trace,Sender,send,Msg,Self}), 149 150 %% Timestamp. 151 152 BiggerMsg = {even_bigger,Msg}, 153 trac(Sender, true, [send,timestamp]), 154 Sender ! {send_please,self(),BiggerMsg}, 155 receive BiggerMsg -> ok end, 156 expect({trace_ts,Sender,send,BiggerMsg,Self,ts}), 157 158 %% Huge message. 159 160 HugeMsg = huge_data(), 161 Sender ! {send_please,self(),HugeMsg}, 162 receive HugeMsg -> ok end, 163 expect({trace_ts,Sender,send,HugeMsg,Self,ts}), 164 165 %% Kill trace port and force a trace. The emulator should not crasch. 166 167 unlink(Tracer), 168 exit(Tracer, kill), 169 erlang:yield(), % Make sure that port gets killed. 170 Sender ! {send_please,Self,good_bye}, 171 receive good_bye -> ok end, 172 ok. 173 174%% Test sending receive traces to a port. 175receive_trace(Config) when is_list(Config) -> 176 start_tracer(Config), 177 Receiver = fun_spawn(fun receiver/0), 178 trac(Receiver, true, ['receive']), 179 180 Receiver ! {hello,world}, 181 expect({trace,Receiver,'receive',{hello,world}}), 182 183 trac(Receiver, true, ['receive',timestamp]), 184 Huge = {hello,huge_data()}, 185 Receiver ! {hello,huge_data()}, 186 expect({trace_ts,Receiver,'receive',Huge,ts}), 187 ok. 188 189%% Test sending receive traces to a port. 190receive_trace_non_scheduler(Config) when is_list(Config) -> 191 start_tracer(Config), 192 S = self(), 193 Receiver = spawn_link( 194 fun() -> 195 receive 196 go -> 197 Ref = S ! erlang:trace_delivered(all), 198 receive {trace_delivered, Ref, all} -> ok end 199 end 200 end), 201 trac(Receiver, true, ['receive']), 202 Receiver ! go, 203 Ref = receive R -> R end, 204 expect({trace,Receiver,'receive',go}), 205 expect({trace,Receiver,'receive',{trace_delivered, all, Ref}}), 206 207 ok. 208 209%% Tests a few process events (like getting linked). 210process_events(Config) when is_list(Config) -> 211 start_tracer(Config), 212 Self = self(), 213 Receiver = fun_spawn(fun receiver/0), 214 trac(Receiver, true, [procs]), 215 216 unlink(Receiver), %It is already linked. 217 expect({trace,Receiver,getting_unlinked,Self}), 218 link(Receiver), 219 expect({trace,Receiver,getting_linked,Self}), 220 trac(Receiver, true, [procs,timestamp]), 221 unlink(Receiver), 222 expect({trace_ts,Receiver,getting_unlinked,Self,ts}), 223 link(Receiver), 224 expect({trace_ts,Receiver,getting_linked,Self,ts}), 225 226 unlink(Receiver), 227 expect({trace_ts,Receiver,getting_unlinked,Self,ts}), 228 Huge = huge_data(), 229 exit(Receiver, Huge), 230 expect({trace_ts,Receiver,exit,Huge,ts}), 231 232 ok. 233 234%% Test sending scheduling events to a port. 235schedule(Config) when is_list(Config) -> 236 start_tracer(Config), 237 Receiver = fun_spawn(fun receiver/0), 238 trac(Receiver, true, [running]), 239 240 Receiver ! hi, 241 expect({trace,Receiver,in,{?MODULE,receiver,0}}), 242 expect({trace,Receiver,out,{?MODULE,receiver,0}}), 243 244 trac(Receiver, true, [running,timestamp]), 245 246 Receiver ! hi_again, 247 expect({trace_ts,Receiver,in,{?MODULE,receiver,0},ts}), 248 expect({trace_ts,Receiver,out,{?MODULE,receiver,0},ts}), 249 250 ok. 251 252%% Test sending garbage collection events to a port. 253gc(Config) when is_list(Config) -> 254 start_tracer(Config), 255 Garber = fun_spawn(fun garber/0, [{min_heap_size, 5000}]), 256 trac(Garber, true, [garbage_collection]), 257 trace_info(Garber, flags), 258 259 trace_info(Garber, flags), 260 Garber ! hi, 261 expect({trace,Garber,gc_major_start,info}), 262 expect({trace,Garber,gc_major_end,info}), 263 264 trac(Garber, true, [garbage_collection,timestamp]), 265 Garber ! hi, 266 expect({trace_ts,Garber,gc_major_start,info,ts}), 267 expect({trace_ts,Garber,gc_major_end,info,ts}), 268 269 ok. 270 271%% Test a port as default tracer. 272default_tracer(Config) when is_list(Config) -> 273 Tracer = start_tracer(Config), 274 TracerMonitor = erlang:monitor(process, Tracer), 275 Port = get(tracer_port), 276 %% 277 N = erlang:trace(all, true, [send, {tracer, Port}]), 278 {flags, [send]} = erlang:trace_info(self(), flags), 279 {tracer, Port} = erlang:trace_info(self(), tracer), 280 {flags, [send]} = erlang:trace_info(new, flags), 281 {tracer, Port} = erlang:trace_info(new, tracer), 282 G1 = fun_spawn(fun general/0), 283 {flags, [send]} = erlang:trace_info(G1, flags), 284 {tracer, Port} = erlang:trace_info(G1, tracer), 285 unlink(Tracer), 286 exit(Port, done), 287 receive 288 {'DOWN', TracerMonitor, process, Tracer, TracerExitReason} -> 289 done = TracerExitReason 290 end, 291 {flags, []} = erlang:trace_info(self(), flags), 292 {tracer, []} = erlang:trace_info(self(), tracer), 293 {flags, []} = erlang:trace_info(new, flags), 294 {tracer, []} = erlang:trace_info(new, tracer), 295 M = erlang:trace(all, false, [all]), 296 {flags, []} = erlang:trace_info(self(), flags), 297 {tracer, []} = erlang:trace_info(self(), tracer), 298 {flags, []} = erlang:trace_info(G1, flags), 299 {tracer, []} = erlang:trace_info(G1, tracer), 300 G1 ! {apply,{erlang,exit,[normal]}}, 301 io:format("~p = ~p.~n", [M, N]), 302 M = N - 1, % G1 has been started, but Tracer and Port have died 303 ok. 304 305tracer_port_crash(Config) when is_list(Config) -> 306 case test_server:is_native(?MODULE) orelse 307 test_server:is_native(lists) of 308 true -> 309 {skip,"Native code"}; 310 false -> 311 Tr = start_tracer(Config), 312 Port = get(tracer_port), 313 Tracee = spawn(fun () -> 314 register(trace_port_linker, self()), 315 link(Port), 316 receive go -> ok end, 317 lists:reverse([1,b,c]), 318 receive die -> ok end 319 end), 320 Tr ! {unlink_tracer_port, self()}, 321 receive {unlinked_tracer_port, Tr} -> ok end, 322 port_control(Port, $c, []), %% Make port commands crash tracer port... 323 trace_func({lists,reverse,1}, []), 324 trace_pid(Tracee, true, [call]), 325 trace_info(Tracee, flags), 326 trace_info(self(), tracer), 327 Tracee ! go, 328 receive after 1000 -> ok end, 329 case whereis(trace_port_linker) of 330 undefined -> 331 ok; 332 Id -> 333 % erts_debug:set_internal_state(available_internal_state, true), 334 % erts_debug:set_internal_state(abort, {trace_port_linker, Id}) 335 ct:fail({trace_port_linker, Id}) 336 end, 337 undefined = process_info(Tracee), 338 ok 339 end. 340 341%%% Help functions. 342 343huge_data() -> huge_data(16384). 344huge_data(0) -> []; 345huge_data(N) when N rem 2 == 0 -> 346 P = huge_data(N div 2), 347 [P|P]; 348huge_data(N) -> 349 P = huge_data(N div 2), 350 [16#1234566,P|P]. 351 352expect({trace_ts,E1,E2,info,ts}=Message) -> 353 receive 354 {trace_ts,E1,E2,_Info,_Ts}=MessageTs -> 355 ok = io:format("Expected and got ~p", [MessageTs]), 356 MessageTs; 357 Other -> 358 io:format("Expected ~p; got ~p", [Message,Other]), 359 ct:fail({unexpected,Other}) 360 after 5000 -> 361 io:format("Expected ~p; got nothing", [Message]), 362 ct:fail(no_trace_message) 363 end; 364expect({trace,E1,E2,info}=Message) -> 365 receive 366 {trace,E1,E2,_Info}=MessageTs -> 367 ok = io:format("Expected and got ~p", [MessageTs]), 368 MessageTs; 369 Other -> 370 io:format("Expected ~p; got ~p", [Message,Other]), 371 ct:fail({unexpected,Other}) 372 after 5000 -> 373 io:format("Expected ~p; got nothing", [Message]), 374 ct:fail(no_trace_message) 375 end; 376expect({trace_ts,E1,E2,E3,ts}=Message) -> 377 receive 378 {trace_ts,E1,E2,E3,_Ts}=MessageTs -> 379 ok = io:format("Expected and got ~p", [MessageTs]), 380 MessageTs; 381 Other -> 382 io:format("Expected ~p; got ~p", [Message,Other]), 383 ct:fail({unexpected,Other}) 384 after 5000 -> 385 io:format("Expected ~p; got nothing", [Message]), 386 ct:fail(no_trace_message) 387 end; 388expect({trace_ts,E1,E2,E3,E4,ts}=Message) -> 389 receive 390 {trace_ts,E1,E2,E3,E4,_Ts}=MessageTs -> 391 ok = io:format("Expected and got ~p", [MessageTs]), 392 MessageTs; 393 Other -> 394 io:format("Expected ~p; got ~p", [Message,Other]), 395 ct:fail({unexpected,Other}) 396 after 5000 -> 397 io:format("Expected ~p; got nothing", [Message]), 398 ct:fail(no_trace_message) 399 end; 400expect(Message) -> 401 receive 402 Message -> 403 ok = io:format("Expected and got ~p", [Message]), 404 Message; 405 Other -> 406 io:format("Expected ~p; got ~p", [Message,Other]), 407 ct:fail({unexpected,Other}) 408 after 5000 -> 409 io:format("Expected ~p; got nothing", [Message]), 410 ct:fail(no_trace_message) 411 end. 412 413trac(What, On, Flags0) -> 414 Flags = [{tracer,get(tracer_port)}|Flags0], 415 get(tracer) ! {apply,self(),{erlang,trace,[What,On,Flags]}}, 416 Res = receive 417 {apply_result,Result} -> Result 418 end, 419 ok = io:format("erlang:trace(~p, ~p, ~p) -> ~p", 420 [What,On,Flags,Res]), 421 Res. 422 423trace_info(What, Key) -> 424 get(tracer) ! {apply,self(),{erlang,trace_info,[What,Key]}}, 425 Res = receive 426 {apply_result,Result} -> Result 427 end, 428 ok = io:format("erlang:trace_info(~p, ~p) -> ~p", 429 [What,Key,Res]), 430 Res. 431 432trace_func(MFA, MatchProg) -> 433 get(tracer) ! {apply,self(),{erlang,trace_pattern,[MFA,MatchProg]}}, 434 Res = receive 435 {apply_result,Result} -> Result 436 end, 437 ok = io:format("erlang:trace_pattern(~p, ~p) -> ~p", [MFA,MatchProg,Res]), 438 Res. 439 440trace_func(MFA, MatchProg, Flags) -> 441 get(tracer) ! {apply,self(),{erlang,trace_pattern,[MFA,MatchProg,Flags]}}, 442 Res = receive 443 {apply_result,Result} -> Result 444 end, 445 ok = io:format("erlang:trace_pattern(~p, ~p) -> ~p", [MFA,MatchProg,Res]), 446 Res. 447 448trace_pid(Pid, On, Flags0) -> 449 Flags = [{tracer,get(tracer_port)}|Flags0], 450 get(tracer) ! {apply,self(),{erlang,trace,[Pid,On,Flags]}}, 451 Res = receive 452 {apply_result,Result} -> Result 453 end, 454 ok = io:format("erlang:trace(~p, ~p, ~p) -> ~p", 455 [Pid,On,Flags,Res]), 456 Res. 457 458start_tracer(Config) -> 459 Path = proplists:get_value(data_dir, Config), 460 ok = load_driver(Path, echo_drv), 461 Self = self(), 462 put(tracer, fun_spawn(fun() -> tracer(Self) end)), 463 receive 464 {started,Port} -> 465 put(tracer_port, Port) 466 end, 467 get(tracer). 468 469load_driver(Dir, Driver) -> 470 case erl_ddll:load_driver(Dir, Driver) of 471 ok -> ok; 472 {error, Error} = Res -> 473 io:format("~s\n", [erl_ddll:format_error(Error)]), 474 Res 475 end. 476 477tracer(RelayTo) -> 478 Port = open_port({spawn,echo_drv}, [eof,binary]), 479 RelayTo ! {started,Port}, 480 tracer_loop(RelayTo, Port). 481 482tracer_loop(RelayTo, Port) -> 483 receive 484 {apply,From,{M,F,A}} -> 485 From ! {apply_result,apply(M, F, A)}, 486 tracer_loop(RelayTo, Port); 487 {Port,{data,Msg}} -> 488 RelayTo ! binary_to_term(Msg), 489 tracer_loop(RelayTo, Port); 490 {unlink_tracer_port, From} -> 491 unlink(Port), 492 From ! {unlinked_tracer_port, self()}, 493 tracer_loop(RelayTo, Port); 494 Other -> 495 exit({bad_message,Other}) 496 end. 497 498fun_spawn(Fun) -> 499 spawn_link(erlang, apply, [Fun,[]]). 500 501fun_spawn(Fun, Opts) -> 502 spawn_opt(erlang, apply, [Fun,[]], [link | Opts]). 503 504% flush() -> 505% receive 506% X -> 507% [X | flush()] 508% after 2000 -> 509% [] 510% end. 511 512 513%%% Models for various kinds of processes. 514 515%% Sends messages when ordered to. 516 517sender() -> 518 receive 519 {send_please, To, What} -> 520 To ! What, 521 sender() 522 end. 523 524%% Just consumes messages from its message queue. 525 526receiver() -> 527 receive 528 _Any -> receiver() 529 end. 530 531%% Does a garbage collection when it receives a message. 532 533garber() -> 534 receive 535 _Any -> 536 lists:seq(1, 100), 537 erlang:garbage_collect(), 538 garber() 539 end. 540 541%% All-purpose process 542 543general() -> 544 receive 545 {apply, {M, F, Args}} -> 546 erlang:apply(M, F, Args), 547 general(); 548 {send, Dest, Msg} -> 549 Dest ! Msg, 550 general(); 551 {call_f_1, Arg} -> 552 f(Arg), 553 general(); 554 nop -> 555 general() 556 end. 557 558f(Arg) -> 559 Arg. 560