gcc/timevar.c

   1 /* Timing variables for measuring compiler performance.
   2    Copyright (C) 2000-2015 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 "timevar.h"
  24
  25 #ifndef HAVE_CLOCK_T
  26 typedef int clock_t;
  27 #endif
  28
  29 #ifndef HAVE_STRUCT_TMS
  30 struct tms
  31 {
  32   clock_t tms_utime;
  33   clock_t tms_stime;
  34   clock_t tms_cutime;
  35   clock_t tms_cstime;
  36 };
  37 #endif
  38
  39 #ifndef RUSAGE_SELF
  40 # define RUSAGE_SELF 0
  41 #endif
  42
  43 /* Calculation of scale factor to convert ticks to microseconds.
  44    We mustn't use CLOCKS_PER_SEC except with clock().  */
  45 #if HAVE_SYSCONF && defined _SC_CLK_TCK
  46 # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
  47 #else
  48 # ifdef CLK_TCK
  49 #  define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
  50 # else
  51 #  ifdef HZ
  52 #   define TICKS_PER_SECOND HZ  /* traditional UNIX */
  53 #  else
  54 #   define TICKS_PER_SECOND 100 /* often the correct value */
  55 #  endif
  56 # endif
  57 #endif
  58
  59 /* Prefer times to getrusage to clock (each gives successively less
  60    information).  */
  61 #ifdef HAVE_TIMES
  62 # if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
  63   extern clock_t times (struct tms *);
  64 # endif
  65 # define USE_TIMES
  66 # define HAVE_USER_TIME
  67 # define HAVE_SYS_TIME
  68 # define HAVE_WALL_TIME
  69 #else
  70 #ifdef HAVE_GETRUSAGE
  71 # if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
  72   extern int getrusage (int, struct rusage *);
  73 # endif
  74 # define USE_GETRUSAGE
  75 # define HAVE_USER_TIME
  76 # define HAVE_SYS_TIME
  77 #else
  78 #ifdef HAVE_CLOCK
  79 # if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
  80   extern clock_t clock (void);
  81 # endif
  82 # define USE_CLOCK
  83 # define HAVE_USER_TIME
  84 #endif
  85 #endif
  86 #endif
  87
  88 /* libc is very likely to have snuck a call to sysconf() into one of
  89    the underlying constants, and that can be very slow, so we have to
  90    precompute them.  Whose wonderful idea was it to make all those
  91    _constants_ variable at run time, anyway?  */
  92 #ifdef USE_TIMES
  93 static double ticks_to_msec;
  94 #define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND)
  95 #endif
  96
  97 #ifdef USE_CLOCK
  98 static double clocks_to_msec;
  99 #define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC)
 100 #endif
 101
 102 /* True if timevars should be used.  In GCC, this happens with
 103    the -ftime-report flag.  */
 104
 105 bool timevar_enable;
 106
 107 /* Total amount of memory allocated by garbage collector.  */
 108
 109 size_t timevar_ggc_mem_total;
 110
 111 /* The amount of memory that will cause us to report the timevar even
 112    if the time spent is not significant.  */
 113
 114 #define GGC_MEM_BOUND (1 << 20)
 115
 116 /* See timevar.h for an explanation of timing variables.  */
 117
 118 /* A timing variable.  */
 119
 120 struct timevar_def
 121 {
 122   /* Elapsed time for this variable.  */
 123   struct timevar_time_def elapsed;
 124
 125   /* If this variable is timed independently of the timing stack,
 126      using timevar_start, this contains the start time.  */
 127   struct timevar_time_def start_time;
 128
 129   /* The name of this timing variable.  */
 130   const char *name;
 131
 132   /* Nonzero if this timing variable is running as a standalone
 133      timer.  */
 134   unsigned standalone : 1;
 135
 136   /* Nonzero if this timing variable was ever started or pushed onto
 137      the timing stack.  */
 138   unsigned used : 1;
 139 };
 140
 141 /* An element on the timing stack.  Elapsed time is attributed to the
 142    topmost timing variable on the stack.  */
 143
 144 struct timevar_stack_def
 145 {
 146   /* The timing variable at this stack level.  */
 147   struct timevar_def *timevar;
 148
 149   /* The next lower timing variable context in the stack.  */
 150   struct timevar_stack_def *next;
 151 };
 152
 153 /* Declared timing variables.  Constructed from the contents of
 154    timevar.def.  */
 155 static struct timevar_def timevars[TIMEVAR_LAST];
 156
 157 /* The top of the timing stack.  */
 158 static struct timevar_stack_def *stack;
 159
 160 /* A list of unused (i.e. allocated and subsequently popped)
 161    timevar_stack_def instances.  */
 162 static struct timevar_stack_def *unused_stack_instances;
 163
 164 /* The time at which the topmost element on the timing stack was
 165    pushed.  Time elapsed since then is attributed to the topmost
 166    element.  */
 167 static struct timevar_time_def start_time;
 168
 169 static void get_time (struct timevar_time_def *);
 170 static void timevar_accumulate (struct timevar_time_def *,
 171                                 struct timevar_time_def *,
 172                                 struct timevar_time_def *);
 173
 174 /* Fill the current times into TIME.  The definition of this function
 175    also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
 176    HAVE_WALL_TIME macros.  */
 177
 178 static void
 179 get_time (struct timevar_time_def *now)
 180 {
 181   now->user = 0;
 182   now->sys  = 0;
 183   now->wall = 0;
 184   now->ggc_mem = timevar_ggc_mem_total;
 185
 186   if (!timevar_enable)
 187     return;
 188
 189   {
 190 #ifdef USE_TIMES
 191     struct tms tms;
 192     now->wall = times (&tms)  * ticks_to_msec;
 193     now->user = tms.tms_utime * ticks_to_msec;
 194     now->sys  = tms.tms_stime * ticks_to_msec;
 195 #endif
 196 #ifdef USE_GETRUSAGE
 197     struct rusage rusage;
 198     getrusage (RUSAGE_SELF, &rusage);
 199     now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
 200     now->sys  = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
 201 #endif
 202 #ifdef USE_CLOCK
 203     now->user = clock () * clocks_to_msec;
 204 #endif
 205   }
 206 }
 207
 208 /* Add the difference between STOP_TIME and START_TIME to TIMER.  */
 209
 210 static void
 211 timevar_accumulate (struct timevar_time_def *timer,
 212                     struct timevar_time_def *start_time,
 213                     struct timevar_time_def *stop_time)
 214 {
 215   timer->user += stop_time->user - start_time->user;
 216   timer->sys += stop_time->sys - start_time->sys;
 217   timer->wall += stop_time->wall - start_time->wall;
 218   timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
 219 }
 220
 221 /* Initialize timing variables.  */
 222
 223 void
 224 timevar_init (void)
 225 {
 226   if (timevar_enable)
 227     return;
 228
 229   timevar_enable = true;
 230
 231   /* Zero all elapsed times.  */
 232   memset (timevars, 0, sizeof (timevars));
 233
 234   /* Initialize the names of timing variables.  */
 235 #define DEFTIMEVAR(identifier__, name__) \
 236   timevars[identifier__].name = name__;
 237 #include "timevar.def"
 238 #undef DEFTIMEVAR
 239
 240 #ifdef USE_TIMES
 241   ticks_to_msec = TICKS_TO_MSEC;
 242 #endif
 243 #ifdef USE_CLOCK
 244   clocks_to_msec = CLOCKS_TO_MSEC;
 245 #endif
 246 }
 247
 248 /* Push TIMEVAR onto the timing stack.  No further elapsed time is
 249    attributed to the previous topmost timing variable on the stack;
 250    subsequent elapsed time is attributed to TIMEVAR, until it is
 251    popped or another element is pushed on top.
 252
 253    TIMEVAR cannot be running as a standalone timer.  */
 254
 255 void
 256 timevar_push_1 (timevar_id_t timevar)
 257 {
 258   struct timevar_def *tv = &timevars[timevar];
 259   struct timevar_stack_def *context;
 260   struct timevar_time_def now;
 261
 262   /* Mark this timing variable as used.  */
 263   tv->used = 1;
 264
 265   /* Can't push a standalone timer.  */
 266   gcc_assert (!tv->standalone);
 267
 268   /* What time is it?  */
 269   get_time (&now);
 270
 271   /* If the stack isn't empty, attribute the current elapsed time to
 272      the old topmost element.  */
 273   if (stack)
 274     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 275
 276   /* Reset the start time; from now on, time is attributed to
 277      TIMEVAR.  */
 278   start_time = now;
 279
 280   /* See if we have a previously-allocated stack instance.  If so,
 281      take it off the list.  If not, malloc a new one.  */
 282   if (unused_stack_instances != NULL)
 283     {
 284       context = unused_stack_instances;
 285       unused_stack_instances = unused_stack_instances->next;
 286     }
 287   else
 288     context = XNEW (struct timevar_stack_def);
 289
 290   /* Fill it in and put it on the stack.  */
 291   context->timevar = tv;
 292   context->next = stack;
 293   stack = context;
 294 }
 295
 296 /* Pop the topmost timing variable element off the timing stack.  The
 297    popped variable must be TIMEVAR.  Elapsed time since the that
 298    element was pushed on, or since it was last exposed on top of the
 299    stack when the element above it was popped off, is credited to that
 300    timing variable.  */
 301
 302 void
 303 timevar_pop_1 (timevar_id_t timevar)
 304 {
 305   struct timevar_time_def now;
 306   struct timevar_stack_def *popped = stack;
 307
 308   gcc_assert (&timevars[timevar] == stack->timevar);
 309
 310   /* What time is it?  */
 311   get_time (&now);
 312
 313   /* Attribute the elapsed time to the element we're popping.  */
 314   timevar_accumulate (&popped->timevar->elapsed, &start_time, &now);
 315
 316   /* Reset the start time; from now on, time is attributed to the
 317      element just exposed on the stack.  */
 318   start_time = now;
 319
 320   /* Take the item off the stack.  */
 321   stack = stack->next;
 322
 323   /* Don't delete the stack element; instead, add it to the list of
 324      unused elements for later use.  */
 325   popped->next = unused_stack_instances;
 326   unused_stack_instances = popped;
 327 }
 328
 329 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 330    time until timevar_stop is called for the same timing variable is
 331    attributed to TIMEVAR.  */
 332
 333 void
 334 timevar_start (timevar_id_t timevar)
 335 {
 336   struct timevar_def *tv = &timevars[timevar];
 337
 338   if (!timevar_enable)
 339     return;
 340
 341   /* Mark this timing variable as used.  */
 342   tv->used = 1;
 343
 344   /* Don't allow the same timing variable to be started more than
 345      once.  */
 346   gcc_assert (!tv->standalone);
 347   tv->standalone = 1;
 348
 349   get_time (&tv->start_time);
 350 }
 351
 352 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 353    is attributed to it.  */
 354
 355 void
 356 timevar_stop (timevar_id_t timevar)
 357 {
 358   struct timevar_def *tv = &timevars[timevar];
 359   struct timevar_time_def now;
 360
 361   if (!timevar_enable)
 362     return;
 363
 364   /* TIMEVAR must have been started via timevar_start.  */
 365   gcc_assert (tv->standalone);
 366   tv->standalone = 0; /* Enable a restart.  */
 367
 368   get_time (&now);
 369   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 370 }
 371
 372
 373 /* Conditionally start timing TIMEVAR independently of the timing stack.
 374    If the timer is already running, leave it running and return true.
 375    Otherwise, start the timer and return false.
 376    Elapsed time until the corresponding timevar_cond_stop
 377    is called for the same timing variable is attributed to TIMEVAR.  */
 378
 379 bool
 380 timevar_cond_start (timevar_id_t timevar)
 381 {
 382   struct timevar_def *tv = &timevars[timevar];
 383
 384   if (!timevar_enable)
 385     return false;
 386
 387   /* Mark this timing variable as used.  */
 388   tv->used = 1;
 389
 390   if (tv->standalone)
 391     return true;  /* The timevar is already running.  */
 392
 393   /* Don't allow the same timing variable
 394      to be unconditionally started more than once.  */
 395   tv->standalone = 1;
 396
 397   get_time (&tv->start_time);
 398   return false;  /* The timevar was not already running.  */
 399 }
 400
 401 /* Conditionally stop timing TIMEVAR.  The RUNNING parameter must come
 402    from the return value of a dynamically matching timevar_cond_start.
 403    If the timer had already been RUNNING, do nothing.  Otherwise, time
 404    elapsed since timevar_cond_start was called is attributed to it.  */
 405
 406 void
 407 timevar_cond_stop (timevar_id_t timevar, bool running)
 408 {
 409   struct timevar_def *tv;
 410   struct timevar_time_def now;
 411
 412   if (!timevar_enable || running)
 413     return;
 414
 415   tv = &timevars[timevar];
 416
 417   /* TIMEVAR must have been started via timevar_cond_start.  */
 418   gcc_assert (tv->standalone);
 419   tv->standalone = 0; /* Enable a restart.  */
 420
 421   get_time (&now);
 422   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 423 }
 424
 425
 426 /* Validate that phase times are consistent.  */
 427
 428 static void
 429 validate_phases (FILE *fp)
 430 {
 431   unsigned int /* timevar_id_t */ id;
 432   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 433   double phase_user = 0.0;
 434   double phase_sys = 0.0;
 435   double phase_wall = 0.0;
 436   size_t phase_ggc_mem = 0;
 437   static char phase_prefix[] = "phase ";
 438   const double tolerance = 1.000001;  /* One part in a million.  */
 439
 440   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 441     {
 442       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 443
 444       /* Don't evaluate timing variables that were never used.  */
 445       if (!tv->used)
 446         continue;
 447
 448       if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
 449         {
 450           phase_user += tv->elapsed.user;
 451           phase_sys += tv->elapsed.sys;
 452           phase_wall += tv->elapsed.wall;
 453           phase_ggc_mem += tv->elapsed.ggc_mem;
 454         }
 455     }
 456
 457   if (phase_user > total->user * tolerance
 458       || phase_sys > total->sys * tolerance
 459       || phase_wall > total->wall * tolerance
 460       || phase_ggc_mem > total->ggc_mem * tolerance)
 461     {
 462
 463       fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
 464       if (phase_user > total->user)
 465         fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
 466       if (phase_sys > total->sys)
 467         fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
 468       if (phase_wall > total->wall)
 469         fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
 470       if (phase_ggc_mem > total->ggc_mem)
 471         fprintf (fp, "ggc_mem %24lu > %24lu\n", (unsigned long)phase_ggc_mem,
 472                  (unsigned long)total->ggc_mem);
 473       gcc_unreachable ();
 474     }
 475 }
 476
 477
 478 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 479    a special meaning -- it's considered to be the total elapsed time,
 480    for normalizing the others, and is displayed last.  */
 481
 482 void
 483 timevar_print (FILE *fp)
 484 {
 485   /* Only print stuff if we have some sort of time information.  */
 486 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 487   unsigned int /* timevar_id_t */ id;
 488   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 489   struct timevar_time_def now;
 490
 491   if (!timevar_enable)
 492     return;
 493
 494   /* Update timing information in case we're calling this from GDB.  */
 495
 496   if (fp == 0)
 497     fp = stderr;
 498
 499   /* What time is it?  */
 500   get_time (&now);
 501
 502   /* If the stack isn't empty, attribute the current elapsed time to
 503      the old topmost element.  */
 504   if (stack)
 505     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 506
 507   /* Reset the start time; from now on, time is attributed to
 508      TIMEVAR.  */
 509   start_time = now;
 510
 511   fputs ("\nExecution times (seconds)\n", fp);
 512   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 513     {
 514       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 515       const double tiny = 5e-3;
 516
 517       /* Don't print the total execution time here; that goes at the
 518          end.  */
 519       if ((timevar_id_t) id == TV_TOTAL)
 520         continue;
 521
 522       /* Don't print timing variables that were never used.  */
 523       if (!tv->used)
 524         continue;
 525
 526       /* Don't print timing variables if we're going to get a row of
 527          zeroes.  */
 528       if (tv->elapsed.user < tiny
 529           && tv->elapsed.sys < tiny
 530           && tv->elapsed.wall < tiny
 531           && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
 532         continue;
 533
 534       /* The timing variable name.  */
 535       fprintf (fp, " %-24s:", tv->name);
 536
 537 #ifdef HAVE_USER_TIME
 538       /* Print user-mode time for this process.  */
 539       fprintf (fp, "%7.2f (%2.0f%%) usr",
 540                tv->elapsed.user,
 541                (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
 542 #endif /* HAVE_USER_TIME */
 543
 544 #ifdef HAVE_SYS_TIME
 545       /* Print system-mode time for this process.  */
 546       fprintf (fp, "%7.2f (%2.0f%%) sys",
 547                tv->elapsed.sys,
 548                (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
 549 #endif /* HAVE_SYS_TIME */
 550
 551 #ifdef HAVE_WALL_TIME
 552       /* Print wall clock time elapsed.  */
 553       fprintf (fp, "%7.2f (%2.0f%%) wall",
 554                tv->elapsed.wall,
 555                (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
 556 #endif /* HAVE_WALL_TIME */
 557
 558       /* Print the amount of ggc memory allocated.  */
 559       fprintf (fp, "%8u kB (%2.0f%%) ggc",
 560                (unsigned) (tv->elapsed.ggc_mem >> 10),
 561                (total->ggc_mem == 0
 562                 ? 0
 563                 : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
 564
 565       putc ('\n', fp);
 566     }
 567
 568   /* Print total time.  */
 569   fputs (" TOTAL                 :", fp);
 570 #ifdef HAVE_USER_TIME
 571   fprintf (fp, "%7.2f          ", total->user);
 572 #endif
 573 #ifdef HAVE_SYS_TIME
 574   fprintf (fp, "%7.2f          ", total->sys);
 575 #endif
 576 #ifdef HAVE_WALL_TIME
 577   fprintf (fp, "%7.2f           ", total->wall);
 578 #endif
 579   fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10));
 580
 581 #ifdef ENABLE_CHECKING
 582   fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 583   fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
 584 #endif
 585 #ifndef ENABLE_ASSERT_CHECKING
 586   fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
 587   fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
 588 #endif
 589
 590 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 591           || defined (HAVE_WALL_TIME) */
 592
 593   validate_phases (fp);
 594 }
 595
 596 /* Prints a message to stderr stating that time elapsed in STR is
 597    TOTAL (given in microseconds).  */
 598
 599 void
 600 print_time (const char *str, long total)
 601 {
 602   long all_time = get_run_time ();
 603   fprintf (stderr,
 604            "time in %s: %ld.%06ld (%ld%%)\n",
 605            str, total / 1000000, total % 1000000,
 606            all_time == 0 ? 0
 607            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 608 }