1%% 2%% %CopyrightBegin% 3%% 4%% Copyright Ericsson AB 2007-2018. 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%%% Purpose : Tests system_profile BIF 23 24-module(system_profile_SUITE). 25 26-export([all/0, suite/0, 27 system_profile_on_and_off/1, 28 runnable_procs/1, runnable_ports/1, 29 dont_profile_profiler/1, 30 scheduler/1, sane_location/1]). 31 32-export([profiler_process/1, ring_loop/1, port_echo_start/0, 33 list_load/0, run_load/2]). 34 35-include_lib("common_test/include/ct.hrl"). 36 37suite() -> 38 [{ct_hooks,[ts_install_cth]}, 39 {timetrap, {minutes, 1}}]. 40 41all() -> 42 [system_profile_on_and_off, runnable_procs, 43 runnable_ports, scheduler, dont_profile_profiler, 44 sane_location]. 45 46%% No specification clause needed for an init function in a conf case!!! 47 48%% Test switching system_profiling on and off. 49system_profile_on_and_off(Config) when is_list(Config) -> 50 Pid = start_profiler_process(), 51 52 % Test runnable_ports on and off 53 undefined = erlang:system_profile(Pid, [runnable_ports]), 54 {Pid, [runnable_ports]} = erlang:system_profile(), 55 {Pid, [runnable_ports]} = erlang:system_profile(undefined, []), 56 57 % Test runnable_procs on and off 58 undefined = erlang:system_profile(Pid, [runnable_procs]), 59 {Pid, [runnable_procs]} = erlang:system_profile(), 60 {Pid, [runnable_procs]} = erlang:system_profile(undefined, []), 61 62 % Test scheduler on and off 63 undefined = erlang:system_profile(Pid, [scheduler]), 64 {Pid, [scheduler]} = erlang:system_profile(), 65 {Pid, [scheduler]} = erlang:system_profile(undefined, []), 66 67 % Test combined runnable_ports, runnable_procs, scheduler; on and off 68 undefined = erlang:system_profile(Pid, [scheduler, runnable_procs, runnable_ports]), 69 {Pid, [scheduler,runnable_procs,runnable_ports]} = erlang:system_profile(), 70 {Pid, [scheduler,runnable_procs,runnable_ports]} = erlang:system_profile(undefined, []), 71 72 % Test turned off and kill process 73 undefined = erlang:system_profile(), 74 exit(Pid,kill), 75 ok. 76 77%% Tests system_profiling with runnable_procs. 78runnable_procs(Config) when is_list(Config) -> 79 lists:foreach(fun (TsType) -> 80 Arg = case TsType of 81 no_timestamp -> 82 {timestamp, []}; 83 _ -> 84 {TsType, [TsType]} 85 end, 86 do_runnable_procs(Arg), 87 receive after 1000 -> ok end 88 end, 89 [no_timestamp, timestamp, monotonic_timestamp, 90 strict_monotonic_timestamp]). 91 92do_runnable_procs({TsType, TsTypeFlag}) -> 93 Pid = start_profiler_process(), 94 % start a ring of processes 95 % FIXME: Set #laps and #nodes in config file 96 Nodes = 10, 97 Laps = 10, 98 All = ring(Nodes, [link,monitor]), 99 [Master | _] = All, 100 undefined = erlang:system_profile(Pid, [runnable_procs]++TsTypeFlag), 101 % loop a message 102 ok = ring_message(Master, message, Laps), 103 ok = kill_ring(Master), 104 [receive {'DOWN', _, process, P, _} -> ok end || P <- All], 105 Events = get_profiler_events(), 106 erlang:system_profile(undefined, []), 107 put(master, Master), 108 put(laps, Laps), 109 true = has_runnable_event(TsType, Events), 110 Pids = sort_events_by_pid(Events), 111 ok = check_events(TsType, Pids, (Laps+1)*2+2, (Laps+1)*2), 112 erase(), 113 exit(Pid,kill), 114 ok. 115 116%% Tests system_profiling with runnable_port. 117runnable_ports(Config) when is_list(Config) -> 118 lists:foreach(fun (TsType) -> 119 Arg = case TsType of 120 no_timestamp -> 121 {timestamp, []}; 122 _ -> 123 {TsType, [TsType]} 124 end, 125 do_runnable_ports(Arg, Config), 126 receive after 1000 -> ok end 127 end, 128 [no_timestamp, timestamp, monotonic_timestamp, 129 strict_monotonic_timestamp]). 130 131do_runnable_ports({TsType, TsTypeFlag}, Config) -> 132 Pid = start_profiler_process(), 133 undefined = erlang:system_profile(Pid, [runnable_ports]++TsTypeFlag), 134 EchoPid = echo(Config), 135 % FIXME: Set config to number_of_echos 136 Laps = 10, 137 put(laps, Laps), 138 ok = echo_message(EchoPid, Laps, message), 139 Events = get_profiler_events(), 140 kill_em_all = kill_echo(EchoPid), 141 erlang:system_profile(undefined, []), 142 true = has_runnable_event(TsType, Events), 143 Pids = sort_events_by_pid(Events), 144 ok = check_events(TsType, Pids, Laps*2+2, Laps*2), 145 erase(), 146 exit(Pid,kill), 147 ok. 148 149%% Tests system_profiling with scheduler. 150scheduler(Config) when is_list(Config) -> 151 case erlang:system_info(schedulers_online) of 152 1 -> {skipped, "No need for scheduler test when only one scheduler online."}; 153 _ -> 154 Nodes = 10, 155 lists:foreach(fun (TsType) -> 156 Arg = case TsType of 157 no_timestamp -> 158 {timestamp, []}; 159 _ -> 160 {TsType, [TsType]} 161 end, 162 ok = check_block_system(Arg, Nodes), 163 ok = check_multi_scheduling_block(Arg, Nodes), 164 receive after 1000 -> ok end 165 end, 166 [no_timestamp, timestamp, monotonic_timestamp, 167 strict_monotonic_timestamp]) 168 end. 169 170%% Ensure system profiler process is not profiled. 171dont_profile_profiler(Config) when is_list(Config) -> 172 Pid = start_profiler_process(), 173 174 Nodes = 10, 175 Laps = 10, 176 [Master|_] = ring(Nodes, [link]), 177 undefined = erlang:system_profile(Pid, [runnable_procs]), 178 % loop a message 179 ok = ring_message(Master, message, Laps), 180 erlang:system_profile(undefined, []), 181 ok = kill_ring(Master), 182 Events = get_profiler_events(), 183 false = has_profiler_pid_event(Events, Pid), 184 185 exit(Pid,kill), 186 ok. 187 188%% Check sane location (of exits) 189sane_location(Config) when is_list(Config) -> 190 Check = spawn_link(fun() -> flush_sane_location() end), 191 erlang:system_profile(Check, [runnable_procs]), 192 Me = self(), 193 Pids = [spawn_link(fun() -> wat(Me) end) || _ <- lists:seq(1,100)], 194 [receive {Pid,ok} -> ok end || Pid <- Pids], 195 Check ! {Me, done}, 196 receive {Check,ok} -> ok end, 197 ok. 198 199wat(Pid) -> 200 Pid ! {self(), ok}. 201 202flush_sane_location() -> 203 receive 204 {profile,_,_,{M,F,A},_} when is_atom(M), is_atom(F), 205 is_integer(A) -> 206 flush_sane_location(); 207 {profile,_,_,0,_} -> 208 flush_sane_location(); 209 {Pid,done} when is_pid(Pid) -> 210 Pid ! {self(), ok}; 211 M -> 212 ct:fail({badness,M}) 213 end. 214 215 216%%% Check scheduler profiling 217 218check_multi_scheduling_block({TsType, TsTypeFlag}, Nodes) -> 219 Pid = start_profiler_process(), 220 undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag), 221 {ok, Supervisor} = start_load(Nodes), 222 wait(600), 223 erlang:system_flag(multi_scheduling, block), 224 wait(600), 225 erlang:system_flag(multi_scheduling, unblock), 226 {Pid, [scheduler]} = erlang:system_profile(undefined, []), 227 Events = get_profiler_events(), 228 true = has_scheduler_event(TsType, Events), 229 stop_load(Supervisor), 230 exit(Pid,kill), 231 erase(), 232 ok. 233 234check_block_system({TsType, TsTypeFlag}, Nodes) -> 235 Dummy = spawn(?MODULE, profiler_process, [[]]), 236 Pid = start_profiler_process(), 237 undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag), 238 {ok, Supervisor} = start_load(Nodes), 239 wait(300), 240 undefined = erlang:system_monitor(Dummy, [busy_port]), 241 {Dummy, [busy_port]} = erlang:system_monitor(undefined, []), 242 {Pid, [scheduler]} = erlang:system_profile(undefined, []), 243 Events = get_profiler_events(), 244 true = has_scheduler_event(TsType, Events), 245 stop_load(Supervisor), 246 exit(Pid,kill), 247 exit(Dummy,kill), 248 erase(), 249 ok. 250 251%%% Check events 252 253check_events(_TsType, [], _, _) -> ok; 254check_events(TsType, [Pid | Pids], ExpMaster, ExpMember) -> 255 Master = get(master), 256 CheckPids = get(pids), 257 {Events, N} = get_pid_events(Pid), 258 ok = check_event_flow(Events), 259 ok = check_event_ts(TsType, Events), 260 IsMember = lists:member(Pid, CheckPids), 261 {Title,Exp} = case Pid of 262 Master -> {master,ExpMaster}; 263 Pid when IsMember == true -> {member,ExpMember}; 264 _ -> {other,N} 265 end, 266 ok = case N of 267 Exp -> ok; 268 _ -> 269 io:format("Expected ~p and got ~p profile events from ~p ~p:~n~p~n", 270 [Exp, N, Title, Pid, Events]), 271 error 272 end, 273 check_events(TsType, Pids, ExpMaster, ExpMember). 274 275 276%% timestamp consistency check for descending timestamps 277 278check_event_ts(TsType, Events) -> 279 check_event_ts(TsType, Events, undefined). 280check_event_ts(_TsType, [], _) -> ok; 281check_event_ts(TsType, [Event | Events], undefined) -> 282 check_event_ts(TsType, Events, Event); 283check_event_ts(TsType, [{Pid, _, _, TS1}=Event | Events], {Pid,_,_,TS0}) -> 284 Time = case TsType of 285 timestamp -> 286 timer:now_diff(TS1, TS0); 287 monotonic_timestamp -> 288 TS1 - TS0; 289 strict_monotonic_timestamp -> 290 {MT1, _} = TS1, 291 {MT0, _} = TS0, 292 MT1 - MT0 293 end, 294 if 295 Time < 0.0 -> timestamp_error; 296 true -> check_event_ts(TsType, Events, Event) 297 end. 298 299%% consistency check for active vs. inactive activity (runnable) 300 301check_event_flow(Events) -> 302 case check_event_flow(Events, undefined) of 303 ok -> ok; 304 Error -> 305 io:format("Events = ~p\n", [Events]), 306 Error 307 end. 308 309check_event_flow([], _) -> ok; 310check_event_flow([Event | PidEvents], undefined) -> 311 check_event_flow(PidEvents, Event); 312check_event_flow([{Pid,Act,_,_}=Event | Events], PrevEvent) -> 313 case PrevEvent of 314 {Pid, Act, _MFA, _TS} -> consistency_error; 315 _ -> check_event_flow(Events, Event) 316 end. 317 318 319 320get_pid_events(Pid) -> 321 Events = get({pid_events, Pid}), 322 {Events, length(Events)}. 323 324sort_events_by_pid(Events) -> 325 sort_events_by_pid(lists:reverse(Events), []). 326sort_events_by_pid([], Pids) -> Pids; 327sort_events_by_pid([Event | Events],Pids) -> 328 case Event of 329 {profile,Pid,Act,MFA,TS} -> 330 case get({pid_events, Pid}) of 331 undefined -> 332 put({pid_events, Pid}, [{Pid,Act,MFA,TS}]), 333 sort_events_by_pid(Events, [Pid | Pids]); 334 PidEvents -> 335 put({pid_events, Pid}, [{Pid,Act,MFA,TS}|PidEvents]), 336 sort_events_by_pid(Events, Pids) 337 end 338 end. 339 340 341%%% 342%% Process ring 343%%% 344 345%% API 346 347% Returns master pid 348ring(N, SpawnOpt) -> 349 Pids = build_ring(N, [], SpawnOpt), 350 put(pids, Pids), 351 setup_ring(Pids), 352 Pids. 353 354ring_message(Master, Message, Laps) -> 355 Master ! {message, Master, Laps, Message}, 356 receive 357 {laps_complete, Master} -> ok 358 end. 359 360kill_ring(Master) -> 361 Master ! kill_em_all, 362 ok. 363 364%% Process ring helpers 365 366build_ring(0, Pids, _) -> Pids; 367build_ring(N, Pids, SpawnOpt) -> 368 Pid = case spawn_opt(?MODULE, ring_loop, [undefined], SpawnOpt) of 369 {P,_} -> P; 370 P -> P 371 end, 372 build_ring(N-1, [Pid | Pids], SpawnOpt). 373 374setup_ring([Master | Relayers]) -> 375 % Relayers may not include the master pid 376 Master ! {setup_ring, Relayers, self()}, 377 receive 378 {setup_complete, Master} -> Master 379 end. 380 381ring_loop(RelayTo) -> 382 receive 383 kill_em_all -> 384 RelayTo ! kill_em_all; 385 {setup_ring, [Pid | Pids], Supervisor} -> 386 put(supervisor, Supervisor), 387 Pid ! {relay_to, Pids, self()}, 388 ring_loop(Pid); 389 {setup_complete, _} -> 390 get(supervisor) ! {setup_complete, self()}, 391 ring_loop(RelayTo); 392 {relay_to, [], Master} -> 393 Master ! {setup_complete, self()}, 394 ring_loop(Master); 395 {relay_to, [Pid | Pids], Master} -> 396 Pid ! {relay_to, Pids, Master}, 397 ring_loop(Pid); 398 {message, Master, Lap, Msg}=Message -> 399 case {self(), Lap} of 400 {Master, 0} -> 401 get(supervisor) ! {laps_complete, self()}; 402 {Master, Lap} -> 403 RelayTo ! {message, Master, Lap - 1, Msg}; 404 _ -> 405 RelayTo ! Message 406 end, 407 ring_loop(RelayTo) 408 end. 409 410%%% 411%% Echo driver 412%%% 413 414%% API 415 416echo(Config) -> 417 Path = proplists:get_value(data_dir, Config), 418 erl_ddll:load_driver(Path, echo_drv), 419 Pid = spawn_link(?MODULE, port_echo_start, []), 420 Pid ! {self(), get_ports}, 421 receive 422 {port, Port} -> 423 put(pids, [Port]), 424 put(master, Port), 425 Pid 426 end. 427 428echo_message(Pid, N, Msg) -> 429 Pid ! {start_echo, self(), N, Msg}, 430 receive 431 {echo_complete, Pid} -> ok 432 end. 433 434kill_echo(Pid) -> Pid ! kill_em_all. 435 436 437%% Echo driver helpers 438port_echo_start() -> 439 Port = open_port({spawn,echo_drv}, [eof,binary]), 440 receive 441 {Pid, get_ports} -> 442 Pid ! {port, Port}, 443 port_echo_loop(Port) 444 end. 445 446port_echo_loop(Port) -> 447 receive 448 {start_echo, Pid, Echos, Msg} -> 449 port_command(Port, term_to_binary({Pid, Echos, Msg})), 450 port_echo_loop(Port); 451 {Port, {data, Data}} -> 452 {Pid, Echos, Msg} = binary_to_term(Data), 453 case Echos of 454 0 -> 455 Pid ! {echo_complete, self()}, 456 port_echo_loop(Port); 457 Echos -> 458 port_command(Port, term_to_binary({Pid, Echos - 1, Msg})), 459 port_echo_loop(Port) 460 end; 461 kill_em_all -> 462 port_close(Port), 463 ok 464 end. 465 466 467 468%%% 469%% Helpers 470%%% 471 472check_ts(no_timestamp, Ts) -> 473 try 474 no_timestamp = Ts 475 catch 476 _ : _ -> 477 ct:fail({unexpected_timestamp, Ts}) 478 end, 479 ok; 480check_ts(timestamp, Ts) -> 481 try 482 {Ms,S,Us} = Ts, 483 true = is_integer(Ms), 484 true = is_integer(S), 485 true = is_integer(Us) 486 catch 487 _ : _ -> 488 ct:fail({unexpected_timestamp, Ts}) 489 end, 490 ok; 491check_ts(monotonic_timestamp, Ts) -> 492 try 493 true = is_integer(Ts) 494 catch 495 _ : _ -> 496 ct:fail({unexpected_timestamp, Ts}) 497 end, 498 ok; 499check_ts(strict_monotonic_timestamp, Ts) -> 500 try 501 {MT, UMI} = Ts, 502 true = is_integer(MT), 503 true = is_integer(UMI) 504 catch 505 _ : _ -> 506 ct:fail({unexpected_timestamp, Ts}) 507 end, 508 ok. 509 510start_load(N) -> 511 Pid = spawn_link(?MODULE, run_load, [N, []]), 512 {ok, Pid}. 513 514 515stop_load(Supervisor) -> 516 erlang:unlink(Supervisor), 517 exit(Supervisor, kill). 518 519run_load(0, _Pids) -> 520 receive 521 % wait for an exit signal or a message then kill 522 % all associated processes. 523 _ -> exit(annihilated) 524 end; 525run_load(N, Pids) -> 526 Pid = spawn_link(?MODULE, list_load, []), 527 run_load(N - 1, [Pid | Pids]). 528 529list_load() -> 530 ok = case math:sin(rand:uniform(32451)) of 531 A when is_float(A) -> ok; 532 _ -> ok 533 end, 534 list_load(). 535 536has_scheduler_event(TsType, Events) -> 537 lists:any( 538 fun (Pred) -> 539 case Pred of 540 {profile, scheduler, _ID, _Activity, _NR, TS} -> 541 check_ts(TsType, TS), 542 true; 543 _ -> false 544 end 545 end, Events). 546 547has_runnable_event(TsType, Events) -> 548 lists:any( 549 fun (Pred) -> 550 case Pred of 551 {profile, _Pid, _Activity, _MFA, TS} -> 552 check_ts(TsType, TS), 553 true; 554 _ -> false 555 end 556 end, Events). 557 558has_profiler_pid_event([], _) -> 559 false; 560has_profiler_pid_event([{profile, Pid, _Activity, _MFA, _TS}|_Events], Pid) -> 561 true; 562has_profiler_pid_event([_|Events], Pid) -> 563 has_profiler_pid_event(Events, Pid). 564 565 566wait(Time) -> receive after Time -> ok end. 567 568%%% 569%% Receivers 570%%% 571 572%% Process receiver 573 574 575get_profiler_events() -> 576 Pid = get(profiler), 577 Pid ! {self(), get_events}, 578 receive 579 Events -> Events 580 end. 581 582start_profiler_process() -> 583 Pid = spawn(?MODULE, profiler_process, [[]]), 584 put(profiler, Pid), 585 Pid. 586 587profiler_process(Events) -> 588 receive 589 {Pid, get_events} -> 590 Ref = erlang:trace_delivered(all), 591 profiler_process_followup(Pid, Events, Ref); 592 Event -> 593 profiler_process([Event | Events]) 594 end. 595 596profiler_process_followup(Pid, Events, Ref) -> 597 receive 598 {trace_delivered,all,Ref} -> 599 Pid ! lists:reverse(Events); 600 Event -> 601 profiler_process_followup(Pid, [Event | Events], Ref) 602 end. 603 604%% Port receiver 605 606 607