[PATCH][RFC] Add the ability to record sub-timevars (-ftime-report-details)

Richard Biener rguenther@suse.de
Wed Aug 10 12:04:00 GMT 2016


The following patch adds the ability to record time spent in utility
to the pass using it.  For things like CFG cleanup, alias stmt walking
or DF infrastructure work it is currently not visible which pass is
responsible for the time spent there.  With -ftime-report-details
you now get

 alias stmt walking      :   4.48 ( 2%) usr   0.14 ( 3%) sys   4.66 ( 2%) 
wall    1209 kB ( 0%) ggc
...
 tree PRE                :   3.58 ( 2%) usr   0.04 ( 1%) sys   3.71 ( 2%) 
wall   11870 kB ( 1%) ggc
 `- tree tail merge      :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) 
wall       0 kB ( 0%) ggc
 `- alias stmt walking   :   0.88 ( 0%) usr   0.00 ( 0%) sys   0.91 ( 0%) 
wall     153 kB ( 0%) ggc
 `- loop init            :   0.05 ( 0%) usr   0.00 ( 0%) sys   0.08 ( 0%) 
wall       0 kB ( 0%) ggc
 `- tree SSA incremental :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) 
wall       0 kB ( 0%) ggc
 `- tree operand scan    :   0.06 ( 0%) usr   0.00 ( 0%) sys   0.04 ( 0%) 
wall     544 kB ( 0%) ggc
 `- tree STMT verifier   :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) 
wall       0 kB ( 0%) ggc
 tree FRE                :   3.91 ( 2%) usr   0.09 ( 2%) sys   3.71 ( 2%) 
wall    5658 kB ( 1%) ggc
 `- alias stmt walking   :   2.81 ( 2%) usr   0.08 ( 2%) sys   2.84 ( 2%) 
wall     819 kB ( 0%) ggc
 `- unaccounted todo     :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) 
wall     851 kB ( 0%) ggc
 `- tree operand scan    :   0.06 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) 
wall       0 kB ( 0%) ggc
 `- dominance computation:   0.03 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) 
wall       0 kB ( 0%) ggc
 tree code sinking       :   0.11 ( 0%) usr   0.02 ( 0%) sys   0.17 ( 0%) 
wall    1268 kB ( 0%) ggc
 `- loop init            :   0.13 ( 0%) usr   0.00 ( 0%) sys   0.11 ( 0%) 
wall     526 kB ( 0%) ggc
 `- dominance computation:   0.06 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) 
wall       0 kB ( 0%) ggc
...

note that the full time spent in, say, alias stmt walking is still
recorded and dumped.  Note this also visualizes current nesting
of timevars and thus you'll get

 rest of compilation     :   1.02 ( 1%) usr   0.04 ( 1%) sys   1.17 ( 1%) 
wall    4977 kB ( 0%) ggc
 `- hard reg cprop       :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) 
wall       0 kB ( 0%) ggc
 `- tree conservative DCE:   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) 
wall       0 kB ( 0%) ggc
...

because we have passes w/o timevar that are accumulated in
rest of compilation.  There is the opportunity to clean this up.

I've extended the pass timevars to also cover their TODOs and thus
removed TV_TODO.

The accounting is "flat", that is, at most one level of sub-timevars
are recorded.

Does this look sensible and useful given the imperfectness of the
current timevar assignments?

Bootstrap pending.

Thanks,
Richard.

2016-08-10  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::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.
	* timevar.def (TV_TODO): Remove.

Index: gcc/common.opt
===================================================================
--- gcc/common.opt	(revision 238469)
+++ gcc/common.opt	(working copy)
@@ -2255,6 +2255,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.
Index: gcc/doc/invoke.texi
===================================================================
--- gcc/doc/invoke.texi	(revision 238469)
+++ gcc/doc/invoke.texi	(working copy)
@@ -548,7 +548,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
@@ -12543,6 +12543,10 @@ print some statistics about each pass wh
 Makes the compiler print some statistics about the time consumed by each
 pass when it finishes.
 
+@item -ftime-report
+@opindex ftime-report
+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.
Index: gcc/timevar.c
===================================================================
--- gcc/timevar.c	(revision 238469)
+++ gcc/timevar.c	(working copy)
@@ -205,7 +205,7 @@ timer::named_items::print (FILE *fp, con
     {
       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,9 @@ timer::~timer ()
       next = iter->next;
       free (iter);
     }
+  for (unsigned i = 0; i < TIMEVAR_LAST; ++i)
+    if (m_timevars[i].children)
+      delete m_timevars[i].children;
 
   delete m_jit_client_items;
 }
@@ -399,13 +402,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,38 +635,38 @@ 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);
 }
