diff options
| -rw-r--r-- | lib/hipe/cerl/erl_bif_types.erl | 5 | ||||
| -rw-r--r-- | lib/tools/doc/src/eprof.xml | 55 | ||||
| -rw-r--r-- | lib/tools/src/eprof.erl | 756 | ||||
| -rw-r--r-- | lib/tools/test/eprof_SUITE.erl | 95 | ||||
| -rw-r--r-- | lib/tools/test/eprof_SUITE_data/eprof_test.erl | 9 | ||||
| -rw-r--r-- | lib/tools/test/fprof_SUITE.erl | 4 |
6 files changed, 517 insertions, 407 deletions
diff --git a/lib/hipe/cerl/erl_bif_types.erl b/lib/hipe/cerl/erl_bif_types.erl index 838f9429f0..9df3dedb45 100644 --- a/lib/hipe/cerl/erl_bif_types.erl +++ b/lib/hipe/cerl/erl_bif_types.erl @@ -4026,7 +4026,8 @@ arg_types(erlang, trace_info, 2) -> t_atom('flags'), t_atom('tracer'), %% while the following are items about a func t_atom('traced'), t_atom('match_spec'), t_atom('meta'), - t_atom('meta_match_spec'), t_atom('call_count'), t_atom('all')])]; + t_atom('meta_match_spec'), t_atom('call_count'), + t_atom('call_time'), t_atom('all')])]; arg_types(erlang, trace_pattern, 2) -> [t_sup(t_tuple([t_atom(), t_atom(), t_sup(t_arity(), t_atom('_'))]), t_atom('on_load')), @@ -4035,7 +4036,7 @@ arg_types(erlang, trace_pattern, 3) -> arg_types(erlang, trace_pattern, 2) ++ [t_list(t_sup([t_atom('global'), t_atom('local'), t_atom('meta'), t_tuple([t_atom('meta'), t_pid()]), - t_atom('call_count')]))]; + t_atom('call_count'), t_atom('call_time')]))]; arg_types(erlang, trunc, 1) -> [t_number()]; arg_types(erlang, tuple_size, 1) -> diff --git a/lib/tools/doc/src/eprof.xml b/lib/tools/doc/src/eprof.xml index ae1033f2d0..6d68c90768 100644 --- a/lib/tools/doc/src/eprof.xml +++ b/lib/tools/doc/src/eprof.xml @@ -4,7 +4,7 @@ <erlref> <header> <copyright> - <year>1996</year><year>2009</year> + <year>1996</year><year>2010</year> <holder>Ericsson AB. All Rights Reserved.</holder> </copyright> <legalnotice> @@ -13,12 +13,12 @@ compliance with the License. You should have received a copy of the Erlang Public License along with this software. If not, it can be retrieved online at http://www.erlang.org/. - + Software distributed under the License is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License for the specific language governing rights and limitations under the License. - + </legalnotice> <title>eprof</title> @@ -35,8 +35,7 @@ used. The profiling is done using the Erlang trace BIFs. Tracing of local function calls for a specified set of processes is enabled when profiling is begun, and disabled when profiling is stopped.</p> - <p>When using Eprof, expect a significant slowdown in program execution, - in most cases at least 100 percent.</p> + <p>When using Eprof expect a slowdown in program execution.</p> </description> <funcs> <func> @@ -47,15 +46,19 @@ <v>Reason = {already_started,Pid}</v> </type> <desc> - <p>Starts the Eprof server which owns the Eprof internal database.</p> + <p>Starts the Eprof server which holds the internal state of the collected data.</p> </desc> </func> <func> - <name>start_profiling(Rootset) -> profiling | error</name> - <name>profile(Rootset) -> profiling | error</name> + <name>start_profiling(Rootset) -> profiling | {error, Reason}</name> + <name>start_profiling(Rootset,Pattern) -> profiling | {error, Reason}</name> <fsummary>Start profiling.</fsummary> <type> <v>Rootset = [atom() | pid()]</v> + <v>Pattern = {Module, Function, Arity}</v> + <v>Module = Function = atom()</v> + <v>Arity = integer()</v> + <v>Reason = term()</v> </type> <desc> <p>Starts profiling for the processes in <c>Rootset</c> (and any new @@ -64,6 +67,9 @@ <p><c>Rootset</c> is a list of pids and registered names.</p> <p>The function returns <c>profiling</c> if tracing could be enabled for all processes in <c>Rootset</c>, or <c>error</c> otherwise.</p> + <p>A pattern can be selected to narrow the profiling. For instance ca a specific + module be selected and only the code processes executes in that module will be + profiled.</p> </desc> </func> <func> @@ -75,14 +81,20 @@ </desc> </func> <func> - <name>profile(Rootset,Fun) -> {ok,Value} | {error,Reason} | error</name> - <name>profile(Rootset,Module,Function,Args) -> {ok,Value} | {error,Reason} | error</name> + <name>profile(Fun) -> profiling | {error, Reason}</name> + <name>profile(Rootset) -> profiling | {error, Reason}</name> + <name>profile(Rootset,Fun) -> {ok, Value} | {error,Reason}</name> + <name>profile(Rootset,Fun,Pattern) -> {ok, Value} | {error, Reason}</name> + <name>profile(Rootset,Module,Function,Args) -> {ok, Value} | {error, Reason}</name> + <name>profile(Rootset,Module,Function,Args,Pattern) -> {ok, Value} | {error, Reason}</name> <fsummary>Start profiling.</fsummary> <type> <v>Rootset = [atom() | pid()]</v> <v>Fun = fun() -> term()</v> + <v>Pattern = {Module, Function, Arity}</v> <v>Module = Function = atom()</v> <v>Args = [term()]</v> + <v>Arity = integer()</v> <v>Value = Reason = term()</v> </type> <desc> @@ -96,7 +108,7 @@ <c>Rootset</c>, the function returns <c>{ok,Value}</c> when <c>Fun()</c>/<c>apply</c> returns with the value <c>Value</c>, or <c>{error,Reason}</c> if <c>Fun()</c>/<c>apply</c> fails with - exit reason <c>Reason</c>. Otherwise it returns <c>error</c> + exit reason <c>Reason</c>. Otherwise it returns <c>{error, Reason}</c> immediately.</p> <p>The programmer must ensure that the function given as argument is truly synchronous and that no work continues after @@ -104,7 +116,15 @@ </desc> </func> <func> - <name>analyse()</name> + <name>analyze() -> ok</name> + <name>analyze(Type) -> ok</name> + <name>analyze(Type,Options) -> ok</name> + <type> + <v>Type = procs | total</v> + <v>Options = [{filter, Filter} | {sort, Sort}</v> + <v>Filter = [{calls, integer()} | {time, float()}]</v> + <v>Sort = time | calls | mfa</v> + </type> <fsummary>Display profiling results per process.</fsummary> <desc> <p>Call this function when profiling has been stopped to display @@ -113,17 +133,10 @@ <item>how much time has been used by each process, and</item> <item>in which function calls this time has been spent.</item> </list> - <p>Time is shown as percentage of total time, not as absolute time.</p> - </desc> - </func> - <func> - <name>total_analyse()</name> - <fsummary>Display profiling results per function call.</fsummary> - <desc> - <p>Call this function when profiling has been stopped to display + <p>Call <c>analyze</c> with <c>total</c> option when profiling has been stopped to display the results per function call, that is in which function calls the time has been spent.</p> - <p>Time is shown as percentage of total time, not as absolute time.</p> + <p>Time is shown as percentage of total time and as absolute time.</p> </desc> </func> <func> diff --git a/lib/tools/src/eprof.erl b/lib/tools/src/eprof.erl index b4313d6888..f7c1b76364 100644 --- a/lib/tools/src/eprof.erl +++ b/lib/tools/src/eprof.erl @@ -1,19 +1,19 @@ %% %% %CopyrightBegin% -%% -%% Copyright Ericsson AB 1996-2009. All Rights Reserved. -%% +%% +%% Copyright Ericsson AB 1996-2010. All Rights Reserved. +%% %% The contents of this file are subject to the Erlang Public License, %% Version 1.1, (the "License"); you may not use this file except in %% compliance with the License. You should have received a copy of the %% Erlang Public License along with this software. If not, it can be %% retrieved online at http://www.erlang.org/. -%% +%% %% Software distributed under the License is distributed on an "AS IS" %% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See %% the License for the specific language governing rights and limitations %% under the License. -%% +%% %% %CopyrightEnd% %% %% Purpose: Profile a system in order to figure out where the @@ -23,456 +23,464 @@ -module(eprof). -behaviour(gen_server). --export([start/0, stop/0, dump/0, total_analyse/0, - start_profiling/1, profile/2, profile/4, profile/1, - stop_profiling/0, analyse/0, log/1]). +-export([start/0, + stop/0, + dump/0, + start_profiling/1, start_profiling/2, + profile/1, profile/2, profile/3, profile/4, profile/5, + stop_profiling/0, + analyze/0, analyze/1, analyze/2, + log/1]). %% Internal exports -export([init/1, - call/4, handle_call/3, handle_cast/2, handle_info/2, terminate/2, code_change/3]). +-record(bpd, { + n = 0, % number of total calls + us = 0, % sum of uS for all calls + p = gb_trees:empty(), % tree of {Pid, {Mfa, {Count, Us}}} + mfa = [] % list of {Mfa, {Count, Us}} + }). + +-record(state, { + profiling = false, + pattern = {'_','_','_'}, + rootset = [], + fd = undefined, + start_ts = undefined, + reply = undefined, + bpd = #bpd{} + }). + + + +%% -------------------------------------------------------------------- %% +%% +%% API +%% +%% -------------------------------------------------------------------- %% --include_lib("stdlib/include/qlc.hrl"). - --import(lists, [flatten/1,reverse/1,keysort/2]). - - --record(state, {table = notable, - proc = noproc, - profiling = false, - pfunc = undefined, - pop = running, - ptime = 0, - overhead = 0, - rootset = []}). - -%%%%%%%%%%%%%% - -start() -> gen_server:start({local, eprof}, eprof, [], []). -stop() -> gen_server:call(eprof, stop, infinity). +start() -> gen_server:start({local, ?MODULE}, ?MODULE, [], []). +stop() -> gen_server:call(?MODULE, stop, infinity). +profile(Fun) when is_function(Fun) -> + profile([], Fun); +profile(Rs) when is_list(Rs) -> + start_profiling(Rs). profile(Pids, Fun) -> - start(), - gen_server:call(eprof, {profile,Pids,erlang,apply,[Fun,[]]},infinity). + profile(Pids, Fun, {'_','_','_'}). + +profile(Pids, Fun, Pattern) -> + profile(Pids, erlang, apply, [Fun,[]], Pattern). profile(Pids, M, F, A) -> + profile(Pids, M, F, A, {'_','_','_'}). + +profile(Pids, M, F, A, Pattern) -> start(), - gen_server:call(eprof, {profile,Pids,M,F,A},infinity). + gen_server:call(?MODULE, {profile,Pids,Pattern,M,F,A},infinity). dump() -> - gen_server:call(eprof, dump, infinity). + gen_server:call(?MODULE, dump, infinity). -analyse() -> - gen_server:call(eprof, analyse, infinity). +analyze() -> + analyze(procs). -log(File) -> - gen_server:call(eprof, {logfile, File}, infinity). +analyze(Type) when is_atom(Type) -> + analyze(Type, []); +analyze(Opts) when is_list(Opts) -> + analyze(procs, Opts). +analyze(Type, Opts) when is_list(Opts) -> + gen_server:call(?MODULE, {analyze, Type, Opts}, infinity). -total_analyse() -> - gen_server:call(eprof, total_analyse, infinity). +log(File) -> + gen_server:call(?MODULE, {logfile, File}, infinity). start_profiling(Rootset) -> + start_profiling(Rootset, {'_','_','_'}). +start_profiling(Rootset, Pattern) -> start(), - gen_server:call(eprof, {profile, Rootset}, infinity). + gen_server:call(?MODULE, {profile, Rootset, Pattern}, infinity). stop_profiling() -> - gen_server:call(eprof, stop_profiling, infinity). + gen_server:call(?MODULE, stop_profiling, infinity). -profile(Rs) -> - start_profiling(Rs). -%%%%%%%%%%%%%%%% +%% -------------------------------------------------------------------- %% +%% +%% init +%% +%% -------------------------------------------------------------------- %% -init(_) -> +init([]) -> process_flag(trap_exit, true), - process_flag(priority, max), - put(three_one, {3,1}), %To avoid building garbage. {ok, #state{}}. -subtr({X1,Y1,Z1}, {X1,Y1,Z2}) -> - Z1 - Z2; -subtr({X1,Y1,Z1}, {X2,Y2,Z2}) -> - (((X1-X2) * 1000000) + Y1 - Y2) * 1000000 + Z1 - Z2. +%% -------------------------------------------------------------------- %% +%% +%% handle_call +%% +%% -------------------------------------------------------------------- %% -update_call_statistics(Tab, Key, Time) -> - try ets:update_counter(Tab, Key, Time) of - NewTime when is_integer(NewTime) -> - ets:update_counter(Tab, Key, get(three_one)) - catch - error:badarg -> - ets:insert(Tab, {Key,Time,1}) - end. +%% analyze -update_other_statistics(Tab, Key, Time) -> - try - ets:update_counter(Tab, Key, Time) - catch - error:badarg -> - ets:insert(Tab, {Key,Time,0}) - end. +handle_call({analyze, _, _}, _, #state{ bpd = #bpd{ p = {0,nil}, us = 0, n = 0} = Bpd } = S) when is_record(Bpd, bpd) -> + {reply, nothing_to_analyze, S}; -do_messages({trace_ts,From,Op,Mfa,Time}, Tab, undefined,_PrevOp0,_PrevTime0) -> - PrevFunc = [From|Mfa], - receive - {trace_ts,_,_,_,_}=Ts -> do_messages(Ts, Tab, PrevFunc, Op, Time) - after 0 -> - {PrevFunc,Op,Time} - end; -do_messages({trace_ts,From,Op,Mfa,Time}, Tab, PrevFunc0, call, PrevTime0) -> - update_call_statistics(Tab, PrevFunc0, subtr(Time, PrevTime0)), - PrevFunc = case Op of - exit -> undefined; - out -> undefined; - _ -> [From|Mfa] - end, - receive - {trace_ts,_,_,_,_}=Ts -> do_messages(Ts, Tab, PrevFunc, Op, Time) - after 0 -> - {PrevFunc,Op,Time} - end; -do_messages({trace_ts,From,Op,Mfa,Time}, Tab, PrevFunc0, _PrevOp0, PrevTime0) -> - update_other_statistics(Tab, PrevFunc0, subtr(Time, PrevTime0)), - PrevFunc = case Op of - exit -> undefined; - out -> undefined; - _ -> [From|Mfa] - end, - receive - {trace_ts,_,_,_,_}=Ts -> do_messages(Ts, Tab, PrevFunc, Op, Time) - after 0 -> - {PrevFunc,Op,Time} - end. +handle_call({analyze, procs, Opts}, _, #state{ bpd = #bpd{ p = Ps, us = Tus} = Bpd, fd = Fd} = S) when is_record(Bpd, bpd) -> + lists:foreach(fun + ({Pid, Mfas}) -> + {Pn, Pus} = sum_bp_total_n_us(Mfas), + format(Fd, "~n****** Process ~w -- ~s % of profiled time *** ~n", [Pid, s("~.2f", [100.0*(Pus/Tus)])]), + print_bp_mfa(Mfas, {Pn,Pus}, Fd, Opts), + ok + end, gb_trees:to_list(Ps)), + {reply, ok, S}; -%%%%%%%%%%%%%%%%%% +handle_call({analyze, total, Opts}, _, #state{ bpd = #bpd{ mfa = Mfas, n = Tn, us = Tus} = Bpd, fd = Fd} = S) when is_record(Bpd, bpd) -> + print_bp_mfa(Mfas, {Tn, Tus}, Fd, Opts), + {reply, ok, S}; -handle_cast(_Req, S) -> {noreply, S}. +handle_call({analyze, Type, _Opts}, _, S) -> + {reply, {error, {undefined, Type}}, S}; -terminate(_Reason,_S) -> - call_trace_for_all(false), - normal. +%% profile -%%%%%%%%%%%%%%%%%% +handle_call({profile, _Rootset, _Pattern, _M,_F,_A}, _From, #state{ profiling = true } = S) -> + {reply, {error, already_profiling}, S}; -handle_call({logfile, F}, _FromTag, Status) -> - case file:open(F, [write]) of - {ok, Fd} -> - case get(fd) of - undefined -> ok; - FdOld -> file:close(FdOld) - end, - put(fd, Fd), - {reply, ok, Status}; - {error, _} -> - {reply, error, Status} - end; +handle_call({profile, Rootset, Pattern, M,F,A}, From, #state{fd = Fd } = S) -> -handle_call({profile, Rootset}, {From, _Tag}, S) -> - link(From), - maybe_delete(S#state.table), - io:format("eprof: Starting profiling ..... ~n",[]), - ptrac(S#state.rootset, false, all()), - flush_receive(), - Tab = ets:new(eprof, [set, public]), - case ptrac(Rootset, true, all()) of - false -> - {reply, error, #state{}}; + set_pattern_trace(false, S#state.pattern), + set_process_trace(false, S#state.rootset), + + Pid = setup_profiling(M,F,A), + case set_process_trace(true, [Pid|Rootset]) of true -> - uni_schedule(), - call_trace_for_all(true), - erase(replyto), - {reply, profiling, #state{table = Tab, - proc = From, - profiling = true, - rootset = Rootset}} + set_pattern_trace(true, Pattern), + T0 = now(), + execute_profiling(Pid), + {noreply, #state{ + profiling = true, + rootset = [Pid|Rootset], + start_ts = T0, + reply = From, + fd = Fd, + pattern = Pattern + }}; + false -> + exit(Pid, eprof_kill), + {reply, error, #state{ fd = Fd}} end; -handle_call(stop_profiling, _FromTag, S) when S#state.profiling -> - ptrac(S#state.rootset, false, all()), - call_trace_for_all(false), - multi_schedule(), - io:format("eprof: Stop profiling~n",[]), - ets:delete(S#state.table, nofunc), - {reply, profiling_stopped, S#state{profiling = false}}; +handle_call({profile, _Rootset, _Pattern}, _From, #state{ profiling = true } = S) -> + {reply, {error, already_profiling}, S}; -handle_call(stop_profiling, _FromTag, S) -> - {reply, profiling_already_stopped, S}; +handle_call({profile, Rootset, Pattern}, From, #state{ fd = Fd } = S) -> + + set_pattern_trace(false, S#state.pattern), + set_process_trace(false, S#state.rootset), -handle_call({profile, Rootset, M, F, A}, FromTag, S) -> - io:format("eprof: Starting profiling..... ~n", []), - maybe_delete(S#state.table), - ptrac(S#state.rootset, false, all()), - flush_receive(), - put(replyto, FromTag), - Tab = ets:new(eprof, [set, public]), - P = spawn_link(eprof, call, [self(), M, F, A]), - case ptrac([P|Rootset], true, all()) of + case set_process_trace(true, Rootset) of true -> - uni_schedule(), - call_trace_for_all(true), - P ! {self(),go}, - {noreply, #state{table = Tab, - profiling = true, - rootset = [P|Rootset]}}; + T0 = now(), + set_pattern_trace(true, Pattern), + {reply, profiling, #state{ + profiling = true, + rootset = Rootset, + start_ts = T0, + reply = From, + fd = Fd, + pattern = Pattern + }}; false -> - exit(P, kill), - erase(replyto), - {reply, error, #state{}} + {reply, error, #state{ fd = Fd }} end; -handle_call(dump, _FromTag, S) -> - {reply, dump(S#state.table), S}; - -handle_call(analyse, _FromTag, S) -> - {reply, analyse(S), S}; +handle_call(stop_profiling, _From, #state{ profiling = false } = S) -> + {reply, profiling_already_stopped, S}; -handle_call(total_analyse, _FromTag, S) -> - {reply, total_analyse(S), S}; +handle_call(stop_profiling, _From, #state{ profiling = true } = S) -> -handle_call(stop, _FromTag, S) -> - multi_schedule(), - {stop, normal, stopped, S}. + set_pattern_trace(pause, S#state.pattern), -%%%%%%%%%%%%%%%%%%% + Bpd = collect_bpd(), -handle_info({trace_ts,_From,_Op,_Func,_Time}=M, S0) when S0#state.profiling -> - Start = erlang:now(), - #state{table=Tab,pop=PrevOp0,ptime=PrevTime0,pfunc=PrevFunc0, - overhead=Overhead0} = S0, - {PrevFunc,PrevOp,PrevTime} = do_messages(M, Tab, PrevFunc0, PrevOp0, PrevTime0), - Overhead = Overhead0 + subtr(erlang:now(), Start), - S = S0#state{overhead=Overhead,pfunc=PrevFunc,pop=PrevOp,ptime=PrevTime}, - {noreply,S}; + set_process_trace(false, S#state.rootset), + set_pattern_trace(false, S#state.pattern), -handle_info({trace_ts, From, _, _, _}, S) when not S#state.profiling -> - ptrac([From], false, all()), - {noreply, S}; + {reply, profiling_stopped, S#state{ + profiling = false, + rootset = [], + pattern = {'_','_','_'}, + bpd = Bpd + }}; -handle_info({_P, {answer, A}}, S) -> - ptrac(S#state.rootset, false, all()), - io:format("eprof: Stop profiling~n",[]), - {From,_Tag} = get(replyto), - catch unlink(From), - ets:delete(S#state.table, nofunc), - gen_server:reply(erase(replyto), {ok, A}), - multi_schedule(), - {noreply, S#state{profiling = false, - rootset = []}}; - -handle_info({'EXIT', P, Reason}, - #state{profiling=true,proc=P,table=T,rootset=RootSet}) -> - maybe_delete(T), - ptrac(RootSet, false, all()), - multi_schedule(), - io:format("eprof: Profiling failed\n",[]), - case erase(replyto) of - undefined -> - {noreply, #state{}}; - FromTag -> - gen_server:reply(FromTag, {error, Reason}), - {noreply, #state{}} +%% logfile +handle_call({logfile, File}, _From, #state{ fd = OldFd } = S) -> + case file:open(File, [write]) of + {ok, Fd} -> + case OldFd of + undefined -> ok; + OldFd -> file:close(OldFd) + end, + {reply, ok, S#state{ fd = Fd}}; + Error -> + {reply, Error, S} end; -handle_info({'EXIT',_P,_Reason}, S) -> - {noreply, S}. +handle_call(dump, _From, #state{ bpd = Bpd } = S) when is_record(Bpd, bpd) -> + {reply, gb_trees:to_list(Bpd#bpd.p), S}; -uni_schedule() -> - erlang:system_flag(multi_scheduling, block). +handle_call(stop, _FromTag, S) -> + {stop, normal, stopped, S}. -multi_schedule() -> - erlang:system_flag(multi_scheduling, unblock). +%% -------------------------------------------------------------------- %% +%% +%% handle_cast +%% +%% -------------------------------------------------------------------- %% -%%%%%%%%%%%%%%%%%% +handle_cast(_Msg, State) -> + {noreply, State}. -call(Top, M, F, A) -> - receive - {Top,go} -> - Top ! {self(), {answer, apply(M,F,A)}} - end. +%% -------------------------------------------------------------------- %% +%% +%% handle_info +%% +%% -------------------------------------------------------------------- %% -call_trace_for_all(Flag) -> - erlang:trace_pattern(on_load, Flag, [local]), - erlang:trace_pattern({'_','_','_'}, Flag, [local]). +handle_info({'EXIT', _, normal}, S) -> + {noreply, S}; +handle_info({'EXIT', _, eprof_kill}, S) -> + {noreply, S}; +handle_info({'EXIT', _, Reason}, #state{ reply = FromTag } = S) -> -ptrac([P|T], How, Flags) when is_pid(P) -> - case dotrace(P, How, Flags) of - true -> - ptrac(T, How, Flags); - false when How -> - false; - false -> - ptrac(T, How, Flags) - end; + set_process_trace(false, S#state.rootset), + set_pattern_trace(false, S#state.pattern), -ptrac([P|T], How, Flags) when is_atom(P) -> - case whereis(P) of - undefined when How -> - false; - undefined when not How -> - ptrac(T, How, Flags); - Pid -> - ptrac([Pid|T], How, Flags) - end; + gen_server:reply(FromTag, {error, Reason}), + {noreply, S#state{ + profiling = false, + rootset = [], + pattern = {'_','_','_'} + }}; -ptrac([H|_],_How,_Flags) -> - io:format("** eprof bad process ~w~n",[H]), - false; +% check if Pid is spawned process? +handle_info({_Pid, {answer, Result}}, #state{ reply = {From,_} = FromTag} = S) -> -ptrac([],_,_) -> true. + set_pattern_trace(pause, S#state.pattern), -dotrace(P, How, What) -> - case (catch erlang:trace(P, How, What)) of - 1 -> - true; - _Other when not How -> - true; - _Other -> - io:format("** eprof: bad process: ~p,~p,~p~n", [P,How,What]), - false - end. + Bpd = collect_bpd(), -all() -> [call,arity,return_to,running,timestamp,set_on_spawn]. - -total_analyse(#state{table=notable}) -> - nothing_to_analyse; -total_analyse(S) -> - #state{table = T, overhead = Overhead} = S, - QH = qlc:q([{{From,Mfa},Time,Count} || - {[From|Mfa],Time,Count} <- ets:table(T)]), - Pcalls = reverse(keysort(2, replicas(qlc:eval(QH)))), - Time = collect_times(Pcalls), - format("FUNCTION~44s TIME ~n", ["CALLS"]), - printit(Pcalls, Time), - format("\nTotal time: ~.2f\n", [Time / 1000000]), - format("Measurement overhead: ~.2f\n", [Overhead / 1000000]). - -analyse(#state{table=notable}) -> - nothing_to_analyse; -analyse(S) -> - #state{table = T, overhead = Overhead} = S, - Pids = ordsets:from_list(flatten(ets:match(T, {['$1'|'_'],'_', '_'}))), - Times = sum(ets:match(T, {'_','$1', '_'})), - format("FUNCTION~44s TIME ~n", ["CALLS"]), - do_pids(Pids, T, 0, Times), - format("\nTotal time: ~.2f\n", [Times / 1000000]), - format("Measurement overhead: ~.2f\n", [Overhead / 1000000]). - -do_pids([Pid|Tail], T, AckTime, Total) -> - Pcalls = - reverse(keysort(2, to_tups(ets:match(T, {[Pid|'$1'], '$2','$3'})))), - Time = collect_times(Pcalls), - PercentTotal = 100 * (divide(Time, Total)), - format("~n****** Process ~w -- ~s % of profiled time *** ~n", - [Pid, fpf(PercentTotal)]), - printit(Pcalls, Time), - do_pids(Tail, T, AckTime + Time, Total); -do_pids([], _, _, _) -> - ok. + set_process_trace(false, S#state.rootset), + set_pattern_trace(false, S#state.pattern), -printit([],_) -> ok; -printit([{{Mod,Fun,Arity}, Time, Calls} |Tail], ProcTime) -> - format("~s ~s ~s % ~n", [ff(Mod,Fun,Arity), fint(Calls), - fpf(100*(divide(Time,ProcTime)))]), - printit(Tail, ProcTime); -printit([{{_,{Mod,Fun,Arity}}, Time, Calls} |Tail], ProcTime) -> - format("~s ~s ~s % ~n", [ff(Mod,Fun,Arity), fint(Calls), - fpf(100*(divide(Time,ProcTime)))]), - printit(Tail, ProcTime); -printit([_|T], Time) -> - printit(T, Time). - -ff(Mod,Fun,Arity) -> - pad(flatten(io_lib:format("~w:~w/~w", [Mod,Fun, Arity])),45). - -pad(Str, Len) -> - Strlen = length(Str), - if - Strlen > Len -> strip_tail(Str, 45); - true -> lists:append(Str, mklist(Len-Strlen)) - end. + catch unlink(From), + gen_server:reply(FromTag, {ok, Result}), + {noreply, S#state{ + profiling = false, + rootset = [], + pattern = {'_','_','_'}, + bpd = Bpd + }}. + +%% -------------------------------------------------------------------- %% +%% +%% termination +%% +%% -------------------------------------------------------------------- %% + +terminate(_Reason, #state{ fd = undefined }) -> + set_pattern_trace(false, {'_','_','_'}), + ok; +terminate(_Reason, #state{ fd = Fd }) -> + file:close(Fd), + set_pattern_trace(false, {'_','_','_'}), + ok. -strip_tail([_|_], 0) ->[]; -strip_tail([H|T], I) -> [H|strip_tail(T, I-1)]; -strip_tail([],_I) -> []. +%% -------------------------------------------------------------------- %% +%% +%% code_change +%% +%% -------------------------------------------------------------------- %% -fpf(F) -> strip_tail(flatten(io_lib:format("~w", [round(F)])), 5). -fint(Int) -> pad(flatten(io_lib:format("~w",[Int])), 10). +code_change(_OldVsn, State, _Extra) -> + {ok, State}. -mklist(0) -> []; -mklist(I) -> [$ |mklist(I-1)]. -to_tups(L) -> lists:map(fun(List) -> erlang:list_to_tuple(List) end, L). +%% -------------------------------------------------------------------- %% +%% +%% AUX Functions +%% +%% -------------------------------------------------------------------- %% -divide(X,Y) -> X / Y. +setup_profiling(M,F,A) -> + spawn_link(fun() -> spin_profile(M,F,A) end). -collect_times([]) -> 0; -collect_times([Tup|Tail]) -> element(2, Tup) + collect_times(Tail). +spin_profile(M, F, A) -> + receive + {Pid, execute} -> + Pid ! {self(), {answer, erlang:apply(M,F,A)}} + end. -dump(T) -> - L = ets:tab2list(T), - format(L). +execute_profiling(Pid) -> + Pid ! {self(), execute}. -format([H|T]) -> - format("~p~n", [H]), format(T); -format([]) -> ok. +set_pattern_trace(Flag, Pattern) -> + erlang:system_flag(multi_scheduling, block), + erlang:trace_pattern(on_load, Flag, [call_time]), + erlang:trace_pattern(Pattern, Flag, [call_time]), + erlang:system_flag(multi_scheduling, unblock), + ok. -format(F, A) -> - io:format(F,A), - case get(fd) of - undefined -> ok; - Fd -> io:format(Fd, F,A) +set_process_trace(Flag, Pids) -> + % do we need procs for meta info? + % could be useful + set_process_trace(Flag, Pids, [call, set_on_spawn]). +set_process_trace(_, [], _) -> true; +set_process_trace(Flag, [Pid|Pids], Options) when is_pid(Pid) -> + try + erlang:trace(Pid, Flag, Options), + set_process_trace(Flag, Pids, Options) + catch + _:_ -> + false + end; +set_process_trace(Flag, [Name|Pids], Options) when is_atom(Name) -> + case whereis(Name) of + undefined -> + set_process_trace(Flag, Pids, Options); + Pid -> + set_process_trace(Flag, [Pid|Pids], Options) end. -maybe_delete(T) -> - catch ets:delete(T). - -sum([[H]|T]) -> H + sum(T); -sum([]) -> 0. +collect_bpd() -> + collect_bpd([M || M <- [element(1, Mi) || Mi <- code:all_loaded()], M =/= ?MODULE]). + +collect_bpd(Ms) when is_list(Ms) -> + collect_bpdf(collect_mfas(Ms) ++ erlang:system_info(snifs)). + +collect_mfas(Ms) -> + lists:foldl(fun + (M, Mfas) -> + Mfas ++ [{M, F, A} || {F, A} <- M:module_info(functions)] + end, [], Ms). + +collect_bpdf(Mfas) -> + collect_bpdf(Mfas, #bpd{}). +collect_bpdf([], Bpd) -> + Bpd; +collect_bpdf([Mfa|Mfas], #bpd{n = N, us = Us, p = Tree, mfa = Code } = Bpd) -> + case erlang:trace_info(Mfa, call_time) of + {call_time, []} -> + collect_bpdf(Mfas, Bpd); + {call_time, Data} when is_list(Data) -> + {CTn, CTus, CTree} = collect_bpdfp(Mfa, Tree, Data), + collect_bpdf(Mfas, Bpd#bpd{ + n = CTn + N, + us = CTus + Us, + p = CTree, + mfa = [{Mfa, {CTn, CTus}}|Code] + }); + {call_time, false} -> + collect_bpdf(Mfas, Bpd); + {call_time, _Other} -> + collect_bpdf(Mfas, Bpd) + end. -replicas(L) -> - replicas(L, []). +collect_bpdfp(Mfa, Tree, Data) -> + lists:foldl(fun + ({Pid, Ni, Si, Usi}, {PTno, PTuso, To}) -> + Time = Si * 1000000 + Usi, + Ti1 = case gb_trees:lookup(Pid, To) of + none -> + gb_trees:enter(Pid, [{Mfa, {Ni, Time}}], To); + {value, Pmfas} -> + gb_trees:enter(Pid, [{Mfa, {Ni, Time}}|Pmfas], To) + end, + {PTno + Ni, PTuso + Time, Ti1} + end, {0,0, Tree}, Data). + +%% manipulators +sort_mfa(Bpfs, mfa) when is_list(Bpfs) -> + lists:sort(fun + ({A,_}, {B,_}) when A < B -> true; + (_, _) -> false + end, Bpfs); +sort_mfa(Bpfs, time) when is_list(Bpfs) -> + lists:sort(fun + ({_,{A,_}}, {_,{B,_}}) when A < B -> true; + (_, _) -> false + end, Bpfs); +sort_mfa(Bpfs, calls) when is_list(Bpfs) -> + lists:sort(fun + ({_,{_,A}}, {_,{_,B}}) when A < B -> true; + (_, _) -> false + end, Bpfs); +sort_mfa(Bpfs, _) when is_list(Bpfs) -> sort_mfa(Bpfs, calls). + +filter_mfa(Bpfs, Ts) when is_list(Ts) -> + filter_mfa(Bpfs, [], proplists:get_value(calls, Ts, 0), proplists:get_value(time, Ts, 0)); +filter_mfa(Bpfs, _) -> Bpfs. +filter_mfa([], Out, _, _) -> lists:reverse(Out); +filter_mfa([{_, {C, T}}=Bpf|Bpfs], Out, Ct, Tt) when C >= Ct, T >= Tt -> filter_mfa(Bpfs, [Bpf|Out], Ct, Tt); +filter_mfa([_|Bpfs], Out, Ct, Tt) -> filter_mfa(Bpfs, Out, Ct, Tt). + +sum_bp_total_n_us(Mfas) -> + lists:foldl(fun ({_, {Ci,Usi}}, {Co, Uso}) -> {Co + Ci, Uso + Usi} end, {0,0}, Mfas). + +%% strings and format + +string_bp_mfa(Mfas, Tus) -> string_bp_mfa(Mfas, Tus, {0,0,0,0,0}, []). +string_bp_mfa([], _, Ws, Strings) -> {Ws, lists:reverse(Strings)}; +string_bp_mfa([{Mfa, {Count, Time}}|Mfas], Tus, {MfaW, CountW, PercW, TimeW, TpCW}, Strings) -> + Smfa = s(Mfa), + Scount = s(Count), + Stime = s(Time), + Sperc = s("~.2f", [100*(Time/Tus)]), + Stpc = s("~.2f", [Time/Count]), + + string_bp_mfa(Mfas, Tus, { + erlang:max(MfaW, length(Smfa)), + erlang:max(CountW,length(Scount)), + erlang:max(PercW, length(Sperc)), + erlang:max(TimeW, length(Stime)), + erlang:max(TpCW, length(Stpc)) + }, [[Smfa, Scount, Sperc, Stime, Stpc] | Strings]). + +print_bp_mfa(Mfas, {_Tn, Tus}, Fd, Opts) -> + Fmfas = filter_mfa(sort_mfa(Mfas, proplists:get_value(sort, Opts)), proplists:get_value(filter, Opts)), + {{MfaW, CountW, PercW, TimeW, TpCW}, Strs} = string_bp_mfa(Fmfas, Tus), + Ws = { + erlang:max(length("FUNCTION"), MfaW), + erlang:max(length("CALLS"), CountW), + erlang:max(length(" %"), PercW), + erlang:max(length("TIME"), TimeW), + erlang:max(length("uS / CALLS"), TpCW) + }, + format(Fd, Ws, ["FUNCTION", "CALLS", " %", "TIME", "uS / CALLS"]), + format(Fd, Ws, ["--------", "-----", "---", "----", "----------"]), + + lists:foreach(fun (String) -> format(Fd, Ws, String) end, Strs), + ok. -replicas([{{Pid, {Mod,Fun,Arity}}, Ack,Calls} |Tail], Result) -> - case search({Mod,Fun,Arity},Result) of - false -> - replicas(Tail, [{{Pid, {Mod,Fun,Arity}}, Ack,Calls} |Result]); - {Ack2, Calls2} -> - Result2 = del({Mod,Fun,Arity}, Result), - replicas(Tail, [{{Pid, {Mod,Fun,Arity}}, - Ack+Ack2,Calls+Calls2} |Result2]) - end; +s({M,F,A}) -> s("~w:~w/~w",[M,F,A]); +s(Term) -> s("~p", [Term]). +s(Format, Terms) -> lists:flatten(io_lib:format(Format, Terms)). -replicas([_|T], Ack) -> %% Whimpy - replicas(T, Ack); - -replicas([], Res) -> Res. - -search(Key, [{{_,Key}, Ack, Calls}|_]) -> - {Ack, Calls}; -search(Key, [_|T]) -> - search(Key, T); -search(_Key,[]) -> false. - -del(Key, [{{_,Key},_Ack,_Calls}|T]) -> - T; -del(Key, [H | Tail]) -> - [H|del(Key, Tail)]; -del(_Key,[]) -> []. - -flush_receive() -> - receive - {trace_ts, From, _, _, _} when is_pid(From) -> - ptrac([From], false, all()), - flush_receive(); - _ -> - flush_receive() - after 0 -> - ok - end. -code_change(_OldVsn, State, _Extra) -> - {ok,State}. +format(Fd, {MfaW, CountW, PercW, TimeW, TpCW}, Strings) -> + format(Fd, s("~~.~ps ~~~ps ~~~ps ~~~ps [~~~ps]~~n", [MfaW, CountW, PercW, TimeW, TpCW]), Strings); +format(undefined, Format, Strings) -> + io:format(Format, Strings), + ok; +format(Fd, Format, Strings) -> + io:format(Fd, Format, Strings), + io:format(Format, Strings), + ok. diff --git a/lib/tools/test/eprof_SUITE.erl b/lib/tools/test/eprof_SUITE.erl index 028fea8fe1..67607c6cf2 100644 --- a/lib/tools/test/eprof_SUITE.erl +++ b/lib/tools/test/eprof_SUITE.erl @@ -20,10 +20,89 @@ -include("test_server.hrl"). --export([all/1,tiny/1,eed/1]). +-export([all/1,tiny/1,eed/1,basic/1]). -all(suite) -> [tiny,eed]. +all(suite) -> [basic,tiny,eed]. +basic(suite) -> []; +basic(Config) when is_list(Config) -> + + %% load eprof_test and change directory + + ?line {ok, OldCurDir} = file:get_cwd(), + Datadir = ?config(data_dir, Config), + Privdir = ?config(priv_dir, Config), + ?line {ok,eprof_test} = compile:file(filename:join(Datadir, "eprof_test"), + [trace,{outdir, Privdir}]), + ?line ok = file:set_cwd(Privdir), + ?line code:purge(eprof_test), + ?line {module,eprof_test} = code:load_file(eprof_test), + + %% rootset profiling + + ?line ensure_eprof_stopped(), + ?line profiling = eprof:profile([self()]), + ?line {error, already_profiling} = eprof:profile([self()]), + ?line profiling_stopped = eprof:stop_profiling(), + ?line profiling_already_stopped = eprof:stop_profiling(), + ?line profiling = eprof:start_profiling([self(),self(),self()]), + ?line profiling_stopped = eprof:stop_profiling(), + + %% with patterns + + ?line profiling = eprof:start_profiling([self()], {?MODULE, '_', '_'}), + ?line {error, already_profiling} = eprof:start_profiling([self()], {?MODULE, '_', '_'}), + ?line profiling_stopped = eprof:stop_profiling(), + ?line profiling = eprof:start_profiling([self()], {?MODULE, start_stop, '_'}), + ?line profiling_stopped = eprof:stop_profiling(), + ?line profiling = eprof:start_profiling([self()], {?MODULE, start_stop, 1}), + ?line profiling_stopped = eprof:stop_profiling(), + + %% with fun + + ?line {ok, _} = eprof:profile(fun() -> eprof_test:go(10) end), + ?line profiling = eprof:profile([self()]), + ?line {error, already_profiling} = eprof:profile(fun() -> eprof_test:go(10) end), + ?line profiling_stopped = eprof:stop_profiling(), + ?line {ok, _} = eprof:profile(fun() -> eprof_test:go(10) end), + ?line {ok, _} = eprof:profile([], fun() -> eprof_test:go(10) end), + ?line Pid = whereis(eprof), + ?line {ok, _} = eprof:profile(erlang:processes() -- [Pid], fun() -> eprof_test:go(10) end), + ?line {ok, _} = eprof:profile([], fun() -> eprof_test:go(10) end, {eprof_test, '_', '_'}), + ?line {ok, _} = eprof:profile([], fun() -> eprof_test:go(10) end, {eprof_test, go, '_'}), + ?line {ok, _} = eprof:profile([], fun() -> eprof_test:go(10) end, {eprof_test, go, 1}), + ?line {ok, _} = eprof:profile([], fun() -> eprof_test:go(10) end, {eprof_test, dec, 1}), + + %% error case + + ?line error = eprof:profile([Pid], fun() -> eprof_test:go(10) end), + ?line Pid = whereis(eprof), + ?line error = eprof:profile([Pid], fun() -> eprof_test:go(10) end), + ?line A = spawn(fun() -> receive _ -> ok end end), + ?line profiling = eprof:profile([A]), + ?line true = exit(A, kill_it), + ?line profiling_stopped = eprof:stop_profiling(), + ?line {error,_} = eprof:profile(fun() -> a = b end), + + %% with mfa + + ?line {ok, _} = eprof:profile([], eprof_test, go, [10]), + ?line {ok, _} = eprof:profile([], eprof_test, go, [10], {eprof_test, dec, 1}), + + %% dump + + ?line {ok, _} = eprof:profile([], fun() -> eprof_test:go(10) end, {eprof_test, '_', '_'}), + ?line [{_, Mfas}] = eprof:dump(), + ?line Dec_mfa = {eprof_test, dec, 1}, + ?line Go_mfa = {eprof_test, go, 1}, + ?line {value, {Go_mfa, { 1, _Time1}}} = lists:keysearch(Go_mfa, 1, Mfas), + ?line {value, {Dec_mfa, {11, _Time2}}} = lists:keysearch(Dec_mfa, 1, Mfas), + + %% change current working directory + + ?line ok = file:set_cwd(OldCurDir), + ?line stopped = eprof:stop(), + ok. tiny(suite) -> []; tiny(Config) when is_list(Config) -> @@ -40,11 +119,11 @@ tiny(Config) when is_list(Config) -> ?line code:purge(eprof_suite_test), ?line {module,eprof_suite_test} = code:load_file(eprof_suite_test), ?line {ok,_Pid} = eprof:start(), - ?line nothing_to_analyse = eprof:analyse(), - ?line nothing_to_analyse = eprof:total_analyse(), + ?line nothing_to_analyze = eprof:analyze(), + ?line nothing_to_analyze = eprof:analyze(total), ?line eprof:profile([], eprof_suite_test, test, [Config]), - ?line ok = eprof:analyse(), - ?line ok = eprof:total_analyse(), + ?line ok = eprof:analyze(), + ?line ok = eprof:analyze(total), ?line ok = eprof:log("eprof_SUITE_logfile"), ?line stopped = eprof:stop(), ?line ?t:timetrap_cancel(TTrap), @@ -79,8 +158,8 @@ eed(Config) when is_list(Config) -> ?line {ok,ok} = eprof:profile([], eed, file, [Script]), ?line {T3,_} = statistics(runtime), ?line profiling_already_stopped = eprof:stop_profiling(), - ?line ok = eprof:analyse(), - ?line ok = eprof:total_analyse(), + ?line ok = eprof:analyze(), + ?line ok = eprof:analyze(total), ?line ok = eprof:log("eprof_SUITE_logfile"), ?line stopped = eprof:stop(), ?line ?t:timetrap_cancel(TTrap), diff --git a/lib/tools/test/eprof_SUITE_data/eprof_test.erl b/lib/tools/test/eprof_SUITE_data/eprof_test.erl new file mode 100644 index 0000000000..33c428e893 --- /dev/null +++ b/lib/tools/test/eprof_SUITE_data/eprof_test.erl @@ -0,0 +1,9 @@ +-module(eprof_test). +-export([go/1]). + +go(N) -> + 0 = dec(N), + ok. + +dec(0) -> 0; +dec(N) -> dec(N - 1). diff --git a/lib/tools/test/fprof_SUITE.erl b/lib/tools/test/fprof_SUITE.erl index e437007e76..1cd9ac7824 100644 --- a/lib/tools/test/fprof_SUITE.erl +++ b/lib/tools/test/fprof_SUITE.erl @@ -356,7 +356,7 @@ imm_tail_seq(Config) when is_list(Config) -> ?line profiling_stopped = eprof:stop_profiling(), ?line R2 = R0, %% - ?line eprof:analyse(), + ?line eprof:analyze(), ?line stopped = eprof:stop(), %% ?line {ok, Tracer} = fprof:profile(start), @@ -471,7 +471,7 @@ imm_compile(Config) when is_list(Config) -> ?line TS3 = erlang:now(), ?line profiling_stopped = eprof:stop_profiling(), %% - ?line eprof:analyse(), + ?line eprof:analyze(), ?line stopped = eprof:stop(), %% ?line {ok, Tracer} = fprof:profile(start), |