Add better timing labels

4 files changed, 36 insertions, 24 deletions

diff --git a/lib/dialyzer/src/dialyzer.hrl b/lib/dialyzer/src/dialyzer.hrl
index e2edd3f0af..f282bbf73c 100644
--- a/lib/dialyzer/src/dialyzer.hrl
+++ b/lib/dialyzer/src/dialyzer.hrl
@@ -155,10 +155,11 @@
 
 %%--------------------------------------------------------------------
 
--define(timing(Msg,Expr),
+-define(timing(Msg,Var,Expr),
 	begin
 	    dialyzer_timing:start_stamp(Msg),
-	    __T = Expr,
+	    Var = Expr,
 	    dialyzer_timing:end_stamp(),
-	    __T
+	    Var
 	end).
+-define(timing(Msg,Expr),?timing(Msg,_T,Expr)).
diff --git a/lib/dialyzer/src/dialyzer_analysis_callgraph.erl b/lib/dialyzer/src/dialyzer_analysis_callgraph.erl
index 30eb087fcf..02108d6e38 100644
--- a/lib/dialyzer/src/dialyzer_analysis_callgraph.erl
+++ b/lib/dialyzer/src/dialyzer_analysis_callgraph.erl
@@ -134,8 +134,7 @@ analysis_start(Parent, Analysis) ->
 			  use_contracts = Analysis#analysis.use_contracts
 			 },
   Files = ordsets:from_list(Analysis#analysis.files),
-  {Callgraph, NoWarn, TmpCServer0} =
-    ?timing("compile",compile_and_store(Files, State)),
+  {Callgraph, NoWarn, TmpCServer0} = compile_and_store(Files, State),
   %% Remote type postprocessing
   NewCServer =
     try
@@ -156,7 +155,8 @@ analysis_start(Parent, Analysis) ->
         dialyzer_codeserver:insert_temp_exported_types(MergedExpTypes,
                                                        TmpCServer1),
       TmpCServer3 = dialyzer_utils:process_record_remote_types(TmpCServer2),
-      dialyzer_contracts:process_contract_remote_types(TmpCServer3)
+      ?timing("remote",
+	      dialyzer_contracts:process_contract_remote_types(TmpCServer3))
     catch
       throw:{error, _ErrorMsg} = Error -> exit(Error)
     end,
@@ -228,9 +228,10 @@ compile_and_store(Files, #analysis_state{codeserver = CServer,
   lists:foreach(Spawner, Files),
   dialyzer_coordinator:all_spawned(Coordinator),
   {{V, E, Failed, NoWarn, Modules}, NextLabel} =
-    dialyzer_coordinator:receive_compilation_data(),
+    ?timing("compile", _C1, dialyzer_coordinator:receive_compilation_data()),
   CServer2 = dialyzer_codeserver:set_next_core_label(NextLabel, CServer),
-  Callgraph = dialyzer_callgraph:add_edges(E, V, Callgraph),
+  Callgraph =
+    ?timing("digraph", _C2, dialyzer_callgraph:add_edges(E, V, Callgraph)),
   case Failed =:= [] of
     true ->
       NewFiles = lists:zip(lists:reverse(Modules), Files),
@@ -246,7 +247,9 @@ compile_and_store(Files, #analysis_state{codeserver = CServer,
   {T2, _} = statistics(runtime),
   Msg1 = io_lib:format("done in ~.2f secs\nRemoving edges... ", [(T2-T1)/1000]),
   send_log(Parent, Msg1),
-  Callgraph = cleanup_callgraph(State, CServer2, Callgraph, Modules),
+  Callgraph =
+    ?timing("clean", _C3,
+	    cleanup_callgraph(State, CServer2, Callgraph, Modules)),
   {T3, _} = statistics(runtime),
   Msg2 = io_lib:format("done in ~.2f secs\n", [(T3-T2)/1000]),
   send_log(Parent, Msg2),
diff --git a/lib/dialyzer/src/dialyzer_succ_typings.erl b/lib/dialyzer/src/dialyzer_succ_typings.erl
index fbd333f905..c1c437f9a4 100644
--- a/lib/dialyzer/src/dialyzer_succ_typings.erl
+++ b/lib/dialyzer/src/dialyzer_succ_typings.erl
@@ -90,7 +90,8 @@ analyze_callgraph(Callgraph, Plt, Codeserver, Parent) ->
 %%--------------------------------------------------------------------
 
 init_state_and_get_success_typings(Callgraph, Plt, Codeserver, Parent) ->
-  {SCCs, Callgraph1} = dialyzer_callgraph:finalize(Callgraph),
+  {SCCs, Callgraph1} =
+    ?timing("order", dialyzer_callgraph:finalize(Callgraph)),
   State = #st{callgraph = Callgraph1, plt = dialyzer_plt:get_mini_plt(Plt),
 	      codeserver = Codeserver, parent = Parent},
   get_refined_success_typings(SCCs, State).
@@ -102,7 +103,10 @@ get_refined_success_typings(SCCs, State) ->
       Callgraph = State1#st.callgraph,
       NotFixpoint2 = [lookup_name(F, Callgraph) || F <- NotFixpoint1],
       {ModulePostorder, ModCallgraph} =
-	dialyzer_callgraph:module_postorder_from_funs(NotFixpoint2, Callgraph),
+	?timing(
+	   "order", _C1,
+	   dialyzer_callgraph:module_postorder_from_funs(NotFixpoint2,
+							 Callgraph)),
       ModState = State1#st{callgraph = ModCallgraph},
       case refine_succ_typings(ModulePostorder, ModState) of
 	{fixpoint, State2} ->
@@ -112,7 +116,9 @@ get_refined_success_typings(SCCs, State) ->
 	  %% Need to reset the callgraph.
 	  NotFixpoint4 = [lookup_name(F, Callgraph1) || F <- NotFixpoint3],
 	  {NewSCCs, Callgraph2} =
-	    dialyzer_callgraph:reset_from_funs(NotFixpoint4, Callgraph1),
+	    ?timing("order", _C2,
+		    dialyzer_callgraph:reset_from_funs(NotFixpoint4,
+						       Callgraph1)),
 	  NewState = State2#st{callgraph = Callgraph2},
 	  get_refined_success_typings(NewSCCs, NewState)
       end
@@ -325,7 +331,15 @@ find_succ_typings(SCCs, #st{codeserver = Codeserver, callgraph = Callgraph,
 			    plt = Plt} = State) ->
   Servers = {Codeserver, dialyzer_callgraph:mini_callgraph(Callgraph), Plt},
   Coordinator = dialyzer_coordinator:start(typesig, Servers),
-  ?timing("typesig", find_succ_typings(SCCs, State, Coordinator)).
+  ?timing("spawn", _C1, find_succ_typings(SCCs, State, Coordinator)),
+  dialyzer_coordinator:all_spawned(Coordinator),
+  NotFixpoint =
+    ?timing("typesig", _C2, dialyzer_coordinator:receive_not_fixpoint()),
+  ?debug("==================== Typesig done ====================\n\n", []),
+  case NotFixpoint =:= [] of
+    true -> {fixpoint, State};
+    false -> {not_fixpoint, NotFixpoint, State}
+  end.
 
 find_succ_typings([SCC|Rest], #st{parent = Parent} = State, Coordinator) ->
   Msg = io_lib:format("Typesig analysis for SCC: ~w\n", [format_scc(SCC)]),
@@ -333,14 +347,8 @@ find_succ_typings([SCC|Rest], #st{parent = Parent} = State, Coordinator) ->
   send_log(Parent, Msg),
   dialyzer_coordinator:scc_spawn(SCC, Coordinator),
   find_succ_typings(Rest, State, Coordinator);
-find_succ_typings([], State, Coordinator) ->
-  dialyzer_coordinator:all_spawned(Coordinator),
-  NotFixpoint = dialyzer_coordinator:receive_not_fixpoint(),
-  ?debug("==================== Typesig done ====================\n\n", []),
-  case NotFixpoint =:= [] of
-    true -> {fixpoint, State};
-    false -> {not_fixpoint, NotFixpoint, State}
-  end.
+find_succ_typings([], _State, _Coordinator) ->
+  ok.
 
 -spec collect_scc_data(scc(), servers()) -> scc_data().
 
diff --git a/lib/dialyzer/src/dialyzer_timing.erl b/lib/dialyzer/src/dialyzer_timing.erl
index 73dbbf5a34..368c1715ce 100644
--- a/lib/dialyzer/src/dialyzer_timing.erl
+++ b/lib/dialyzer/src/dialyzer_timing.erl
@@ -56,13 +56,13 @@ dummy_loop() ->
 loop(LastNow) ->
   receive
     {stamp, Msg, Now} ->
-      io:format("~s\t(+~6.2fs): ", [Msg, diff(Now, LastNow)]),
+      io:format("    ~-10s (+~4.2fs):", [Msg, diff(Now, LastNow)]),
       loop(Now);
     {stamp, Now} ->
-      io:format("~6.2fs\n", [diff(Now, LastNow)]),
+      io:format("~7.2fs\n", [diff(Now, LastNow)]),
       loop(Now);
     {Pid, stop, Now} ->
-      io:format("\t(+~6.2fs)\n", [diff(Now, LastNow)]),
+      io:format("    ~-10s (+~4.2fs)\n", ["",diff(Now, LastNow)]),
       Pid ! ok
   end.