gcc/timevar.c

   1 /* Timing variables for measuring compiler performance.
   2    Copyright (C) 2000-2018 Free Software Foundation, Inc.
   3    Contributed by Alex Samuel <samuel@codesourcery.com>
   4
   5 This file is part of GCC.
   6
   7 GCC is free software; you can redistribute it and/or modify it under
   8 the terms of the GNU General Public License as published by the Free
   9 Software Foundation; either version 3, or (at your option) any later
  10 version.
  11
  12 GCC is distributed in the hope that it will be useful, but WITHOUT ANY
  13 WARRANTY; without even the implied warranty of MERCHANTABILITY or
  14 FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  15 for more details.
  16
  17 You should have received a copy of the GNU General Public License
  18 along with GCC; see the file COPYING3.  If not see
  19 <http://www.gnu.org/licenses/>.  */
  20
  21 #include "config.h"
  22 #include "system.h"
  23 #include "coretypes.h"
  24 #include "timevar.h"
  25 #include "options.h"
  26
  27 #ifndef HAVE_CLOCK_T
  28 typedef int clock_t;
  29 #endif
  30
  31 #ifndef HAVE_STRUCT_TMS
  32 struct tms
  33 {
  34   clock_t tms_utime;
  35   clock_t tms_stime;
  36   clock_t tms_cutime;
  37   clock_t tms_cstime;
  38 };
  39 #endif
  40
  41 #ifndef RUSAGE_SELF
  42 # define RUSAGE_SELF 0
  43 #endif
  44
  45 /* Calculation of scale factor to convert ticks to microseconds.
  46    We mustn't use CLOCKS_PER_SEC except with clock().  */
  47 #if HAVE_SYSCONF && defined _SC_CLK_TCK
  48 # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
  49 #else
  50 # ifdef CLK_TCK
  51 #  define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
  52 # else
  53 #  ifdef HZ
  54 #   define TICKS_PER_SECOND HZ  /* traditional UNIX */
  55 #  else
  56 #   define TICKS_PER_SECOND 100 /* often the correct value */
  57 #  endif
  58 # endif
  59 #endif
  60
  61 /* Prefer times to getrusage to clock (each gives successively less
  62    information).  */
  63 #ifdef HAVE_TIMES
  64 # if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
  65   extern clock_t times (struct tms *);
  66 # endif
  67 # define USE_TIMES
  68 # define HAVE_USER_TIME
  69 # define HAVE_SYS_TIME
  70 # define HAVE_WALL_TIME
  71 #else
  72 #ifdef HAVE_GETRUSAGE
  73 # if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
  74   extern int getrusage (int, struct rusage *);
  75 # endif
  76 # define USE_GETRUSAGE
  77 # define HAVE_USER_TIME
  78 # define HAVE_SYS_TIME
  79 #else
  80 #ifdef HAVE_CLOCK
  81 # if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
  82   extern clock_t clock (void);
  83 # endif
  84 # define USE_CLOCK
  85 # define HAVE_USER_TIME
  86 #endif
  87 #endif
  88 #endif
  89
  90 /* libc is very likely to have snuck a call to sysconf() into one of
  91    the underlying constants, and that can be very slow, so we have to
  92    precompute them.  Whose wonderful idea was it to make all those
  93    _constants_ variable at run time, anyway?  */
  94 #ifdef USE_TIMES
  95 static double ticks_to_msec;
  96 #define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND)
  97 #endif
  98
  99 #ifdef USE_CLOCK
 100 static double clocks_to_msec;
 101 #define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC)
 102 #endif
 103
 104 /* Non-NULL if timevars should be used.  In GCC, this happens with
 105    the -ftime-report flag.  */
 106
 107 timer *g_timer;
 108
 109 /* Total amount of memory allocated by garbage collector.  */
 110
 111 size_t timevar_ggc_mem_total;
 112
 113 /* The amount of memory that will cause us to report the timevar even
 114    if the time spent is not significant.  */
 115
 116 #define GGC_MEM_BOUND (1 << 20)
 117
 118 /* See timevar.h for an explanation of timing variables.  */
 119
 120 static void get_time (struct timevar_time_def *);
 121 static void timevar_accumulate (struct timevar_time_def *,
 122                                 struct timevar_time_def *,
 123                                 struct timevar_time_def *);
 124
 125 /* The implementation of timing events for jit client code, allowing
 126    arbitrary named items to appear on the timing stack.  */
 127
 128 class timer::named_items
 129 {
 130  public:
 131   named_items (timer *t);
 132   ~named_items ();
 133
 134   void push (const char *item_name);
 135   void pop ();
 136   void print (FILE *fp, const timevar_time_def *total);
 137
 138  private:
 139   /* Which timer instance does this relate to?  */
 140   timer *m_timer;
 141
 142   /* Dictionary, mapping from item names to timevar_def.
 143      Note that currently we merely store/compare the raw string
 144      pointers provided by client code; we don't take a copy,
 145      or use strcmp.  */
 146   hash_map <const char *, timer::timevar_def> m_hash_map;
 147
 148   /* The order in which items were originally inserted.  */
 149   auto_vec <const char *> m_names;
 150 };
 151
 152 /* The constructor for class timer::named_items.  */
 153
 154 timer::named_items::named_items (timer *t)
 155 : m_timer (t),
 156   m_hash_map (),
 157   m_names ()
 158 {
 159 }
 160
 161 /* The destructor for class timer::named_items.  */
 162
 163 timer::named_items::~named_items ()
 164 {
 165 }
 166
 167 /* Push the named item onto the timer stack.  */
 168
 169 void
 170 timer::named_items::push (const char *item_name)
 171 {
 172   gcc_assert (item_name);
 173
 174   bool existed;
 175   timer::timevar_def *def = &m_hash_map.get_or_insert (item_name, &existed);
 176   if (!existed)
 177     {
 178       def->elapsed.user = 0;
 179       def->elapsed.sys = 0;
 180       def->elapsed.wall = 0;
 181       def->name = item_name;
 182       def->standalone = 0;
 183       m_names.safe_push (item_name);
 184     }
 185   m_timer->push_internal (def);
 186 }
 187
 188 /* Pop the top item from the timer stack.  */
 189
 190 void
 191 timer::named_items::pop ()
 192 {
 193   m_timer->pop_internal ();
 194 }
 195
 196 /* Print the given client item.  Helper function for timer::print.  */
 197
 198 void
 199 timer::named_items::print (FILE *fp, const timevar_time_def *total)
 200 {
 201   unsigned int i;
 202   const char *item_name;
 203   fprintf (fp, "Client items:\n");
 204   FOR_EACH_VEC_ELT (m_names, i, item_name)
 205     {
 206       timer::timevar_def *def = m_hash_map.get (item_name);
 207       gcc_assert (def);
 208       m_timer->print_row (fp, total, def->name, def->elapsed);
 209     }
 210 }
 211
 212 /* Fill the current times into TIME.  The definition of this function
 213    also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
 214    HAVE_WALL_TIME macros.  */
 215
 216 static void
 217 get_time (struct timevar_time_def *now)
 218 {
 219   now->user = 0;
 220   now->sys  = 0;
 221   now->wall = 0;
 222   now->ggc_mem = timevar_ggc_mem_total;
 223
 224   {
 225 #ifdef USE_TIMES
 226     struct tms tms;
 227     now->wall = times (&tms)  * ticks_to_msec;
 228     now->user = tms.tms_utime * ticks_to_msec;
 229     now->sys  = tms.tms_stime * ticks_to_msec;
 230 #endif
 231 #ifdef USE_GETRUSAGE
 232     struct rusage rusage;
 233     getrusage (RUSAGE_SELF, &rusage);
 234     now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
 235     now->sys  = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
 236 #endif
 237 #ifdef USE_CLOCK
 238     now->user = clock () * clocks_to_msec;
 239 #endif
 240   }
 241 }
 242
 243 /* Add the difference between STOP_TIME and START_TIME to TIMER.  */
 244
 245 static void
 246 timevar_accumulate (struct timevar_time_def *timer,
 247                     struct timevar_time_def *start_time,
 248                     struct timevar_time_def *stop_time)
 249 {
 250   timer->user += stop_time->user - start_time->user;
 251   timer->sys += stop_time->sys - start_time->sys;
 252   timer->wall += stop_time->wall - start_time->wall;
 253   timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
 254 }
 255
 256 /* Class timer's constructor.  */
 257
 258 timer::timer () :
 259   m_stack (NULL),
 260   m_unused_stack_instances (NULL),
 261   m_start_time (),
 262   m_jit_client_items (NULL)
 263 {
 264   /* Zero all elapsed times.  */
 265   memset (m_timevars, 0, sizeof (m_timevars));
 266
 267   /* Initialize the names of timing variables.  */
 268 #define DEFTIMEVAR(identifier__, name__) \
 269   m_timevars[identifier__].name = name__;
 270 #include "timevar.def"
 271 #undef DEFTIMEVAR
 272
 273   /* Initialize configuration-specific state.
 274      Ideally this would be one-time initialization.  */
 275 #ifdef USE_TIMES
 276   ticks_to_msec = TICKS_TO_MSEC;
 277 #endif
 278 #ifdef USE_CLOCK
 279   clocks_to_msec = CLOCKS_TO_MSEC;
 280 #endif
 281 }
 282
 283 /* Class timer's destructor.  */
 284
 285 timer::~timer ()
 286 {
 287   timevar_stack_def *iter, *next;
 288
 289   for (iter = m_stack; iter; iter = next)
 290     {
 291       next = iter->next;
 292       free (iter);
 293     }
 294   for (iter = m_unused_stack_instances; iter; iter = next)
 295     {
 296       next = iter->next;
 297       free (iter);
 298     }
 299   for (unsigned i = 0; i < TIMEVAR_LAST; ++i)
 300     delete m_timevars[i].children;
 301
 302   delete m_jit_client_items;
 303 }
 304
 305 /* Initialize timing variables.  */
 306
 307 void
 308 timevar_init (void)
 309 {
 310   if (g_timer)
 311     return;
 312
 313   g_timer = new timer ();
 314 }
 315
 316 /* Push TIMEVAR onto the timing stack.  No further elapsed time is
 317    attributed to the previous topmost timing variable on the stack;
 318    subsequent elapsed time is attributed to TIMEVAR, until it is
 319    popped or another element is pushed on top.
 320
 321    TIMEVAR cannot be running as a standalone timer.  */
 322
 323 void
 324 timer::push (timevar_id_t timevar)
 325 {
 326   struct timevar_def *tv = &m_timevars[timevar];
 327   push_internal (tv);
 328 }
 329
 330 /* Push TV onto the timing stack, either one of the builtin ones
 331    for a timevar_id_t, or one provided by client code to libgccjit.  */
 332
 333 void
 334 timer::push_internal (struct timevar_def *tv)
 335 {
 336   struct timevar_stack_def *context;
 337   struct timevar_time_def now;
 338
 339   gcc_assert (tv);
 340
 341   /* Mark this timing variable as used.  */
 342   tv->used = 1;
 343
 344   /* Can't push a standalone timer.  */
 345   gcc_assert (!tv->standalone);
 346
 347   /* What time is it?  */
 348   get_time (&now);
 349
 350   /* If the stack isn't empty, attribute the current elapsed time to
 351      the old topmost element.  */
 352   if (m_stack)
 353     timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
 354
 355   /* Reset the start time; from now on, time is attributed to
 356      TIMEVAR.  */
 357   m_start_time = now;
 358
 359   /* See if we have a previously-allocated stack instance.  If so,
 360      take it off the list.  If not, malloc a new one.  */
 361   if (m_unused_stack_instances != NULL)
 362     {
 363       context = m_unused_stack_instances;
 364       m_unused_stack_instances = m_unused_stack_instances->next;
 365     }
 366   else
 367     context = XNEW (struct timevar_stack_def);
 368
 369   /* Fill it in and put it on the stack.  */
 370   context->timevar = tv;
 371   context->next = m_stack;
 372   m_stack = context;
 373 }
 374
 375 /* Pop the topmost timing variable element off the timing stack.  The
 376    popped variable must be TIMEVAR.  Elapsed time since the that
 377    element was pushed on, or since it was last exposed on top of the
 378    stack when the element above it was popped off, is credited to that
 379    timing variable.  */
 380
 381 void
 382 timer::pop (timevar_id_t timevar)
 383 {
 384   gcc_assert (&m_timevars[timevar] == m_stack->timevar);
 385
 386   pop_internal ();
 387 }
 388
 389 /* Pop the topmost item from the stack, either one of the builtin ones
 390    for a timevar_id_t, or one provided by client code to libgccjit.  */
 391
 392 void
 393 timer::pop_internal ()
 394 {
 395   struct timevar_time_def now;
 396   struct timevar_stack_def *popped = m_stack;
 397
 398   /* What time is it?  */
 399   get_time (&now);
 400
 401   /* Attribute the elapsed time to the element we're popping.  */
 402   timevar_accumulate (&popped->timevar->elapsed, &m_start_time, &now);
 403
 404   /* Take the item off the stack.  */
 405   m_stack = m_stack->next;
 406
 407   /* Record the elapsed sub-time to the parent as well.  */
 408   if (m_stack && time_report_details)
 409     {
 410       if (! m_stack->timevar->children)
 411         m_stack->timevar->children = new child_map_t (5);
 412       bool existed_p;
 413       timevar_time_def &time
 414         = m_stack->timevar->children->get_or_insert (popped->timevar, &existed_p);
 415       if (! existed_p)
 416         memset (&time, 0, sizeof (timevar_time_def));
 417       timevar_accumulate (&time, &m_start_time, &now);
 418     }
 419
 420   /* Reset the start time; from now on, time is attributed to the
 421      element just exposed on the stack.  */
 422   m_start_time = now;
 423
 424   /* Don't delete the stack element; instead, add it to the list of
 425      unused elements for later use.  */
 426   popped->next = m_unused_stack_instances;
 427   m_unused_stack_instances = popped;
 428 }
 429
 430 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 431    time until timevar_stop is called for the same timing variable is
 432    attributed to TIMEVAR.  */
 433
 434 void
 435 timevar_start (timevar_id_t timevar)
 436 {
 437   if (!g_timer)
 438     return;
 439
 440   g_timer->start (timevar);
 441 }
 442
 443 /* See timevar_start above.  */
 444
 445 void
 446 timer::start (timevar_id_t timevar)
 447 {
 448   struct timevar_def *tv = &m_timevars[timevar];
 449
 450   /* Mark this timing variable as used.  */
 451   tv->used = 1;
 452
 453   /* Don't allow the same timing variable to be started more than
 454      once.  */
 455   gcc_assert (!tv->standalone);
 456   tv->standalone = 1;
 457
 458   get_time (&tv->start_time);
 459 }
 460
 461 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 462    is attributed to it.  */
 463
 464 void
 465 timevar_stop (timevar_id_t timevar)
 466 {
 467   if (!g_timer)
 468     return;
 469
 470   g_timer->stop (timevar);
 471 }
 472
 473 /* See timevar_stop above.  */
 474
 475 void
 476 timer::stop (timevar_id_t timevar)
 477 {
 478   struct timevar_def *tv = &m_timevars[timevar];
 479   struct timevar_time_def now;
 480
 481   /* TIMEVAR must have been started via timevar_start.  */
 482   gcc_assert (tv->standalone);
 483   tv->standalone = 0; /* Enable a restart.  */
 484
 485   get_time (&now);
 486   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 487 }
 488
 489
 490 /* Conditionally start timing TIMEVAR independently of the timing stack.
 491    If the timer is already running, leave it running and return true.
 492    Otherwise, start the timer and return false.
 493    Elapsed time until the corresponding timevar_cond_stop
 494    is called for the same timing variable is attributed to TIMEVAR.  */
 495
 496 bool
 497 timevar_cond_start (timevar_id_t timevar)
 498 {
 499   if (!g_timer)
 500     return false;
 501
 502   return g_timer->cond_start (timevar);
 503 }
 504
 505 /* See timevar_cond_start above.  */
 506
 507 bool
 508 timer::cond_start (timevar_id_t timevar)
 509 {
 510   struct timevar_def *tv = &m_timevars[timevar];
 511
 512   /* Mark this timing variable as used.  */
 513   tv->used = 1;
 514
 515   if (tv->standalone)
 516     return true;  /* The timevar is already running.  */
 517
 518   /* Don't allow the same timing variable
 519      to be unconditionally started more than once.  */
 520   tv->standalone = 1;
 521
 522   get_time (&tv->start_time);
 523   return false;  /* The timevar was not already running.  */
 524 }
 525
 526 /* Conditionally stop timing TIMEVAR.  The RUNNING parameter must come
 527    from the return value of a dynamically matching timevar_cond_start.
 528    If the timer had already been RUNNING, do nothing.  Otherwise, time
 529    elapsed since timevar_cond_start was called is attributed to it.  */
 530
 531 void
 532 timevar_cond_stop (timevar_id_t timevar, bool running)
 533 {
 534   if (!g_timer || running)
 535     return;
 536
 537   g_timer->cond_stop (timevar);
 538 }
 539
 540 /* See timevar_cond_stop above.  */
 541
 542 void
 543 timer::cond_stop (timevar_id_t timevar)
 544 {
 545   struct timevar_def *tv;
 546   struct timevar_time_def now;
 547
 548   tv = &m_timevars[timevar];
 549
 550   /* TIMEVAR must have been started via timevar_cond_start.  */
 551   gcc_assert (tv->standalone);
 552   tv->standalone = 0; /* Enable a restart.  */
 553
 554   get_time (&now);
 555   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 556 }
 557
 558 /* Push the named item onto the timing stack.  */
 559
 560 void
 561 timer::push_client_item (const char *item_name)
 562 {
 563   gcc_assert (item_name);
 564
 565   /* Lazily create the named_items instance.  */
 566   if (!m_jit_client_items)
 567     m_jit_client_items = new named_items (this);
 568
 569   m_jit_client_items->push (item_name);
 570 }
 571
 572 /* Pop the top-most client item from the timing stack.  */
 573
 574 void
 575 timer::pop_client_item ()
 576 {
 577   gcc_assert (m_jit_client_items);
 578   m_jit_client_items->pop ();
 579 }
 580
 581 /* Validate that phase times are consistent.  */
 582
 583 void
 584 timer::validate_phases (FILE *fp) const
 585 {
 586   unsigned int /* timevar_id_t */ id;
 587   const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
 588   double phase_user = 0.0;
 589   double phase_sys = 0.0;
 590   double phase_wall = 0.0;
 591   size_t phase_ggc_mem = 0;
 592   static char phase_prefix[] = "phase ";
 593   const double tolerance = 1.000001;  /* One part in a million.  */
 594
 595   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 596     {
 597       const timevar_def *tv = &m_timevars[(timevar_id_t) id];
 598
 599       /* Don't evaluate timing variables that were never used.  */
 600       if (!tv->used)
 601         continue;
 602
 603       if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
 604         {
 605           phase_user += tv->elapsed.user;
 606           phase_sys += tv->elapsed.sys;
 607           phase_wall += tv->elapsed.wall;
 608           phase_ggc_mem += tv->elapsed.ggc_mem;
 609         }
 610     }
 611
 612   if (phase_user > total->user * tolerance
 613       || phase_sys > total->sys * tolerance
 614       || phase_wall > total->wall * tolerance
 615       || phase_ggc_mem > total->ggc_mem * tolerance)
 616     {
 617
 618       fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
 619       if (phase_user > total->user)
 620         fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
 621       if (phase_sys > total->sys)
 622         fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
 623       if (phase_wall > total->wall)
 624         fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
 625       if (phase_ggc_mem > total->ggc_mem)
 626         fprintf (fp, "ggc_mem %24lu > %24lu\n", (unsigned long)phase_ggc_mem,
 627                  (unsigned long)total->ggc_mem);
 628       gcc_unreachable ();
 629     }
 630 }
 631
 632 /* Helper function for timer::print.  */
 633
 634 void
 635 timer::print_row (FILE *fp,
 636                   const timevar_time_def *total,
 637                   const char *name, const timevar_time_def &elapsed)
 638 {
 639   /* The timing variable name.  */
 640   fprintf (fp, " %-35s:", name);
 641
 642 #ifdef HAVE_USER_TIME
 643   /* Print user-mode time for this process.  */
 644   fprintf (fp, "%7.2f (%3.0f%%)",
 645            elapsed.user,
 646            (total->user == 0 ? 0 : elapsed.user / total->user) * 100);
 647 #endif /* HAVE_USER_TIME */
 648
 649 #ifdef HAVE_SYS_TIME
 650   /* Print system-mode time for this process.  */
 651   fprintf (fp, "%7.2f (%3.0f%%)",
 652            elapsed.sys,
 653            (total->sys == 0 ? 0 : elapsed.sys / total->sys) * 100);
 654 #endif /* HAVE_SYS_TIME */
 655
 656 #ifdef HAVE_WALL_TIME
 657   /* Print wall clock time elapsed.  */
 658   fprintf (fp, "%7.2f (%3.0f%%)",
 659            elapsed.wall,
 660            (total->wall == 0 ? 0 : elapsed.wall / total->wall) * 100);
 661 #endif /* HAVE_WALL_TIME */
 662
 663   /* Print the amount of ggc memory allocated.  */
 664   fprintf (fp, "%8u kB (%3.0f%%)",
 665            (unsigned) (elapsed.ggc_mem >> 10),
 666            (total->ggc_mem == 0
 667             ? 0
 668             : (float) elapsed.ggc_mem / total->ggc_mem) * 100);
 669
 670   putc ('\n', fp);
 671 }
 672
 673 /* Return whether ELAPSED is all zero.  */
 674
 675 bool
 676 timer::all_zero (const timevar_time_def &elapsed)
 677 {
 678   const double tiny = 5e-3;
 679   return (elapsed.user < tiny
 680           && elapsed.sys < tiny
 681           && elapsed.wall < tiny
 682           && elapsed.ggc_mem < GGC_MEM_BOUND);
 683 }
 684
 685 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 686    a special meaning -- it's considered to be the total elapsed time,
 687    for normalizing the others, and is displayed last.  */
 688
 689 void
 690 timer::print (FILE *fp)
 691 {
 692   /* Only print stuff if we have some sort of time information.  */
 693 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 694   unsigned int /* timevar_id_t */ id;
 695   const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
 696   struct timevar_time_def now;
 697
 698   /* Update timing information in case we're calling this from GDB.  */
 699
 700   if (fp == 0)
 701     fp = stderr;
 702
 703   /* What time is it?  */
 704   get_time (&now);
 705
 706   /* If the stack isn't empty, attribute the current elapsed time to
 707      the old topmost element.  */
 708   if (m_stack)
 709     timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
 710
 711   /* Reset the start time; from now on, time is attributed to
 712      TIMEVAR.  */
 713   m_start_time = now;
 714
 715   fprintf (fp, "\n%-35s%16s%14s%14s%18s\n", "Time variable", "usr", "sys",
 716            "wall", "GGC");
 717   if (m_jit_client_items)
 718     fputs ("GCC items:\n", fp);
 719   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 720     {
 721       const timevar_def *tv = &m_timevars[(timevar_id_t) id];
 722
 723       /* Don't print the total execution time here; that goes at the
 724          end.  */
 725       if ((timevar_id_t) id == TV_TOTAL)
 726         continue;
 727
 728       /* Don't print timing variables that were never used.  */
 729       if (!tv->used)
 730         continue;
 731
 732       bool any_children_with_time = false;
 733       if (tv->children)
 734         for (child_map_t::iterator i = tv->children->begin ();
 735              i != tv->children->end (); ++i)
 736           if (! all_zero ((*i).second))
 737             {
 738               any_children_with_time = true;
 739               break;
 740             }
 741
 742       /* Don't print timing variables if we're going to get a row of
 743          zeroes.  Unless there are children with non-zero time.  */
 744       if (! any_children_with_time
 745           && all_zero (tv->elapsed))
 746         continue;
 747
 748       print_row (fp, total, tv->name, tv->elapsed);
 749
 750       if (tv->children)
 751         for (child_map_t::iterator i = tv->children->begin ();
 752              i != tv->children->end (); ++i)
 753           {
 754             timevar_def *tv2 = (*i).first;
 755             /* Don't print timing variables if we're going to get a row of
 756                zeroes.  */
 757             if (! all_zero ((*i).second))
 758               {
 759                 char lname[256];
 760                 snprintf (lname, 256, "`- %s", tv2->name);
 761                 print_row (fp, total, lname, (*i).second);
 762               }
 763           }
 764     }
 765   if (m_jit_client_items)
 766     m_jit_client_items->print (fp, total);
 767
 768   /* Print total time.  */
 769   fprintf (fp, " %-35s:", "TOTAL");
 770 #ifdef HAVE_USER_TIME
 771   fprintf (fp, "%7.2f      ", total->user);
 772 #endif
 773 #ifdef HAVE_SYS_TIME
 774   fprintf (fp, "%8.2f      ", total->sys);
 775 #endif
 776 #ifdef HAVE_WALL_TIME
 777   fprintf (fp, "%8.2f      ", total->wall);
 778 #endif
 779   fprintf (fp, "%9u kB\n", (unsigned) (total->ggc_mem >> 10));
 780
 781   if (CHECKING_P || flag_checking)
 782     fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 783   if (CHECKING_P)
 784     fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
 785 #ifndef ENABLE_ASSERT_CHECKING
 786   fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
 787   fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
 788 #endif
 789
 790 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 791           || defined (HAVE_WALL_TIME) */
 792
 793   validate_phases (fp);
 794 }
 795
 796 /* Get the name of the topmost item.  For use by jit for validating
 797    inputs to gcc_jit_timer_pop.  */
 798 const char *
 799 timer::get_topmost_item_name () const
 800 {
 801   if (m_stack)
 802     return m_stack->timevar->name;
 803   else
 804     return NULL;
 805 }
 806
 807 /* Prints a message to stderr stating that time elapsed in STR is
 808    TOTAL (given in microseconds).  */
 809
 810 void
 811 print_time (const char *str, long total)
 812 {
 813   long all_time = get_run_time ();
 814   fprintf (stderr,
 815            "time in %s: %ld.%06ld (%ld%%)\n",
 816            str, total / 1000000, total % 1000000,
 817            all_time == 0 ? 0
 818            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 819 }