gcc/timevar.c

   1 /* Timing variables for measuring compiler performance.
   2    Copyright (C) 2000-2014 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   timevar_enable = true;
 227
 228   /* Zero all elapsed times.  */
 229   memset (timevars, 0, sizeof (timevars));
 230
 231   /* Initialize the names of timing variables.  */
 232 #define DEFTIMEVAR(identifier__, name__) \
 233   timevars[identifier__].name = name__;
 234 #include "timevar.def"
 235 #undef DEFTIMEVAR
 236
 237 #ifdef USE_TIMES
 238   ticks_to_msec = TICKS_TO_MSEC;
 239 #endif
 240 #ifdef USE_CLOCK
 241   clocks_to_msec = CLOCKS_TO_MSEC;
 242 #endif
 243 }
 244
 245 /* Push TIMEVAR onto the timing stack.  No further elapsed time is
 246    attributed to the previous topmost timing variable on the stack;
 247    subsequent elapsed time is attributed to TIMEVAR, until it is
 248    popped or another element is pushed on top.
 249
 250    TIMEVAR cannot be running as a standalone timer.  */
 251
 252 void
 253 timevar_push_1 (timevar_id_t timevar)
 254 {
 255   struct timevar_def *tv = &timevars[timevar];
 256   struct timevar_stack_def *context;
 257   struct timevar_time_def now;
 258
 259   /* Mark this timing variable as used.  */
 260   tv->used = 1;
 261
 262   /* Can't push a standalone timer.  */
 263   gcc_assert (!tv->standalone);
 264
 265   /* What time is it?  */
 266   get_time (&now);
 267
 268   /* If the stack isn't empty, attribute the current elapsed time to
 269      the old topmost element.  */
 270   if (stack)
 271     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 272
 273   /* Reset the start time; from now on, time is attributed to
 274      TIMEVAR.  */
 275   start_time = now;
 276
 277   /* See if we have a previously-allocated stack instance.  If so,
 278      take it off the list.  If not, malloc a new one.  */
 279   if (unused_stack_instances != NULL)
 280     {
 281       context = unused_stack_instances;
 282       unused_stack_instances = unused_stack_instances->next;
 283     }
 284   else
 285     context = XNEW (struct timevar_stack_def);
 286
 287   /* Fill it in and put it on the stack.  */
 288   context->timevar = tv;
 289   context->next = stack;
 290   stack = context;
 291 }
 292
 293 /* Pop the topmost timing variable element off the timing stack.  The
 294    popped variable must be TIMEVAR.  Elapsed time since the that
 295    element was pushed on, or since it was last exposed on top of the
 296    stack when the element above it was popped off, is credited to that
 297    timing variable.  */
 298
 299 void
 300 timevar_pop_1 (timevar_id_t timevar)
 301 {
 302   struct timevar_time_def now;
 303   struct timevar_stack_def *popped = stack;
 304
 305   gcc_assert (&timevars[timevar] == stack->timevar);
 306
 307   /* What time is it?  */
 308   get_time (&now);
 309
 310   /* Attribute the elapsed time to the element we're popping.  */
 311   timevar_accumulate (&popped->timevar->elapsed, &start_time, &now);
 312
 313   /* Reset the start time; from now on, time is attributed to the
 314      element just exposed on the stack.  */
 315   start_time = now;
 316
 317   /* Take the item off the stack.  */
 318   stack = stack->next;
 319
 320   /* Don't delete the stack element; instead, add it to the list of
 321      unused elements for later use.  */
 322   popped->next = unused_stack_instances;
 323   unused_stack_instances = popped;
 324 }
 325
 326 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 327    time until timevar_stop is called for the same timing variable is
 328    attributed to TIMEVAR.  */
 329
 330 void
 331 timevar_start (timevar_id_t timevar)
 332 {
 333   struct timevar_def *tv = &timevars[timevar];
 334
 335   if (!timevar_enable)
 336     return;
 337
 338   /* Mark this timing variable as used.  */
 339   tv->used = 1;
 340
 341   /* Don't allow the same timing variable to be started more than
 342      once.  */
 343   gcc_assert (!tv->standalone);
 344   tv->standalone = 1;
 345
 346   get_time (&tv->start_time);
 347 }
 348
 349 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 350    is attributed to it.  */
 351
 352 void
 353 timevar_stop (timevar_id_t timevar)
 354 {
 355   struct timevar_def *tv = &timevars[timevar];
 356   struct timevar_time_def now;
 357
 358   if (!timevar_enable)
 359     return;
 360
 361   /* TIMEVAR must have been started via timevar_start.  */
 362   gcc_assert (tv->standalone);
 363   tv->standalone = 0; /* Enable a restart.  */
 364
 365   get_time (&now);
 366   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 367 }
 368
 369
 370 /* Conditionally start timing TIMEVAR independently of the timing stack.
 371    If the timer is already running, leave it running and return true.
 372    Otherwise, start the timer and return false.
 373    Elapsed time until the corresponding timevar_cond_stop
 374    is called for the same timing variable is attributed to TIMEVAR.  */
 375
 376 bool
 377 timevar_cond_start (timevar_id_t timevar)
 378 {
 379   struct timevar_def *tv = &timevars[timevar];
 380
 381   if (!timevar_enable)
 382     return false;
 383
 384   /* Mark this timing variable as used.  */
 385   tv->used = 1;
 386
 387   if (tv->standalone)
 388     return true;  /* The timevar is already running.  */
 389
 390   /* Don't allow the same timing variable
 391      to be unconditionally started more than once.  */
 392   tv->standalone = 1;
 393
 394   get_time (&tv->start_time);
 395   return false;  /* The timevar was not already running.  */
 396 }
 397
 398 /* Conditionally stop timing TIMEVAR.  The RUNNING parameter must come
 399    from the return value of a dynamically matching timevar_cond_start.
 400    If the timer had already been RUNNING, do nothing.  Otherwise, time
 401    elapsed since timevar_cond_start was called is attributed to it.  */
 402
 403 void
 404 timevar_cond_stop (timevar_id_t timevar, bool running)
 405 {
 406   struct timevar_def *tv;
 407   struct timevar_time_def now;
 408
 409   if (!timevar_enable || running)
 410     return;
 411
 412   tv = &timevars[timevar];
 413
 414   /* TIMEVAR must have been started via timevar_cond_start.  */
 415   gcc_assert (tv->standalone);
 416   tv->standalone = 0; /* Enable a restart.  */
 417
 418   get_time (&now);
 419   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 420 }
 421
 422
 423 /* Validate that phase times are consistent.  */
 424
 425 static void
 426 validate_phases (FILE *fp)
 427 {
 428   unsigned int /* timevar_id_t */ id;
 429   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 430   double phase_user = 0.0;
 431   double phase_sys = 0.0;
 432   double phase_wall = 0.0;
 433   size_t phase_ggc_mem = 0;
 434   static char phase_prefix[] = "phase ";
 435   const double tolerance = 1.000001;  /* One part in a million.  */
 436
 437   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 438     {
 439       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 440
 441       /* Don't evaluate timing variables that were never used.  */
 442       if (!tv->used)
 443         continue;
 444
 445       if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
 446         {
 447           phase_user += tv->elapsed.user;
 448           phase_sys += tv->elapsed.sys;
 449           phase_wall += tv->elapsed.wall;
 450           phase_ggc_mem += tv->elapsed.ggc_mem;
 451         }
 452     }
 453
 454   if (phase_user > total->user * tolerance
 455       || phase_sys > total->sys * tolerance
 456       || phase_wall > total->wall * tolerance
 457       || phase_ggc_mem > total->ggc_mem * tolerance)
 458     {
 459
 460       fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
 461       if (phase_user > total->user)
 462         fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
 463       if (phase_sys > total->sys)
 464         fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
 465       if (phase_wall > total->wall)
 466         fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
 467       if (phase_ggc_mem > total->ggc_mem)
 468         fprintf (fp, "ggc_mem %24lu > %24lu\n", (unsigned long)phase_ggc_mem,
 469                  (unsigned long)total->ggc_mem);
 470       gcc_unreachable ();
 471     }
 472 }
 473
 474
 475 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 476    a special meaning -- it's considered to be the total elapsed time,
 477    for normalizing the others, and is displayed last.  */
 478
 479 void
 480 timevar_print (FILE *fp)
 481 {
 482   /* Only print stuff if we have some sort of time information.  */
 483 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 484   unsigned int /* timevar_id_t */ id;
 485   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 486   struct timevar_time_def now;
 487
 488   if (!timevar_enable)
 489     return;
 490
 491   /* Update timing information in case we're calling this from GDB.  */
 492
 493   if (fp == 0)
 494     fp = stderr;
 495
 496   /* What time is it?  */
 497   get_time (&now);
 498
 499   /* If the stack isn't empty, attribute the current elapsed time to
 500      the old topmost element.  */
 501   if (stack)
 502     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 503
 504   /* Reset the start time; from now on, time is attributed to
 505      TIMEVAR.  */
 506   start_time = now;
 507
 508   fputs ("\nExecution times (seconds)\n", fp);
 509   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 510     {
 511       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 512       const double tiny = 5e-3;
 513
 514       /* Don't print the total execution time here; that goes at the
 515          end.  */
 516       if ((timevar_id_t) id == TV_TOTAL)
 517         continue;
 518
 519       /* Don't print timing variables that were never used.  */
 520       if (!tv->used)
 521         continue;
 522
 523       /* Don't print timing variables if we're going to get a row of
 524          zeroes.  */
 525       if (tv->elapsed.user < tiny
 526           && tv->elapsed.sys < tiny
 527           && tv->elapsed.wall < tiny
 528           && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
 529         continue;
 530
 531       /* The timing variable name.  */
 532       fprintf (fp, " %-24s:", tv->name);
 533
 534 #ifdef HAVE_USER_TIME
 535       /* Print user-mode time for this process.  */
 536       fprintf (fp, "%7.2f (%2.0f%%) usr",
 537                tv->elapsed.user,
 538                (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
 539 #endif /* HAVE_USER_TIME */
 540
 541 #ifdef HAVE_SYS_TIME
 542       /* Print system-mode time for this process.  */
 543       fprintf (fp, "%7.2f (%2.0f%%) sys",
 544                tv->elapsed.sys,
 545                (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
 546 #endif /* HAVE_SYS_TIME */
 547
 548 #ifdef HAVE_WALL_TIME
 549       /* Print wall clock time elapsed.  */
 550       fprintf (fp, "%7.2f (%2.0f%%) wall",
 551                tv->elapsed.wall,
 552                (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
 553 #endif /* HAVE_WALL_TIME */
 554
 555       /* Print the amount of ggc memory allocated.  */
 556       fprintf (fp, "%8u kB (%2.0f%%) ggc",
 557                (unsigned) (tv->elapsed.ggc_mem >> 10),
 558                (total->ggc_mem == 0
 559                 ? 0
 560                 : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
 561
 562       putc ('\n', fp);
 563     }
 564
 565   /* Print total time.  */
 566   fputs (" TOTAL                 :", fp);
 567 #ifdef HAVE_USER_TIME
 568   fprintf (fp, "%7.2f          ", total->user);
 569 #endif
 570 #ifdef HAVE_SYS_TIME
 571   fprintf (fp, "%7.2f          ", total->sys);
 572 #endif
 573 #ifdef HAVE_WALL_TIME
 574   fprintf (fp, "%7.2f           ", total->wall);
 575 #endif
 576   fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10));
 577
 578 #ifdef ENABLE_CHECKING
 579   fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 580   fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
 581 #endif
 582 #ifndef ENABLE_ASSERT_CHECKING
 583   fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
 584   fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
 585 #endif
 586
 587 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 588           || defined (HAVE_WALL_TIME) */
 589
 590   validate_phases (fp);
 591 }
 592
 593 /* Prints a message to stderr stating that time elapsed in STR is
 594    TOTAL (given in microseconds).  */
 595
 596 void
 597 print_time (const char *str, long total)
 598 {
 599   long all_time = get_run_time ();
 600   fprintf (stderr,
 601            "time in %s: %ld.%06ld (%ld%%)\n",
 602            str, total / 1000000, total % 1000000,
 603            all_time == 0 ? 0
 604            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 605 }