passes.c (execute_todo): Do not push/pop TV_TODO.

2016-08-12  Richard Biener  <rguenther@suse.de>

	* passes.c (execute_todo): Do not push/pop TV_TODO.
	(execute_one_ipa_transform_pass): Move timevar push/pop TODO execution.
	(execute_one_pass): Likewise.
	* common.opt (ftime-report-details): New switch.
	* doc/invoke.texi (ftime-report-details): Document.
	* timevar.h (timer::print_row): Adjust signature.
	(timer::all_zero): New static helper.
	(timer::child_map_t): New typedef.
	(timer::time_var_def): Add children field.
	* timevar.c (timer::named_items::print): Adjust.
	(timer::~timer): Free timevar recorded children.
	(timer::pop_internal): When -ftime-report-details record
	time spent in sub-timevars.
	(timer::print_row): Adjust.
	(timer::print): Print sub-timevar stats, use all_zero.
	* timevar.def (TV_TODO): Remove.

From-SVN: r239406

gcc/ChangeLog

 2016-08-12  Richard Biener  <rguenther@suse.de>
 
+	* passes.c (execute_todo): Do not push/pop TV_TODO.
+	(execute_one_ipa_transform_pass): Move timevar push/pop TODO execution.
+	(execute_one_pass): Likewise.
+	* common.opt (ftime-report-details): New switch.
+	* doc/invoke.texi (ftime-report-details): Document.
+	* timevar.h (timer::print_row): Adjust signature.
+	(timer::all_zero): New static helper.
+	(timer::child_map_t): New typedef.
+	(timer::time_var_def): Add children field.
+	* timevar.c (timer::named_items::print): Adjust.
+	(timer::~timer): Free timevar recorded children.
+	(timer::pop_internal): When -ftime-report-details record
+	time spent in sub-timevars.
+	(timer::print_row): Adjust.
+	(timer::print): Print sub-timevar stats, use all_zero.
+	* timevar.def (TV_TODO): Remove.
+
+2016-08-12  Richard Biener  <rguenther@suse.de>
+
 	PR tree-optimization/72851
 	* tree-ssa-propagate.c: Include cfganal.h.  Rewrite block and stmt
 	worklists to use bitmaps indexed in execution order.

gcc/common.opt

@@ -2296,6 +2296,10 @@ ftime-report
 Common Report Var(time_report)
 Report the time taken by each compiler pass.
 
+ftime-report-details
+Common Report Var(time_report_details)
+Record times taken by sub-phases separately.
+
 ftls-model=
 Common Joined RejectNegative Enum(tls_model) Var(flag_tls_default) Init(TLS_MODEL_GLOBAL_DYNAMIC)
 -ftls-model=[global-dynamic|local-dynamic|initial-exec|local-exec]	Set the default thread-local storage code generation model.

gcc/doc/invoke.texi

@@ -554,7 +554,7 @@ Objective-C and Objective-C++ Dialects}.
 -fprofile-report @gol
 -frandom-seed=@var{string} -fsched-verbose=@var{n} @gol
 -fsel-sched-verbose -fsel-sched-dump-cfg -fsel-sched-pipelining-verbose @gol
--fstats  -fstack-usage  -ftime-report @gol
+-fstats  -fstack-usage  -ftime-report -ftime-report-details @gol
 -fvar-tracking-assignments-toggle -gtoggle @gol
 -print-file-name=@var{library}  -print-libgcc-file-name @gol
 -print-multi-directory  -print-multi-lib  -print-multi-os-directory @gol
@@ -12742,6 +12742,10 @@ print some statistics about each pass when it finishes.
 Makes the compiler print some statistics about the time consumed by each
 pass when it finishes.
 
+@item -ftime-report-details
+@opindex ftime-report-details
+Record the time consumed by infrastructure parts separately for each pass.
+
 @item -fira-verbose=@var{n}
 @opindex fira-verbose
 Control the verbosity of the dump file for the integrated register allocator.

gcc/passes.c

@@ -2008,8 +2008,6 @@ execute_todo (unsigned int flags)
       && need_ssa_update_p (cfun))
     gcc_assert (flags & TODO_update_ssa_any);
 
-  timevar_push (TV_TODO);
-
   statistics_fini_pass ();
 
   if (flags)
@@ -2043,8 +2041,6 @@ execute_todo (unsigned int flags)
      df problems.  */
   if (flags & TODO_df_finish)
     df_finish_pass ((flags & TODO_df_verify) != 0);
-
-  timevar_pop (TV_TODO);
 }
 
 /* Verify invariants that should hold between passes.  This is a place
@@ -2198,20 +2194,16 @@ execute_one_ipa_transform_pass (struct cgraph_node *node,
 
   pass_init_dump_file (pass);
 
-  /* Run pre-pass verification.  */
-  execute_todo (ipa_pass->function_transform_todo_flags_start);
-
   /* If a timevar is present, start it.  */
   if (pass->tv_id != TV_NONE)
     timevar_push (pass->tv_id);
 
