The intent of the phases was to have a high-level but mutually exclusive accounting of compile time.

The intent of the phases was to have a high-level but mutually exclusive
accounting of compile time.  We want to track compile time in a way that
tells us which conceptual phases are taking the most time.  That intent
is not currently satisfied.  This patch restores that intent.

Add code to verify that the sum of the phase times is less than the total
time, to detect when phases are overlapped.  A slight amount of leeway is
required due to time jitters.  This verification is done as the last step
in printing timevars so that any timevar information is not lost.

Rename the phases to be clearer about what they measure, so that they
are less likely to be modified to be overlapping.  The primary example
is to change TV_PHASE_GENERATE to TV_PHASE_LATE_ASM, meaning late work
on the assembly.  This name change avoids confusion n moving the timevar
start call after the call to lang_hooks.decls.final_write_globals, which
prevents overlapping phases.

Each implementation of lang_hooks.decls.final_write_globals, is responsible
for starting and stopping its own phases.  Each implementation currently has
a first phase of TV_PHASE_DEFERRED for front-end work deferred until after
parsing is complete.  The second phase has been renamed from TV_PHASE_CGRAPH
to TV_PHASE_OPT_GEN, to better reflect its use as the main optimization
and generation phase.  This phase accounts for 70%-80% of compilation time
during bootstrap.  The third phase is TV_PHASE_DBGINFO, except in cp/decl2.c,
where it is TV_PHASE_CHECK_DBGINFO because cc1plus mixes checking in with
debug info generation.  In langhooks.c, write_global_declarations was
using TV_PHASE_CHECK_DBGINFO, but it was doing no checking.  So, it now
uses TV_PHASE_DBGINFO.

The changes to LTO are significant.  First, initialization now uses
TV_PHASE_SETUP.  Reading files now uses TV_PHASE_STREAM_IN.  Writing files
now uses TV_PHASE_STREAM_OUT.  The remaining phase is TV_PHASE_OPT_GEN
(formerly TV_PHASE_CGRAPH).  Finally, because LTO is treated as a front
end, TV_PHASE_PARSING and TV_PARSE_GLOBAL active around it.  It is not
parsing, and so those timers should not be active.  Rather than make all
front ends manage them, we turn them off as the first thing in LTO and turn
them back on as the last thing.

Tested on x86_64.


Index: gcc/ChangeLog

2012-06-18  Lawrence Crowl  <crowl@google.com>

	* timevar.def (TV_PHASE_GENERATE): Rename to TV_PHASE_LATE_ASM.
	(TV_PHASE_CGRAPH): Rename to TV_PHASE_OPT_GEN.
	(TV_PHASE_STREAM_IN): New.
	(TV_PHASE_STREAM_OUT): New.
	* timevar.c (validate_phases): New.
	(timevar_print): Call validate_phases.
	* c-decl.c (c_write_global_declarations): Rename use of TV_PHASE_CGRAPH
	to TV_PHASE_OPT_GEN.
	* langhooks.c (write_global_declarations): Rename use of
	TV_PHASE_CGRAPH to TV_PHASE_OPT_GEN.  Use TV_PHASE_DBGINFO instead of
	TV_PHASE_CHECK_DBGINFO.
	* toplev.c (compile_file): Rename use of TV_PHASE_GENERATE to
	TV_PHASE_LATE_ASM.  Move start of TV_PHASE_LATE_ASM to after call to
	lang_hooks.decls.final_write_globals.

Index: gcc/cp/ChangeLog

2012-06-18  Lawrence Crowl  <crowl@google.com>

	* decl2.c (cp_write_global_declarations): Rename use of TV_PHASE_CGRAPH
	to TV_PHASE_OPT_GEN.

Index: gcc/lto/ChangeLog