@@ -702,15 +718,47 @@ timer::print (FILE *fp)
       if (!tv->used)
 	continue;
 
+      bool any_childs_with_time = false;
+      if (tv->children)
+	for (child_map_t::iterator i = tv->children->begin ();
+	     i != tv->children->end (); ++i)
+	  if (!((*i).second.user < tiny
+		&& (*i).second.sys < tiny
+		&& (*i).second.wall < tiny
+		&& (*i).second.ggc_mem < GGC_MEM_BOUND))
+	    {
+	      any_childs_with_time = true;
+	      break;
+	    }
+
       /* Don't print timing variables if we're going to get a row of
-         zeroes.  */
-      if (tv->elapsed.user < tiny
+         zeroes.  Unless there are children with non-zero time.  */
+      if (! any_childs_with_time
+	  && tv->elapsed.user < tiny
 	  && tv->elapsed.sys < tiny
 	  && tv->elapsed.wall < tiny
 	  && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
 	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 (!((*i).second.user < tiny
+		  && (*i).second.sys < tiny
+		  && (*i).second.wall < tiny
+		  && (*i).second.ggc_mem < GGC_MEM_BOUND))
+	      {
+		char lname[256];
+		sprintf (lname, "`- %s", tv2->name);
+		print_row (fp, total, lname, (*i).second);
+	      }
+	  }
     }
   if (m_jit_client_items)
     m_jit_client_items->print (fp, total);
Index: gcc/timevar.h
===================================================================
--- gcc/timevar.h	(revision 238469)
+++ gcc/timevar.h	(working copy)
@@ -131,9 +131,10 @@ 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);
 
  private:
+  typedef hash_map<timevar_def *, timevar_time_def> child_map_t;
 
   /* Private type: a timing variable.  */
   struct timevar_def
@@ -155,6 +156,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
Index: gcc/passes.c
===================================================================
*** gcc/passes.c	(revision 238469)
--- gcc/passes.c	(working copy)
*************** execute_todo (unsigned int flags)
*** 2002,2009 ****
        && need_ssa_update_p (cfun))
      gcc_assert (flags & TODO_update_ssa_any);
  
-   timevar_push (TV_TODO);
- 
    statistics_fini_pass ();
  
    if (flags)
--- 2002,2007 ----
*************** execute_todo (unsigned int flags)
*** 2037,2044 ****
       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
--- 2035,2040 ----
*************** execute_one_ipa_transform_pass (struct c
*** 2190,2209 ****
  
    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);
  
    /* 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);
  
--- 2186,2201 ----
  
    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 (ipa_pass->function_transform_todo_flags_start);
+ 
    /* Do it!  */
    todo_after = ipa_pass->function_transform (node);
  
    if (profile_report && cfun && (cfun->curr_properties & PROP_cfg))
      check_profile_consistency (pass->static_pass_number, 0, true);
  
*************** execute_one_ipa_transform_pass (struct c
*** 2213,2218 ****
--- 2205,2214 ----
    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);
*************** execute_one_pass (opt_pass *pass)
*** 2321,2326 ****
--- 2317,2326 ----
  
    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);
  
*************** execute_one_pass (opt_pass *pass)
*** 2328,2342 ****
      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)
      {
        pass_fini_dump_file (pass);
  
        gcc_assert (cfun);
--- 2328,2342 ----
      do_per_function (verify_curr_properties,
  		     (void *)(size_t)pass->properties_required);
  
    /* 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);
*************** execute_one_pass (opt_pass *pass)
*** 2363,2372 ****
  
    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))
--- 2363,2368 ----
*************** execute_one_pass (opt_pass *pass)
*** 2378,2383 ****
--- 2374,2384 ----
      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)
      {
Index: gcc/timevar.def
===================================================================
*** gcc/timevar.def	(revision 238469)
--- gcc/timevar.def	(working copy)
*************** DEFTIMEVAR (TV_POSTRELOAD	     , "unacco
*** 290,296 ****
  DEFTIMEVAR (TV_LATE_COMPILATION	     , "unaccounted late compilation")
  DEFTIMEVAR (TV_REMOVE_UNUSED	     , "remove unused locals")
  DEFTIMEVAR (TV_ADDRESS_TAKEN	     , "address taken")
- DEFTIMEVAR (TV_TODO		     , "unaccounted todo")
  DEFTIMEVAR (TV_VERIFY_LOOP_CLOSED    , "verify loop closed")
  DEFTIMEVAR (TV_VERIFY_RTL_SHARING    , "verify RTL sharing")
  DEFTIMEVAR (TV_REBUILD_FREQUENCIES   , "rebuild frequencies")
--- 290,295 ----



More information about the Gcc-patches mailing list