+  /* Run pre-pass verification.  */
+  execute_todo (ipa_pass->function_transform_todo_flags_start);
+
   /* Do it!  */
   todo_after = ipa_pass->function_transform (node);
 
-  /* Stop timevar.  */
-  if (pass->tv_id != TV_NONE)
-    timevar_pop (pass->tv_id);
-
   if (profile_report && cfun && (cfun->curr_properties & PROP_cfg))
     check_profile_consistency (pass->static_pass_number, 0, true);
 
@@ -2221,6 +2213,10 @@ execute_one_ipa_transform_pass (struct cgraph_node *node,
   if (profile_report && cfun && (cfun->curr_properties & PROP_cfg))
     check_profile_consistency (pass->static_pass_number, 1, true);
 
+  /* Stop timevar.  */
+  if (pass->tv_id != TV_NONE)
+    timevar_pop (pass->tv_id);
+
   if (dump_file)
     do_per_function (execute_function_dump, pass);
   pass_fini_dump_file (pass);
@@ -2329,6 +2325,10 @@ execute_one_pass (opt_pass *pass)
 
   pass_init_dump_file (pass);
 
+  /* If a timevar is present, start it.  */
+  if (pass->tv_id != TV_NONE)
+    timevar_push (pass->tv_id);
+
   /* Run pre-pass verification.  */
   execute_todo (pass->todo_flags_start);
 
@@ -2336,15 +2336,15 @@ execute_one_pass (opt_pass *pass)
     do_per_function (verify_curr_properties,
 		     (void *)(size_t)pass->properties_required);
 
-  /* If a timevar is present, start it.  */
-  if (pass->tv_id != TV_NONE)
-    timevar_push (pass->tv_id);
-
   /* Do it!  */
   todo_after = pass->execute (cfun);
 
   if (todo_after & TODO_discard_function)
     {
+      /* Stop timevar.  */
+      if (pass->tv_id != TV_NONE)
+	timevar_pop (pass->tv_id);
+
       pass_fini_dump_file (pass);
 
       gcc_assert (cfun);
@@ -2371,10 +2371,6 @@ execute_one_pass (opt_pass *pass)
 
   do_per_function (clear_last_verified, NULL);
 
-  /* Stop timevar.  */
-  if (pass->tv_id != TV_NONE)
-    timevar_pop (pass->tv_id);
-
   do_per_function (update_properties_after_pass, pass);
 
   if (profile_report && cfun && (cfun->curr_properties & PROP_cfg))
@@ -2386,6 +2382,11 @@ execute_one_pass (opt_pass *pass)
     check_profile_consistency (pass->static_pass_number, 1, true);
 
   verify_interpass_invariants ();
+
+  /* Stop timevar.  */
+  if (pass->tv_id != TV_NONE)
+    timevar_pop (pass->tv_id);
+
   if (pass->type == IPA_PASS
       && ((ipa_opt_pass_d *)pass)->function_transform)
     {

gcc/timevar.c

@@ -205,7 +205,7 @@ timer::named_items::print (FILE *fp, const timevar_time_def *total)
     {
       timer::timevar_def *def = m_hash_map.get (item_name);
       gcc_assert (def);
-      m_timer->print_row (fp, total, def);
+      m_timer->print_row (fp, total, def->name, def->elapsed);
     }
 }
 
@@ -296,6 +296,8 @@ timer::~timer ()
       next = iter->next;
       free (iter);
     }
+  for (unsigned i = 0; i < TIMEVAR_LAST; ++i)
+    delete m_timevars[i].children;
 
   delete m_jit_client_items;
 }
@@ -399,13 +401,26 @@ timer::pop_internal ()
   /* Attribute the elapsed time to the element we're popping.  */
   timevar_accumulate (&popped->timevar->elapsed, &m_start_time, &now);
 
+  /* Take the item off the stack.  */
+  m_stack = m_stack->next;
+
+  /* Record the elapsed sub-time to the parent as well.  */
+  if (m_stack && time_report_details)
+    {
+      if (! m_stack->timevar->children)
+	m_stack->timevar->children = new child_map_t (5);
+      bool existed_p;
+      timevar_time_def &time
+	= m_stack->timevar->children->get_or_insert (popped->timevar, &existed_p);
+      if (! existed_p)
+	memset (&time, 0, sizeof (timevar_time_def));
+      timevar_accumulate (&time, &m_start_time, &now);
+    }
+
   /* Reset the start time; from now on, time is attributed to the
      element just exposed on the stack.  */
   m_start_time = now;
 
-  /* Take the item off the stack.  */
-  m_stack = m_stack->next;
-
   /* Don't delete the stack element; instead, add it to the list of
      unused elements for later use.  */
   popped->next = m_unused_stack_instances;