2012-06-18  Lawrence Crowl  <crowl@google.com>

        * lto.c (do_whole_program_analysis):  Rename use of TV_PHASE_CGRAPH to
	TV_PHASE_OPT_GEN.  Use new timevar TV_PHASE_STREAM_OUT around the call
	to lto_wpa_write_files.
	(lto_main):  Rename use of TV_PHASE_CGRAPH to TV_PHASE_OPT_GEN.  Move
	start of TV_PHASE_OPT_GEN to include call to materialize_cgraph.  Use
	TV_PHASE_SETUP for the call to lto_init.  Use new timevar
	TV_PHASE_STREAM_IN around the call to read_cgraph_and_symbols.
	Turn TV_PHASE_PARSING off then back on again, because LTO is pretending
	to be a front end, but is not one.

From-SVN: r188765

10 files changed, 136 insertions, 22 deletions

diff --git a/gcc/ChangeLog b/gcc/ChangeLog
index 348185f..0055ebf 100644
--- a/gcc/ChangeLog
+++ b/gcc/ChangeLog
@@ -1,3 +1,20 @@
+2012-06-18  Lawrence Crowl  <crowl@google.com>
+
+	* timevar.def (TV_PHASE_GENERATE): Rename to TV_PHASE_LATE_ASM.
+	(TV_PHASE_CGRAPH): Rename to TV_PHASE_OPT_GEN.
+	(TV_PHASE_STREAM_IN): New.
+	(TV_PHASE_STREAM_OUT): New.
+	* timevar.c (validate_phases): New.
+	(timevar_print): Call validate_phases.
+	* c-decl.c (c_write_global_declarations): Rename use of TV_PHASE_CGRAPH
+	to TV_PHASE_OPT_GEN.
+	* langhooks.c (write_global_declarations): Rename use of
+	TV_PHASE_CGRAPH to TV_PHASE_OPT_GEN.  Use TV_PHASE_DBGINFO instead of
+	TV_PHASE_CHECK_DBGINFO.
+	* toplev.c (compile_file): Rename use of TV_PHASE_GENERATE to
+	TV_PHASE_LATE_ASM.  Move start of TV_PHASE_LATE_ASM to after call to
+	lang_hooks.decls.final_write_globals.
+
 2012-06-18  David Edelshn  <dje.gcc@gmail.com>
 
 	* config/rs6000/aix52.h (TARGET_EXTRA_BUILTINS): Define as 0.
diff --git a/gcc/c-decl.c b/gcc/c-decl.c
index 86add14..9622b12 100644
--- a/gcc/c-decl.c
+++ b/gcc/c-decl.c
@@ -10101,13 +10101,13 @@ c_write_global_declarations (void)
   c_write_global_declarations_1 (BLOCK_VARS (ext_block));
 
   timevar_stop (TV_PHASE_DEFERRED);
-  timevar_start (TV_PHASE_CGRAPH);
+  timevar_start (TV_PHASE_OPT_GEN);
 
   /* We're done parsing; proceed to optimize and emit assembly.
      FIXME: shouldn't be the front end's responsibility to call this.  */
   finalize_compilation_unit ();
 
