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