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 /* Non-NULL if timevars should be used.  In GCC, this happens with
 103    the -ftime-report flag.  */
 104
 105 timer *g_timer;
 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 static void get_time (struct timevar_time_def *);
 119 static void timevar_accumulate (struct timevar_time_def *,
 120                                 struct timevar_time_def *,
 121                                 struct timevar_time_def *);
 122
 123 /* Fill the current times into TIME.  The definition of this function
 124    also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
 125    HAVE_WALL_TIME macros.  */
 126
 127 static void
 128 get_time (struct timevar_time_def *now)
 129 {
 130   now->user = 0;
 131   now->sys  = 0;
 132   now->wall = 0;
 133   now->ggc_mem = timevar_ggc_mem_total;
 134
 135   {
 136 #ifdef USE_TIMES
 137     struct tms tms;
 138     now->wall = times (&tms)  * ticks_to_msec;
 139     now->user = tms.tms_utime * ticks_to_msec;
 140     now->sys  = tms.tms_stime * ticks_to_msec;
 141 #endif
 142 #ifdef USE_GETRUSAGE
 143     struct rusage rusage;
 144     getrusage (RUSAGE_SELF, &rusage);
 145     now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
 146     now->sys  = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
 147 #endif
 148 #ifdef USE_CLOCK
 149     now->user = clock () * clocks_to_msec;
 150 #endif
 151   }
 152 }
 153
 154 /* Add the difference between STOP_TIME and START_TIME to TIMER.  */
 155
 156 static void
 157 timevar_accumulate (struct timevar_time_def *timer,
 158                     struct timevar_time_def *start_time,
 159                     struct timevar_time_def *stop_time)
 160 {
 161   timer->user += stop_time->user - start_time->user;
 162   timer->sys += stop_time->sys - start_time->sys;
 163   timer->wall += stop_time->wall - start_time->wall;
 164   timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
 165 }
 166
 167 /* Class timer's constructor.  */
 168
 169 timer::timer () :
 170   m_stack (NULL),
 171   m_unused_stack_instances (NULL),
 172   m_start_time ()
 173 {
 174   /* Zero all elapsed times.  */
 175   memset (m_timevars, 0, sizeof (m_timevars));
 176
 177   /* Initialize the names of timing variables.  */
 178 #define DEFTIMEVAR(identifier__, name__) \
 179   m_timevars[identifier__].name = name__;
 180 #include "timevar.def"
 181 #undef DEFTIMEVAR
 182
 183   /* Initialize configuration-specific state.
 184      Ideally this would be one-time initialization.  */
 185 #ifdef USE_TIMES
 186   ticks_to_msec = TICKS_TO_MSEC;
 187 #endif
 188 #ifdef USE_CLOCK
 189   clocks_to_msec = CLOCKS_TO_MSEC;
 190 #endif
 191 }
 192
 193 /* Initialize timing variables.  */
 194
 195 void
 196 timevar_init (void)
 197 {
 198   if (g_timer)
 199     return;
 200
 201   g_timer = new timer ();
 202 }
 203
 204 /* Push TIMEVAR onto the timing stack.  No further elapsed time is
 205    attributed to the previous topmost timing variable on the stack;
 206    subsequent elapsed time is attributed to TIMEVAR, until it is
 207    popped or another element is pushed on top.
 208
 209    TIMEVAR cannot be running as a standalone timer.  */
 210
 211 void
 212 timer::push (timevar_id_t timevar)
 213 {
 214   struct timevar_def *tv = &m_timevars[timevar];
 215   struct timevar_stack_def *context;
 216   struct timevar_time_def now;
 217
 218   /* Mark this timing variable as used.  */
 219   tv->used = 1;
 220
 221   /* Can't push a standalone timer.  */
 222   gcc_assert (!tv->standalone);
 223
 224   /* What time is it?  */
 225   get_time (&now);
 226
 227   /* If the stack isn't empty, attribute the current elapsed time to
 228      the old topmost element.  */
 229   if (m_stack)
 230     timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
 231
 232   /* Reset the start time; from now on, time is attributed to
 233      TIMEVAR.  */
 234   m_start_time = now;
 235
 236   /* See if we have a previously-allocated stack instance.  If so,
 237      take it off the list.  If not, malloc a new one.  */
 238   if (m_unused_stack_instances != NULL)
 239     {
 240       context = m_unused_stack_instances;
 241       m_unused_stack_instances = m_unused_stack_instances->next;
 242     }
 243   else
 244     context = XNEW (struct timevar_stack_def);
 245
 246   /* Fill it in and put it on the stack.  */
 247   context->timevar = tv;
 248   context->next = m_stack;
 249   m_stack = context;
 250 }
 251
 252 /* Pop the topmost timing variable element off the timing stack.  The
 253    popped variable must be TIMEVAR.  Elapsed time since the that
 254    element was pushed on, or since it was last exposed on top of the
 255    stack when the element above it was popped off, is credited to that
 256    timing variable.  */
 257
 258 void
 259 timer::pop (timevar_id_t timevar)
 260 {
 261   struct timevar_time_def now;
 262   struct timevar_stack_def *popped = m_stack;
 263
 264   gcc_assert (&m_timevars[timevar] == m_stack->timevar);
 265
 266   /* What time is it?  */
 267   get_time (&now);
 268
 269   /* Attribute the elapsed time to the element we're popping.  */
 270   timevar_accumulate (&popped->timevar->elapsed, &m_start_time, &now);
 271
 272   /* Reset the start time; from now on, time is attributed to the
 273      element just exposed on the stack.  */
 274   m_start_time = now;
 275
 276   /* Take the item off the stack.  */
 277   m_stack = m_stack->next;
 278
 279   /* Don't delete the stack element; instead, add it to the list of
 280      unused elements for later use.  */
 281   popped->next = m_unused_stack_instances;
 282   m_unused_stack_instances = popped;
 283 }
 284
 285 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 286    time until timevar_stop is called for the same timing variable is
 287    attributed to TIMEVAR.  */
 288
 289 void
 290 timevar_start (timevar_id_t timevar)
 291 {
 292   if (!g_timer)
 293     return;
 294
 295   g_timer->start (timevar);
 296 }
 297
 298 /* See timevar_start above.  */
 299
 300 void
 301 timer::start (timevar_id_t timevar)
 302 {
 303   struct timevar_def *tv = &m_timevars[timevar];
 304
 305   /* Mark this timing variable as used.  */
 306   tv->used = 1;
 307
 308   /* Don't allow the same timing variable to be started more than
 309      once.  */
 310   gcc_assert (!tv->standalone);
 311   tv->standalone = 1;
 312
 313   get_time (&tv->start_time);
 314 }
 315
 316 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 317    is attributed to it.  */
 318
 319 void
 320 timevar_stop (timevar_id_t timevar)
 321 {
 322   if (!g_timer)
 323     return;
 324
 325   g_timer->stop (timevar);
 326 }
 327
 328 /* See timevar_stop above.  */
 329
 330 void
 331 timer::stop (timevar_id_t timevar)
 332 {
 333   struct timevar_def *tv = &m_timevars[timevar];
 334   struct timevar_time_def now;
 335
 336   /* TIMEVAR must have been started via timevar_start.  */
 337   gcc_assert (tv->standalone);
 338   tv->standalone = 0; /* Enable a restart.  */
 339
 340   get_time (&now);
 341   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 342 }
 343
 344
 345 /* Conditionally start timing TIMEVAR independently of the timing stack.
 346    If the timer is already running, leave it running and return true.
 347    Otherwise, start the timer and return false.
 348    Elapsed time until the corresponding timevar_cond_stop
 349    is called for the same timing variable is attributed to TIMEVAR.  */
 350
 351 bool
 352 timevar_cond_start (timevar_id_t timevar)
 353 {
 354   if (!g_timer)
 355     return false;
 356
 357   return g_timer->cond_start (timevar);
 358 }
 359
 360 /* See timevar_cond_start above.  */
 361
 362 bool
 363 timer::cond_start (timevar_id_t timevar)
 364 {
 365   struct timevar_def *tv = &m_timevars[timevar];
 366
 367   /* Mark this timing variable as used.  */
 368   tv->used = 1;
 369
 370   if (tv->standalone)
 371     return true;  /* The timevar is already running.  */
 372
 373   /* Don't allow the same timing variable
 374      to be unconditionally started more than once.  */
 375   tv->standalone = 1;
 376
 377   get_time (&tv->start_time);
 378   return false;  /* The timevar was not already running.  */
 379 }
 380
 381 /* Conditionally stop timing TIMEVAR.  The RUNNING parameter must come
 382    from the return value of a dynamically matching timevar_cond_start.
 383    If the timer had already been RUNNING, do nothing.  Otherwise, time
 384    elapsed since timevar_cond_start was called is attributed to it.  */
 385
 386 void
 387 timevar_cond_stop (timevar_id_t timevar, bool running)
 388 {
 389   if (!g_timer || running)
 390     return;
 391
 392   g_timer->cond_stop (timevar);
 393 }
 394
 395 /* See timevar_cond_stop above.  */
 396
 397 void
 398 timer::cond_stop (timevar_id_t timevar)
 399 {
 400   struct timevar_def *tv;
 401   struct timevar_time_def now;
 402
 403   tv = &m_timevars[timevar];
 404
 405   /* TIMEVAR must have been started via timevar_cond_start.  */
 406   gcc_assert (tv->standalone);
 407   tv->standalone = 0; /* Enable a restart.  */
 408
 409   get_time (&now);
 410   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 411 }
 412
 413
 414 /* Validate that phase times are consistent.  */
 415
 416 void
 417 timer::validate_phases (FILE *fp) const
 418 {
 419   unsigned int /* timevar_id_t */ id;
 420   const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
 421   double phase_user = 0.0;
 422   double phase_sys = 0.0;
 423   double phase_wall = 0.0;
 424   size_t phase_ggc_mem = 0;
 425   static char phase_prefix[] = "phase ";
 426   const double tolerance = 1.000001;  /* One part in a million.  */
 427
 428   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 429     {
 430       const timevar_def *tv = &m_timevars[(timevar_id_t) id];
 431
 432       /* Don't evaluate timing variables that were never used.  */
 433       if (!tv->used)
 434         continue;
 435
 436       if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
 437         {
 438           phase_user += tv->elapsed.user;
 439           phase_sys += tv->elapsed.sys;
 440           phase_wall += tv->elapsed.wall;
 441           phase_ggc_mem += tv->elapsed.ggc_mem;
 442         }
 443     }
 444
 445   if (phase_user > total->user * tolerance
 446       || phase_sys > total->sys * tolerance
 447       || phase_wall > total->wall * tolerance
 448       || phase_ggc_mem > total->ggc_mem * tolerance)
 449     {
 450
 451       fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
 452       if (phase_user > total->user)
 453         fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
 454       if (phase_sys > total->sys)
 455         fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
 456       if (phase_wall > total->wall)
 457         fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
 458       if (phase_ggc_mem > total->ggc_mem)
 459         fprintf (fp, "ggc_mem %24lu > %24lu\n", (unsigned long)phase_ggc_mem,
 460                  (unsigned long)total->ggc_mem);
 461       gcc_unreachable ();
 462     }
 463 }
 464
 465
 466 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 467    a special meaning -- it's considered to be the total elapsed time,
 468    for normalizing the others, and is displayed last.  */
 469
 470 void
 471 timer::print (FILE *fp)
 472 {
 473   /* Only print stuff if we have some sort of time information.  */
 474 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 475   unsigned int /* timevar_id_t */ id;
 476   const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
 477   struct timevar_time_def now;
 478
 479   /* Update timing information in case we're calling this from GDB.  */
 480
 481   if (fp == 0)
 482     fp = stderr;
 483
 484   /* What time is it?  */
 485   get_time (&now);
 486
 487   /* If the stack isn't empty, attribute the current elapsed time to
 488      the old topmost element.  */
 489   if (m_stack)
 490     timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
 491
 492   /* Reset the start time; from now on, time is attributed to
 493      TIMEVAR.  */
 494   m_start_time = now;
 495
 496   fputs ("\nExecution times (seconds)\n", fp);
 497   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 498     {
 499       const timevar_def *tv = &m_timevars[(timevar_id_t) id];
 500       const double tiny = 5e-3;
 501
 502       /* Don't print the total execution time here; that goes at the
 503          end.  */
 504       if ((timevar_id_t) id == TV_TOTAL)
 505         continue;
 506
 507       /* Don't print timing variables that were never used.  */
 508       if (!tv->used)
 509         continue;
 510
 511       /* Don't print timing variables if we're going to get a row of
 512          zeroes.  */
 513       if (tv->elapsed.user < tiny
 514           && tv->elapsed.sys < tiny
 515           && tv->elapsed.wall < tiny
 516           && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
 517         continue;
 518
 519       /* The timing variable name.  */
 520       fprintf (fp, " %-24s:", tv->name);
 521
 522 #ifdef HAVE_USER_TIME
 523       /* Print user-mode time for this process.  */
 524       fprintf (fp, "%7.2f (%2.0f%%) usr",
 525                tv->elapsed.user,
 526                (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
 527 #endif /* HAVE_USER_TIME */
 528
 529 #ifdef HAVE_SYS_TIME
 530       /* Print system-mode time for this process.  */
 531       fprintf (fp, "%7.2f (%2.0f%%) sys",
 532                tv->elapsed.sys,
 533                (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
 534 #endif /* HAVE_SYS_TIME */
 535
 536 #ifdef HAVE_WALL_TIME
 537       /* Print wall clock time elapsed.  */
 538       fprintf (fp, "%7.2f (%2.0f%%) wall",
 539                tv->elapsed.wall,
 540                (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
 541 #endif /* HAVE_WALL_TIME */
 542
 543       /* Print the amount of ggc memory allocated.  */
 544       fprintf (fp, "%8u kB (%2.0f%%) ggc",
 545                (unsigned) (tv->elapsed.ggc_mem >> 10),
 546                (total->ggc_mem == 0
 547                 ? 0
 548                 : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
 549
 550       putc ('\n', fp);
 551     }
 552
 553   /* Print total time.  */
 554   fputs (" TOTAL                 :", fp);
 555 #ifdef HAVE_USER_TIME
 556   fprintf (fp, "%7.2f          ", total->user);
 557 #endif
 558 #ifdef HAVE_SYS_TIME
 559   fprintf (fp, "%7.2f          ", total->sys);
 560 #endif
 561 #ifdef HAVE_WALL_TIME
 562   fprintf (fp, "%7.2f           ", total->wall);
 563 #endif
 564   fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10));
 565
 566 #ifdef ENABLE_CHECKING
 567   fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 568   fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
 569 #endif
 570 #ifndef ENABLE_ASSERT_CHECKING
 571   fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
 572   fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
 573 #endif
 574
 575 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 576           || defined (HAVE_WALL_TIME) */
 577
 578   validate_phases (fp);
 579 }
 580
 581 /* Prints a message to stderr stating that time elapsed in STR is
 582    TOTAL (given in microseconds).  */
 583
 584 void
 585 print_time (const char *str, long total)
 586 {
 587   long all_time = get_run_time ();
 588   fprintf (stderr,
 589            "time in %s: %ld.%06ld (%ld%%)\n",
 590            str, total / 1000000, total % 1000000,
 591            all_time == 0 ? 0
 592            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 593 }