-  timevar_stop (TV_PHASE_CGRAPH);
+  timevar_stop (TV_PHASE_OPT_GEN);
   timevar_start (TV_PHASE_DBGINFO);
 
   /* After cgraph has had a chance to emit everything that's going to
diff --git a/gcc/cp/ChangeLog b/gcc/cp/ChangeLog
index 590eadd..b450775 100644
--- a/gcc/cp/ChangeLog
+++ b/gcc/cp/ChangeLog
@@ -1,3 +1,8 @@
+2012-06-18  Lawrence Crowl  <crowl@google.com>
+
+	* decl2.c (cp_write_global_declarations): Rename use of TV_PHASE_CGRAPH
+	to TV_PHASE_OPT_GEN.
+
 2012-06-18  Steven Bosscher  <steven@gcc.gnu.org>
 
 	* decl.c (finish_function): Remove code conditional on VMS_TARGET.
diff --git a/gcc/cp/decl2.c b/gcc/cp/decl2.c
index 2e3c9a6..d8c7260 100644
--- a/gcc/cp/decl2.c
+++ b/gcc/cp/decl2.c
@@ -4019,11 +4019,11 @@ cp_write_global_declarations (void)
   candidates = collect_candidates_for_java_method_aliases ();
 
   timevar_stop (TV_PHASE_DEFERRED);
-  timevar_start (TV_PHASE_CGRAPH);
+  timevar_start (TV_PHASE_OPT_GEN);
 
   finalize_compilation_unit ();
 
-  timevar_stop (TV_PHASE_CGRAPH);
+  timevar_stop (TV_PHASE_OPT_GEN);
   timevar_start (TV_PHASE_CHECK_DBGINFO);
 
   /* Now, issue warnings about static, but not defined, functions,
diff --git a/gcc/langhooks.c b/gcc/langhooks.c
index 46c19c3..a34733f 100644
--- a/gcc/langhooks.c
+++ b/gcc/langhooks.c
@@ -317,15 +317,15 @@ write_global_declarations (void)
   check_global_declarations (vec, len);
   timevar_stop (TV_PHASE_DEFERRED);
 
-  timevar_start (TV_PHASE_CGRAPH);
+  timevar_start (TV_PHASE_OPT_GEN);
   /* This lang hook is dual-purposed, and also finalizes the
      compilation unit.  */
   finalize_compilation_unit ();
-  timevar_stop (TV_PHASE_CGRAPH);
+  timevar_stop (TV_PHASE_OPT_GEN);
 
-  timevar_start (TV_PHASE_CHECK_DBGINFO);
+  timevar_start (TV_PHASE_DBGINFO);
   emit_debug_global_declarations (vec, len);
-  timevar_stop (TV_PHASE_CHECK_DBGINFO);
+  timevar_stop (TV_PHASE_DBGINFO);
 
   /* Clean up.  */
   free (vec);
diff --git a/gcc/lto/ChangeLog b/gcc/lto/ChangeLog
index 06774d8..3f025dc 100644
--- a/gcc/lto/ChangeLog
+++ b/gcc/lto/ChangeLog
@@ -1,3 +1,15 @@
+2012-06-18  Lawrence Crowl  <crowl@google.com>
+
+        * lto.c (do_whole_program_analysis):  Rename use of TV_PHASE_CGRAPH to
+	TV_PHASE_OPT_GEN.  Use new timevar TV_PHASE_STREAM_OUT around the call
+	to lto_wpa_write_files.
+	(lto_main):  Rename use of TV_PHASE_CGRAPH to TV_PHASE_OPT_GEN.  Move
+	start of TV_PHASE_OPT_GEN to include call to materialize_cgraph.  Use
+	TV_PHASE_SETUP for the call to lto_init.  Use new timevar
+	TV_PHASE_STREAM_IN around the call to read_cgraph_and_symbols.
+	Turn TV_PHASE_PARSING off then back on again, because LTO is pretending
+	to be a front end, but is not one.
+
 2012-05-18  Jan Hubicka  <jh@suse.cz>
 
 	* lto.c (lto_materialize_constructors_and_inits): Remove.
