%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2007-2016. 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%
%%
%%% Purpose : Tests system_profile BIF
-module(system_profile_SUITE).
-export([all/0, suite/0,
system_profile_on_and_off/1,
runnable_procs/1, runnable_ports/1,
dont_profile_profiler/1,
scheduler/1, sane_location/1]).
-export([profiler_process/1, ring_loop/1, port_echo_start/0,
list_load/0, run_load/2]).
-include_lib("common_test/include/ct.hrl").
suite() ->
[{ct_hooks,[ts_install_cth]},
{timetrap, {minutes, 1}}].
all() ->
[system_profile_on_and_off, runnable_procs,
runnable_ports, scheduler, dont_profile_profiler,
sane_location].
%% No specification clause needed for an init function in a conf case!!!
%% Test switching system_profiling on and off.
system_profile_on_and_off(Config) when is_list(Config) ->
Pid = start_profiler_process(),
% Test runnable_ports on and off
undefined = erlang:system_profile(Pid, [runnable_ports]),
{Pid, [runnable_ports]} = erlang:system_profile(),
{Pid, [runnable_ports]} = erlang:system_profile(undefined, []),
% Test runnable_procs on and off
undefined = erlang:system_profile(Pid, [runnable_procs]),
{Pid, [runnable_procs]} = erlang:system_profile(),
{Pid, [runnable_procs]} = erlang:system_profile(undefined, []),
% Test scheduler on and off
undefined = erlang:system_profile(Pid, [scheduler]),
{Pid, [scheduler]} = erlang:system_profile(),
{Pid, [scheduler]} = erlang:system_profile(undefined, []),
% Test combined runnable_ports, runnable_procs, scheduler; on and off
undefined = erlang:system_profile(Pid, [scheduler, runnable_procs, runnable_ports]),
{Pid, [scheduler,runnable_procs,runnable_ports]} = erlang:system_profile(),
{Pid, [scheduler,runnable_procs,runnable_ports]} = erlang:system_profile(undefined, []),
% Test turned off and kill process
undefined = erlang:system_profile(),
exit(Pid,kill),
ok.
%% Tests system_profiling with runnable_procs.
runnable_procs(Config) when is_list(Config) ->
lists:foreach(fun (TsType) ->
Arg = case TsType of
no_timestamp ->
{timestamp, []};
_ ->
{TsType, [TsType]}
end,
do_runnable_procs(Arg),
receive after 1000 -> ok end
end,
[no_timestamp, timestamp, monotonic_timestamp,
strict_monotonic_timestamp]).
do_runnable_procs({TsType, TsTypeFlag}) ->
Pid = start_profiler_process(),
% start a ring of processes
% FIXME: Set #laps and #nodes in config file
Nodes = 10,
Laps = 10,
All = ring(Nodes, [link,monitor]),
[Master | _] = All,
undefined = erlang:system_profile(Pid, [runnable_procs]++TsTypeFlag),
% loop a message
ok = ring_message(Master, message, Laps),
ok = kill_ring(Master),
[receive {'DOWN', _, process, P, _} -> ok end || P <- All],
Events = get_profiler_events(),
erlang:system_profile(undefined, []),
put(master, Master),
put(laps, Laps),
true = has_runnable_event(TsType, Events),
Pids = sort_events_by_pid(Events),
ok = check_events(TsType, Pids, (Laps+1)*2+2, (Laps+1)*2),
erase(),
exit(Pid,kill),
ok.
%% Tests system_profiling with runnable_port.
runnable_ports(Config) when is_list(Config) ->
lists:foreach(fun (TsType) ->
Arg = case TsType of
no_timestamp ->
{timestamp, []};
_ ->
{TsType, [TsType]}
end,
do_runnable_ports(Arg, Config),
receive after 1000 -> ok end
end,
[no_timestamp, timestamp, monotonic_timestamp,
strict_monotonic_timestamp]).
do_runnable_ports({TsType, TsTypeFlag}, Config) ->
Pid = start_profiler_process(),
undefined = erlang:system_profile(Pid, [runnable_ports]++TsTypeFlag),
EchoPid = echo(Config),
% FIXME: Set config to number_of_echos
Laps = 10,
put(laps, Laps),
ok = echo_message(EchoPid, Laps, message),
Events = get_profiler_events(),
kill_em_all = kill_echo(EchoPid),
erlang:system_profile(undefined, []),
true = has_runnable_event(TsType, Events),
Pids = sort_events_by_pid(Events),
ok = check_events(TsType, Pids, Laps*2+2, Laps*2),
erase(),
exit(Pid,kill),
ok.
%% Tests system_profiling with scheduler.
scheduler(Config) when is_list(Config) ->
case {erlang:system_info(smp_support), erlang:system_info(schedulers_online)} of
{false,_} -> {skipped, "No need for scheduler test when smp support is disabled."};
{_, 1} -> {skipped, "No need for scheduler test when only one scheduler online."};
_ ->
Nodes = 10,
lists:foreach(fun (TsType) ->
Arg = case TsType of
no_timestamp ->
{timestamp, []};
_ ->
{TsType, [TsType]}
end,
ok = check_block_system(Arg, Nodes),
ok = check_multi_scheduling_block(Arg, Nodes),
receive after 1000 -> ok end
end,
[no_timestamp, timestamp, monotonic_timestamp,
strict_monotonic_timestamp])
end.
%% Ensure system profiler process is not profiled.
dont_profile_profiler(Config) when is_list(Config) ->
Pid = start_profiler_process(),
Nodes = 10,
Laps = 10,
[Master|_] = ring(Nodes, [link]),
undefined = erlang:system_profile(Pid, [runnable_procs]),
% loop a message
ok = ring_message(Master, message, Laps),
erlang:system_profile(undefined, []),
ok = kill_ring(Master),
Events = get_profiler_events(),
false = has_profiler_pid_event(Events, Pid),
exit(Pid,kill),
ok.
%% Check sane location (of exits)
sane_location(Config) when is_list(Config) ->
Check = spawn_link(fun() -> flush_sane_location() end),
erlang:system_profile(Check, [runnable_procs]),
Me = self(),
Pids = [spawn_link(fun() -> wat(Me) end) || _ <- lists:seq(1,100)],
[receive {Pid,ok} -> ok end || Pid <- Pids],
Check ! {Me, done},
receive {Check,ok} -> ok end,
ok.
wat(Pid) ->
Pid ! {self(), ok}.
flush_sane_location() ->
receive
{profile,_,_,{M,F,A},_} when is_atom(M), is_atom(F),
is_integer(A) ->
flush_sane_location();
{profile,_,_,0,_} ->
flush_sane_location();
{Pid,done} when is_pid(Pid) ->
Pid ! {self(), ok};
M ->
ct:fail({badness,M})
end.
%%% Check scheduler profiling
check_multi_scheduling_block({TsType, TsTypeFlag}, Nodes) ->
Pid = start_profiler_process(),
undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag),
{ok, Supervisor} = start_load(Nodes),
wait(600),
erlang:system_flag(multi_scheduling, block),
wait(600),
erlang:system_flag(multi_scheduling, unblock),
{Pid, [scheduler]} = erlang:system_profile(undefined, []),
Events = get_profiler_events(),
true = has_scheduler_event(TsType, Events),
stop_load(Supervisor),
exit(Pid,kill),
erase(),
ok.
check_block_system({TsType, TsTypeFlag}, Nodes) ->
Dummy = spawn(?MODULE, profiler_process, [[]]),
Pid = start_profiler_process(),
undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag),
{ok, Supervisor} = start_load(Nodes),
wait(300),
undefined = erlang:system_monitor(Dummy, [busy_port]),
{Dummy, [busy_port]} = erlang:system_monitor(undefined, []),
{Pid, [scheduler]} = erlang:system_profile(undefined, []),
Events = get_profiler_events(),
true = has_scheduler_event(TsType, Events),
stop_load(Supervisor),
exit(Pid,kill),
exit(Dummy,kill),
erase(),
ok.
%%% Check events
check_events(_TsType, [], _, _) -> ok;
check_events(TsType, [Pid | Pids], ExpMaster, ExpMember) ->
Master = get(master),
CheckPids = get(pids),
{Events, N} = get_pid_events(Pid),
ok = check_event_flow(Events),
ok = check_event_ts(TsType, Events),
IsMember = lists:member(Pid, CheckPids),
{Title,Exp} = case Pid of
Master -> {master,ExpMaster};
Pid when IsMember == true -> {member,ExpMember};
_ -> {other,N}
end,
ok = case N of
Exp -> ok;
_ ->
io:format("Expected ~p and got ~p profile events from ~p ~p:~n~p~n",
[Exp, N, Title, Pid, Events]),
error
end,
check_events(TsType, Pids, ExpMaster, ExpMember).
%% timestamp consistency check for descending timestamps
check_event_ts(TsType, Events) ->
check_event_ts(TsType, Events, undefined).
check_event_ts(_TsType, [], _) -> ok;
check_event_ts(TsType, [Event | Events], undefined) ->
check_event_ts(TsType, Events, Event);
check_event_ts(TsType, [{Pid, _, _, TS1}=Event | Events], {Pid,_,_,TS0}) ->
Time = case TsType of
timestamp ->
timer:now_diff(TS1, TS0);
monotonic_timestamp ->
TS1 - TS0;
strict_monotonic_timestamp ->
{MT1, _} = TS1,
{MT0, _} = TS0,
MT1 - MT0
end,
if
Time < 0.0 -> timestamp_error;
true -> check_event_ts(TsType, Events, Event)
end.
%% consistency check for active vs. inactive activity (runnable)
check_event_flow(Events) ->
case check_event_flow(Events, undefined) of
ok -> ok;
Error ->
io:format("Events = ~p\n", [Events]),
Error
end.
check_event_flow([], _) -> ok;
check_event_flow([Event | PidEvents], undefined) ->
check_event_flow(PidEvents, Event);
check_event_flow([{Pid,Act,_,_}=Event | Events], PrevEvent) ->
case PrevEvent of
{Pid, Act, _MFA, _TS} -> consistency_error;
_ -> check_event_flow(Events, Event)
end.
get_pid_events(Pid) ->
Events = get({pid_events, Pid}),
{Events, length(Events)}.
sort_events_by_pid(Events) ->
sort_events_by_pid(lists:reverse(Events), []).
sort_events_by_pid([], Pids) -> Pids;
sort_events_by_pid([Event | Events],Pids) ->
case Event of
{profile,Pid,Act,MFA,TS} ->
case get({pid_events, Pid}) of
undefined ->
put({pid_events, Pid}, [{Pid,Act,MFA,TS}]),
sort_events_by_pid(Events, [Pid | Pids]);
PidEvents ->
put({pid_events, Pid}, [{Pid,Act,MFA,TS}|PidEvents]),
sort_events_by_pid(Events, Pids)
end
end.
%%%
%% Process ring
%%%
%% API
% Returns master pid
ring(N, SpawnOpt) ->
Pids = build_ring(N, [], SpawnOpt),
put(pids, Pids),
setup_ring(Pids),
Pids.
ring_message(Master, Message, Laps) ->
Master ! {message, Master, Laps, Message},
receive
{laps_complete, Master} -> ok
end.
kill_ring(Master) ->
Master ! kill_em_all,
ok.
%% Process ring helpers
build_ring(0, Pids, _) -> Pids;
build_ring(N, Pids, SpawnOpt) ->
Pid = case spawn_opt(?MODULE, ring_loop, [undefined], SpawnOpt) of
{P,_} -> P;
P -> P
end,
build_ring(N-1, [Pid | Pids], SpawnOpt).
setup_ring([Master | Relayers]) ->
% Relayers may not include the master pid
Master ! {setup_ring, Relayers, self()},
receive
{setup_complete, Master} -> Master
end.
ring_loop(RelayTo) ->
receive
kill_em_all ->
RelayTo ! kill_em_all;
{setup_ring, [Pid | Pids], Supervisor} ->
put(supervisor, Supervisor),
Pid ! {relay_to, Pids, self()},
ring_loop(Pid);
{setup_complete, _} ->
get(supervisor) ! {setup_complete, self()},
ring_loop(RelayTo);
{relay_to, [], Master} ->
Master ! {setup_complete, self()},
ring_loop(Master);
{relay_to, [Pid | Pids], Master} ->
Pid ! {relay_to, Pids, Master},
ring_loop(Pid);
{message, Master, Lap, Msg}=Message ->
case {self(), Lap} of
{Master, 0} ->
get(supervisor) ! {laps_complete, self()};
{Master, Lap} ->
RelayTo ! {message, Master, Lap - 1, Msg};
_ ->
RelayTo ! Message
end,
ring_loop(RelayTo)
end.
%%%
%% Echo driver
%%%
%% API
echo(Config) ->
Path = proplists:get_value(data_dir, Config),
erl_ddll:load_driver(Path, echo_drv),
Pid = spawn_link(?MODULE, port_echo_start, []),
Pid ! {self(), get_ports},
receive
{port, Port} ->
put(pids, [Port]),
put(master, Port),
Pid
end.
echo_message(Pid, N, Msg) ->
Pid ! {start_echo, self(), N, Msg},
receive
{echo_complete, Pid} -> ok
end.
kill_echo(Pid) -> Pid ! kill_em_all.
%% Echo driver helpers
port_echo_start() ->
Port = open_port({spawn,echo_drv}, [eof,binary]),
receive
{Pid, get_ports} ->
Pid ! {port, Port},
port_echo_loop(Port)
end.
port_echo_loop(Port) ->
receive
{start_echo, Pid, Echos, Msg} ->
port_command(Port, term_to_binary({Pid, Echos, Msg})),
port_echo_loop(Port);
{Port, {data, Data}} ->
{Pid, Echos, Msg} = binary_to_term(Data),
case Echos of
0 ->
Pid ! {echo_complete, self()},
port_echo_loop(Port);
Echos ->
port_command(Port, term_to_binary({Pid, Echos - 1, Msg})),
port_echo_loop(Port)
end;
kill_em_all ->
port_close(Port),
ok
end.
%%%
%% Helpers
%%%
check_ts(no_timestamp, Ts) ->
try
no_timestamp = Ts
catch
_ : _ ->
ct:fail({unexpected_timestamp, Ts})
end,
ok;
check_ts(timestamp, Ts) ->
try
{Ms,S,Us} = Ts,
true = is_integer(Ms),
true = is_integer(S),
true = is_integer(Us)
catch
_ : _ ->
ct:fail({unexpected_timestamp, Ts})
end,
ok;
check_ts(monotonic_timestamp, Ts) ->
try
true = is_integer(Ts)
catch
_ : _ ->
ct:fail({unexpected_timestamp, Ts})
end,
ok;
check_ts(strict_monotonic_timestamp, Ts) ->
try
{MT, UMI} = Ts,
true = is_integer(MT),
true = is_integer(UMI)
catch
_ : _ ->
ct:fail({unexpected_timestamp, Ts})
end,
ok.
start_load(N) ->
Pid = spawn_link(?MODULE, run_load, [N, []]),
{ok, Pid}.
stop_load(Supervisor) ->
erlang:unlink(Supervisor),
exit(Supervisor, kill).
run_load(0, _Pids) ->
receive
% wait for an exit signal or a message then kill
% all associated processes.
_ -> exit(annihilated)
end;
run_load(N, Pids) ->
Pid = spawn_link(?MODULE, list_load, []),
run_load(N - 1, [Pid | Pids]).
list_load() ->
ok = case math:sin(rand:uniform(32451)) of
A when is_float(A) -> ok;
_ -> ok
end,
list_load().
has_scheduler_event(TsType, Events) ->
lists:any(
fun (Pred) ->
case Pred of
{profile, scheduler, _ID, _Activity, _NR, TS} ->
check_ts(TsType, TS),
true;
_ -> false
end
end, Events).
has_runnable_event(TsType, Events) ->
lists:any(
fun (Pred) ->
case Pred of
{profile, _Pid, _Activity, _MFA, TS} ->
check_ts(TsType, TS),
true;
_ -> false
end
end, Events).
has_profiler_pid_event([], _) -> false;
has_profiler_pid_event([{profile, Pid, _Activity, _MFA, _TS}|Events], Pid) -> true;
has_profiler_pid_event([_|Events], Pid) ->
has_profiler_pid_event(Events, Pid).
wait(Time) -> receive after Time -> ok end.
%%%
%% Receivers
%%%
%% Process receiver
get_profiler_events() ->
Pid = get(profiler),
Pid ! {self(), get_events},
receive
Events -> Events
end.
start_profiler_process() ->
Pid = spawn(?MODULE, profiler_process, [[]]),
put(profiler, Pid),
Pid.
profiler_process(Events) ->
receive
{Pid, get_events} ->
Ref = erlang:trace_delivered(all),
profiler_process_followup(Pid, Events, Ref);
Event ->
profiler_process([Event | Events])
end.
profiler_process_followup(Pid, Events, Ref) ->
receive
{trace_delivered,all,Ref} ->
Pid ! lists:reverse(Events);
Event ->
profiler_process_followup(Pid, [Event | Events], Ref)
end.
%% Port receiver