aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorBjörn-Egil Dahlberg <[email protected]>2016-04-26 15:28:48 +0200
committerBjörn-Egil Dahlberg <[email protected]>2016-04-26 18:03:15 +0200
commit4acfd18a0e934789f752fd48d3031e48cdd3fbde (patch)
treebebdf6e4a1c4cc2dff24dc0a7159fbaee313762f
parentb842026cc5e86cf7f054da073f6da16adf02baa9 (diff)
downloadotp-4acfd18a0e934789f752fd48d3031e48cdd3fbde.tar.gz
otp-4acfd18a0e934789f752fd48d3031e48cdd3fbde.tar.bz2
otp-4acfd18a0e934789f752fd48d3031e48cdd3fbde.zip
erts: Add profiling of startup
Usage: erl -profile_boot ...
-rw-r--r--erts/preloaded/src/init.erl76
1 files changed, 75 insertions, 1 deletions
diff --git a/erts/preloaded/src/init.erl b/erts/preloaded/src/init.erl
index 77684751c8..618b53f6bb 100644
--- a/erts/preloaded/src/init.erl
+++ b/erts/preloaded/src/init.erl
@@ -41,6 +41,7 @@
%% -s : Start own processes.
%%
%% Experimental flags:
+%% -profile_boot : Use an 'eprof light' to profile boot sequence
%% -init_debug : Activate debug printouts in init
%% -loader_debug : Activate debug printouts in erl_prim_loader
%% -code_path_choice : strict | relaxed
@@ -184,6 +185,11 @@ boot(BootArgs) ->
erl_tracer:on_load(),
{Start0,Flags,Args} = parse_boot_args(BootArgs),
+ %% We don't get to profile parsing of BootArgs
+ case get_flag(profile_boot, Flags, false) of
+ false -> ok;
+ true -> debug_profile_start()
+ end,
Start = map(fun prepare_run_args/1, Start0),
boot(Start, Flags, Args).
@@ -765,7 +771,14 @@ do_boot(Init,Flags,Start) ->
%% print the node name into the Purify log.
(catch erlang:system_info({purify, "Node: " ++ atom_to_list(node())})),
- start_em(Start).
+ start_em(Start),
+ case get_flag(profile_boot,Flags,false) of
+ false -> ok;
+ true ->
+ debug_profile_format_mfas(debug_profile_mfas()),
+ debug_profile_stop()
+ end,
+ ok.
get_root(Flags) ->
case get_argument(root, Flags) of
@@ -1339,3 +1352,64 @@ run_on_load_handlers([M|Ms], Debug) ->
end
end;
run_on_load_handlers([], _) -> ok.
+
+
+%% debug profile (light variant of eprof)
+debug_profile_start() ->
+ _ = erlang:trace_pattern({'_','_','_'},true,[call_time]),
+ _ = erlang:trace_pattern(on_load,true,[call_time]),
+ _ = erlang:trace(all,true,[call]),
+ ok.
+
+debug_profile_stop() ->
+ _ = erlang:trace_pattern({'_','_','_'},false,[call_time]),
+ _ = erlang:trace_pattern(on_load,false,[call_time]),
+ _ = erlang:trace(all,false,[call]),
+ ok.
+
+debug_profile_mfas() ->
+ _ = erlang:trace_pattern({'_','_','_'},pause,[call_time]),
+ _ = erlang:trace_pattern(on_load,pause,[call_time]),
+ MFAs = collect_loaded_mfas() ++ erlang:system_info(snifs),
+ collect_mfas(MFAs,[]).
+
+%% debug_profile_format_mfas should be called at the end of the boot phase
+%% so all pertinent modules should be loaded at that point.
+debug_profile_format_mfas(MFAs0) ->
+ MFAs = lists:sort(MFAs0),
+ lists:foreach(fun({{Us,C},{M,F,A}}) ->
+ Str = io_lib:format("~w:~w/~w", [M,F,A]),
+ io:format(standard_error,"~55s - ~6w : ~w us~n", [Str,C,Us])
+ end, MFAs),
+ ok.
+
+collect_loaded_mfas() ->
+ Ms = [M || M <- [element(1, Mi) || Mi <- code:all_loaded()]],
+ collect_loaded_mfas(Ms,[]).
+
+collect_loaded_mfas([],MFAs) -> MFAs;
+collect_loaded_mfas([M|Ms],MFAs0) ->
+ MFAs = [{M,F,A} || {F,A} <- M:module_info(functions)],
+ collect_loaded_mfas(Ms,MFAs ++ MFAs0).
+
+
+collect_mfas([], Info) -> Info;
+collect_mfas([MFA|MFAs],Info) ->
+ case erlang:trace_info(MFA,call_time) of
+ {call_time, []} ->
+ collect_mfas(MFAs,Info);
+ {call_time, false} ->
+ collect_mfas(MFAs,Info);
+ {call_time, Data} ->
+ case collect_mfa(MFA,Data,0,0) of
+ {{0,_},_} ->
+ %% ignore mfas with zero time
+ collect_mfas(MFAs,Info);
+ MfaData ->
+ collect_mfas(MFAs,[MfaData|Info])
+ end
+ end.
+
+collect_mfa(Mfa,[],Count,Time) -> {{Time,Count},Mfa};
+collect_mfa(Mfa,[{_Pid,C,S,Us}|Data],Count,Time) ->
+ collect_mfa(Mfa,Data,Count + C,Time + S * 1000000 + Us).