diff --git a/gcc/lto/lto.c b/gcc/lto/lto.c
index b94c8a7..df5c3df 100644
--- a/gcc/lto/lto.c
+++ b/gcc/lto/lto.c
@@ -1935,7 +1935,8 @@ materialize_cgraph (void)
 static void
 do_whole_program_analysis (void)
 {
-  timevar_start (TV_PHASE_CGRAPH);
+  timevar_start (TV_PHASE_OPT_GEN);
+
   /* Note that since we are in WPA mode, materialize_cgraph will not
      actually read in all the function bodies.  It only materializes
      the decls and cgraph nodes so that analysis can be performed.  */
@@ -1979,23 +1980,27 @@ do_whole_program_analysis (void)
   else
     lto_balanced_map ();
 
+  timevar_stop (TV_PHASE_OPT_GEN);
+  timevar_start (TV_PHASE_STREAM_OUT);
+
   if (!quiet_flag)
     {
       fprintf (stderr, "\nStreaming out");
       fflush (stderr);
     }
   lto_wpa_write_files ();
-  ggc_collect ();
   if (!quiet_flag)
     fprintf (stderr, "\n");
 
+  timevar_stop (TV_PHASE_STREAM_OUT);
+
+  ggc_collect ();
   if (post_ipa_mem_report)
     {
       fprintf (stderr, "Memory consumption after IPA\n");
       dump_memory_report (false);
     }
 
-  timevar_stop (TV_PHASE_CGRAPH);
   /* Show the LTO report before launching LTRANS.  */
   if (flag_lto_report)
     print_lto_report ();
@@ -2075,13 +2080,28 @@ lto_init (void)
 void
 lto_main (void)
 {
+  /* LTO is called as a front end, even though it is not a front end.
+     Because it is called as a front end, TV_PHASE_PARSING and
+     TV_PARSE_GLOBAL are active, and we need to turn them off while
+     doing LTO.  Later we turn them back on so they are active up in
+     toplev.c.  */
+  timevar_pop (TV_PARSE_GLOBAL);
+  timevar_stop (TV_PHASE_PARSING);
+
+  timevar_start (TV_PHASE_SETUP);
+
   /* Initialize the LTO front end.  */
   lto_init ();
 
+  timevar_stop (TV_PHASE_SETUP);
+  timevar_start (TV_PHASE_STREAM_IN);
+
   /* Read all the symbols and call graph from all the files in the
      command line.  */
   read_cgraph_and_symbols (num_in_fnames, in_fnames);
 
+  timevar_stop (TV_PHASE_STREAM_IN);
+
   if (!seen_error ())
     {
       /* If WPA is enabled analyze the whole call graph and create an
@@ -2091,13 +2111,15 @@ lto_main (void)
 	do_whole_program_analysis ();
       else
 	{
+	  timevar_start (TV_PHASE_OPT_GEN);
+
 	  materialize_cgraph ();
 
 	  /* Let the middle end know that we have read and merged all of
 	     the input files.  */ 
-	  timevar_start (TV_PHASE_CGRAPH);
 	  compile ();
-	  timevar_stop (TV_PHASE_CGRAPH);
+
+	  timevar_stop (TV_PHASE_OPT_GEN);
 
 	  /* FIXME lto, if the processes spawned by WPA fail, we miss
 	     the chance to print WPA's report, so WPA will call
@@ -2108,6 +2130,10 @@ lto_main (void)
 	    print_lto_report ();
 	}
     }
+
+  /* Here we make LTO pretend to be a parser.  */
+  timevar_start (TV_PHASE_PARSING);
+  timevar_push (TV_PARSE_GLOBAL);
 }
 
 #include "gt-lto-lto.h"
diff --git a/gcc/timevar.c b/gcc/timevar.c
index 96eb92a..2d1fe72 100644
--- a/gcc/timevar.c
+++ b/gcc/timevar.c
@@ -421,6 +421,57 @@ timevar_cond_stop (timevar_id_t timevar, bool running)
 }
 
 
+/* Validate that phase times are consistent.  */
+
+static void
+validate_phases (FILE *fp)
+{
+  unsigned int /* timevar_id_t */ id;
+  struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
+  double phase_user = 0.0;
+  double phase_sys = 0.0;
+  double phase_wall = 0.0;
+  unsigned phase_ggc_mem = 0;
+  static char phase_prefix[] = "phase ";
+  const double tolerance = 1.000001;  /* One part in a million.  */
+
+  for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
+    {
+      struct timevar_def *tv = &timevars[(timevar_id_t) id];
+
+      /* Don't evaluate timing variables that were never used.  */
+      if (!tv->used)
+	continue;
+
+      if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
+	{
+	  phase_user += tv->elapsed.user;
+	  phase_sys += tv->elapsed.sys;
+	  phase_wall += tv->elapsed.wall;
+	  phase_ggc_mem += tv->elapsed.ggc_mem;
+	}
+    }
+
+  if (phase_user > total->user * tolerance
+      || phase_sys > total->sys * tolerance
+      || phase_wall > total->wall * tolerance
+      || phase_ggc_mem > total->ggc_mem * tolerance)
+    {
+
+      fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
+      if (phase_user > total->user)
+	fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
+      if (phase_sys > total->sys)
+	fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
+      if (phase_wall > total->wall)
+	fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
+      if (phase_ggc_mem > total->ggc_mem)
+	fprintf (fp, "ggc_mem %24u > %24u\n", phase_ggc_mem, total->ggc_mem);
+      gcc_unreachable ();
+    }
+}
+
+
 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
    a special meaning -- it's considered to be the total elapsed time,
    for normalizing the others, and is displayed last.  */
@@ -535,6 +586,8 @@ timevar_print (FILE *fp)
 
 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 	  || defined (HAVE_WALL_TIME) */
+
+  validate_phases (fp);
 }
 
 /* Prints a message to stderr stating that time elapsed in STR is
diff --git a/gcc/timevar.def b/gcc/timevar.def
index 1f5ea2a..57d9e3f 100644
--- a/gcc/timevar.def
+++ b/gcc/timevar.def
@@ -33,13 +33,17 @@
 
 /* The total execution time.  */
 DEFTIMEVAR (TV_TOTAL                 , "total time")
