diff options
Diffstat (limited to 'gcc')
| -rw-r--r-- | gcc/ChangeLog | 19 | ||||
| -rw-r--r-- | gcc/common.opt | 4 | ||||
| -rw-r--r-- | gcc/doc/invoke.texi | 6 | ||||
| -rw-r--r-- | gcc/passes.c | 39 | ||||
| -rw-r--r-- | gcc/timevar.c | 91 | ||||
| -rw-r--r-- | gcc/timevar.h | 6 |
6 files changed, 123 insertions, 42 deletions
diff --git a/gcc/ChangeLog b/gcc/ChangeLog index 5185627..8257b0e 100644 --- a/gcc/ChangeLog +++ b/gcc/ChangeLog @@ -1,5 +1,24 @@ 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. diff --git a/gcc/common.opt b/gcc/common.opt index 44adae8..65a9762 100644 --- a/gcc/common.opt +++ b/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. diff --git a/gcc/doc/invoke.texi b/gcc/doc/invoke.texi index 1cfaae7..d04be6f 100644 --- a/gcc/doc/invoke.texi +++ b/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. diff --git a/gcc/passes.c b/gcc/passes.c index 0565cfa..c7d7dbe 100644 --- a/gcc/passes.c +++ b/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) { diff --git a/gcc/timevar.c b/gcc/timevar.c index a41ff39..4c8ceac 100644 --- a/gcc/timevar.c +++ b/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); diff --git a/gcc/timevar.h b/gcc/timevar.h index 3465304..8ba7e5c 100644 --- a/gcc/timevar.h +++ b/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 |