@@ -619,42 +634,54 @@ timer::validate_phases (FILE *fp) const
 void
 timer::print_row (FILE *fp,
 		  const timevar_time_def *total,
-		  const timevar_def *tv)
+		  const char *name, const timevar_time_def &elapsed)
 {
   /* The timing variable name.  */
-  fprintf (fp, " %-24s:", tv->name);
+  fprintf (fp, " %-24s:", name);
 
 #ifdef HAVE_USER_TIME
   /* Print user-mode time for this process.  */
   fprintf (fp, "%7.2f (%2.0f%%) usr",
-	   tv->elapsed.user,
-	   (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
+	   elapsed.user,
+	   (total->user == 0 ? 0 : elapsed.user / total->user) * 100);
 #endif /* HAVE_USER_TIME */
 
 #ifdef HAVE_SYS_TIME
   /* Print system-mode time for this process.  */
   fprintf (fp, "%7.2f (%2.0f%%) sys",
-	   tv->elapsed.sys,
-	   (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
+	   elapsed.sys,
+	   (total->sys == 0 ? 0 : elapsed.sys / total->sys) * 100);
 #endif /* HAVE_SYS_TIME */
 
 #ifdef HAVE_WALL_TIME
   /* Print wall clock time elapsed.  */
   fprintf (fp, "%7.2f (%2.0f%%) wall",
-	   tv->elapsed.wall,
-	   (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
+	   elapsed.wall,
+	   (total->wall == 0 ? 0 : elapsed.wall / total->wall) * 100);
 #endif /* HAVE_WALL_TIME */
 
   /* Print the amount of ggc memory allocated.  */
   fprintf (fp, "%8u kB (%2.0f%%) ggc",
-	   (unsigned) (tv->elapsed.ggc_mem >> 10),
+	   (unsigned) (elapsed.ggc_mem >> 10),
 	   (total->ggc_mem == 0
 	    ? 0
-	    : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
+	    : (float) elapsed.ggc_mem / total->ggc_mem) * 100);
 
   putc ('\n', fp);
 }
 
+/* Return whether ELAPSED is all zero.  */
+
+bool
+timer::all_zero (const timevar_time_def &elapsed)
+{
+  const double tiny = 5e-3;
+  return (elapsed.user < tiny
+	  && elapsed.sys < tiny
+	  && elapsed.wall < tiny
+	  && elapsed.ggc_mem < GGC_MEM_BOUND);
+}
+
 /* 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.  */
@@ -691,7 +718,6 @@ timer::print (FILE *fp)
   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
     {
       const timevar_def *tv = &m_timevars[(timevar_id_t) id];
-      const double tiny = 5e-3;
 
       /* Don't print the total execution time here; that goes at the
 	 end.  */
@@ -702,15 +728,38 @@ timer::print (FILE *fp)
       if (!tv->used)
 	continue;
 
+      bool any_children_with_time = false;
+      if (tv->children)
+	for (child_map_t::iterator i = tv->children->begin ();
+	     i != tv->children->end (); ++i)
+	  if (! all_zero ((*i).second))
+	    {
+	      any_children_with_time = true;
+	      break;
+	    }
+
       /* Don't print timing variables if we're going to get a row of
-         zeroes.  */
-      if (tv->elapsed.user < tiny
-	  && tv->elapsed.sys < tiny
-	  && tv->elapsed.wall < tiny
-	  && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
+         zeroes.  Unless there are children with non-zero time.  */
+      if (! any_children_with_time
+	  && all_zero (tv->elapsed))
 	continue;
 
-      print_row (fp, total, tv);
+      print_row (fp, total, tv->name, tv->elapsed);
+
+      if (tv->children)
+	for (child_map_t::iterator i = tv->children->begin ();
+	     i != tv->children->end (); ++i)
+	  {
+	    timevar_def *tv2 = (*i).first;
+	    /* Don't print timing variables if we're going to get a row of
+	       zeroes.  */
+	    if (! all_zero ((*i).second))
+	      {
+		char lname[256];
+		snprintf (lname, 256, "`- %s", tv2->name);
+		print_row (fp, total, lname, (*i).second);
+	      }
+	  }
     }
   if (m_jit_client_items)
     m_jit_client_items->print (fp, total);

gcc/timevar.h

@@ -131,9 +131,11 @@ class timer
   void pop_internal ();
   static void print_row (FILE *fp,
 			 const timevar_time_def *total,
-			 const timevar_def *tv);
+			 const char *name, const timevar_time_def &elapsed);
+  static bool all_zero (const timevar_time_def &elapsed);
 
  private:
+  typedef hash_map<timevar_def *, timevar_time_def> child_map_t;
 
   /* Private type: a timing variable.  */
   struct timevar_def
@@ -155,6 +157,8 @@ class timer
     /* Nonzero if this timing variable was ever started or pushed onto
        the timing stack.  */
     unsigned used : 1;
+
+    child_map_t *children;
   };
 
   /* Private type: an element on the timing stack