+/* The compiler phases.  These must be mutually exclusive.
+   Ideally, they would sum to near the total time.  */
 DEFTIMEVAR (TV_PHASE_SETUP           , "phase setup")
 DEFTIMEVAR (TV_PHASE_PARSING         , "phase parsing")
 DEFTIMEVAR (TV_PHASE_DEFERRED        , "phase lang. deferred")
-DEFTIMEVAR (TV_PHASE_CGRAPH          , "phase cgraph")
+DEFTIMEVAR (TV_PHASE_OPT_GEN         , "phase opt and generate")
 DEFTIMEVAR (TV_PHASE_DBGINFO         , "phase debug info")
 DEFTIMEVAR (TV_PHASE_CHECK_DBGINFO   , "phase check & debug info")
-DEFTIMEVAR (TV_PHASE_GENERATE        , "phase generate")
+DEFTIMEVAR (TV_PHASE_LATE_ASM        , "phase last asm")
+DEFTIMEVAR (TV_PHASE_STREAM_IN       , "phase stream in")
+DEFTIMEVAR (TV_PHASE_STREAM_OUT      , "phase stream out")
 DEFTIMEVAR (TV_PHASE_FINALIZE        , "phase finalize")
 
 /* Concurrent timers, indicated by "|".  */
diff --git a/gcc/toplev.c b/gcc/toplev.c
index 3f5e61b..2eb75f1 100644
--- a/gcc/toplev.c
+++ b/gcc/toplev.c
@@ -558,18 +558,15 @@ compile_file (void)
   if (flag_syntax_only || flag_wpa)
     return;
 
-  timevar_start (TV_PHASE_GENERATE);
-
   ggc_protect_identifiers = false;
 
   /* This must also call finalize_compilation_unit.  */
   lang_hooks.decls.final_write_globals ();
 
   if (seen_error ())
-    {
-      timevar_stop (TV_PHASE_GENERATE);
-      return;
-    }
+    return;
+
+  timevar_start (TV_PHASE_LATE_ASM);
 
   /* Compilation unit is finalized.  When producing non-fat LTO object, we are
      basically finished.  */
@@ -670,7 +667,7 @@ compile_file (void)
      assembly file after this point.  */
   targetm.asm_out.file_end ();
 
-  timevar_stop (TV_PHASE_GENERATE);
+  timevar_stop (TV_PHASE_LATE_ASM);
 }
 
 /* Print version information to FILE.