gcc/timevar.c

   1 /* Timing variables for measuring compiler performance.
   2    Copyright (C) 2000, 2003, 2004, 2005, 2007, 2010
   3    Free Software Foundation, Inc.
   4    Contributed by Alex Samuel <samuel@codesourcery.com>
   5
   6 This file is part of GCC.
   7
   8 GCC is free software; you can redistribute it and/or modify it under
   9 the terms of the GNU General Public License as published by the Free
  10 Software Foundation; either version 3, or (at your option) any later
  11 version.
  12
  13 GCC is distributed in the hope that it will be useful, but WITHOUT ANY
  14 WARRANTY; without even the implied warranty of MERCHANTABILITY or
  15 FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  16 for more details.
  17
  18 You should have received a copy of the GNU General Public License
  19 along with GCC; see the file COPYING3.  If not see
  20 <http://www.gnu.org/licenses/>.  */
  21
  22 #include "config.h"
  23 #include "system.h"
  24 #include "timevar.h"
  25
  26 #ifndef HAVE_CLOCK_T
  27 typedef int clock_t;
  28 #endif
  29
  30 #ifndef HAVE_STRUCT_TMS
  31 struct tms
  32 {
  33   clock_t tms_utime;
  34   clock_t tms_stime;
  35   clock_t tms_cutime;
  36   clock_t tms_cstime;
  37 };
  38 #endif
  39
  40 #ifndef RUSAGE_SELF
  41 # define RUSAGE_SELF 0
  42 #endif
  43
  44 /* Calculation of scale factor to convert ticks to microseconds.
  45    We mustn't use CLOCKS_PER_SEC except with clock().  */
  46 #if HAVE_SYSCONF && defined _SC_CLK_TCK
  47 # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
  48 #else
  49 # ifdef CLK_TCK
  50 #  define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
  51 # else
  52 #  ifdef HZ
  53 #   define TICKS_PER_SECOND HZ  /* traditional UNIX */
  54 #  else
  55 #   define TICKS_PER_SECOND 100 /* often the correct value */
  56 #  endif
  57 # endif
  58 #endif
  59
  60 /* Prefer times to getrusage to clock (each gives successively less
  61    information).  */
  62 #ifdef HAVE_TIMES
  63 # if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
  64   extern clock_t times (struct tms *);
  65 # endif
  66 # define USE_TIMES
  67 # define HAVE_USER_TIME
  68 # define HAVE_SYS_TIME
  69 # define HAVE_WALL_TIME
  70 #else
  71 #ifdef HAVE_GETRUSAGE
  72 # if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
  73   extern int getrusage (int, struct rusage *);
  74 # endif
  75 # define USE_GETRUSAGE
  76 # define HAVE_USER_TIME
  77 # define HAVE_SYS_TIME
  78 #else
  79 #ifdef HAVE_CLOCK
  80 # if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
  81   extern clock_t clock (void);
  82 # endif
  83 # define USE_CLOCK
  84 # define HAVE_USER_TIME
  85 #endif
  86 #endif
  87 #endif
  88
  89 /* libc is very likely to have snuck a call to sysconf() into one of
  90    the underlying constants, and that can be very slow, so we have to
  91    precompute them.  Whose wonderful idea was it to make all those
  92    _constants_ variable at run time, anyway?  */
  93 #ifdef USE_TIMES
  94 static double ticks_to_msec;
  95 #define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND)
  96 #endif
  97
  98 #ifdef USE_CLOCK
  99 static double clocks_to_msec;
 100 #define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC)
 101 #endif
 102
 103 /* True if timevars should be used.  In GCC, this happens with
 104    the -ftime-report flag.  */
 105
 106 bool timevar_enable;
 107
 108 /* Total amount of memory allocated by garbage collector.  */
 109
 110 size_t timevar_ggc_mem_total;
 111
 112 /* The amount of memory that will cause us to report the timevar even
 113    if the time spent is not significant.  */
 114
 115 #define GGC_MEM_BOUND (1 << 20)
 116
 117 /* See timevar.h for an explanation of timing variables.  */
 118
 119 /* A timing variable.  */
 120
 121 struct timevar_def
 122 {
 123   /* Elapsed time for this variable.  */
 124   struct timevar_time_def elapsed;
 125
 126   /* If this variable is timed independently of the timing stack,
 127      using timevar_start, this contains the start time.  */
 128   struct timevar_time_def start_time;
 129
 130   /* The name of this timing variable.  */
 131   const char *name;
 132
 133   /* Nonzero if this timing variable is running as a standalone
 134      timer.  */
 135   unsigned standalone : 1;
 136
 137   /* Nonzero if this timing variable was ever started or pushed onto
 138      the timing stack.  */
 139   unsigned used : 1;
 140 };
 141
 142 /* An element on the timing stack.  Elapsed time is attributed to the
 143    topmost timing variable on the stack.  */
 144
 145 struct timevar_stack_def
 146 {
 147   /* The timing variable at this stack level.  */
 148   struct timevar_def *timevar;
 149
 150   /* The next lower timing variable context in the stack.  */
 151   struct timevar_stack_def *next;
 152 };
 153
 154 /* Declared timing variables.  Constructed from the contents of
 155    timevar.def.  */
 156 static struct timevar_def timevars[TIMEVAR_LAST];
 157
 158 /* The top of the timing stack.  */
 159 static struct timevar_stack_def *stack;
 160
 161 /* A list of unused (i.e. allocated and subsequently popped)
 162    timevar_stack_def instances.  */
 163 static struct timevar_stack_def *unused_stack_instances;
 164
 165 /* The time at which the topmost element on the timing stack was
 166    pushed.  Time elapsed since then is attributed to the topmost
 167    element.  */
 168 static struct timevar_time_def start_time;
 169
 170 static void get_time (struct timevar_time_def *);
 171 static void timevar_accumulate (struct timevar_time_def *,
 172                                 struct timevar_time_def *,
 173                                 struct timevar_time_def *);
 174
 175 /* Fill the current times into TIME.  The definition of this function
 176    also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
 177    HAVE_WALL_TIME macros.  */
 178
 179 static void
 180 get_time (struct timevar_time_def *now)
 181 {
 182   now->user = 0;
 183   now->sys  = 0;
 184   now->wall = 0;
 185   now->ggc_mem = timevar_ggc_mem_total;
 186
 187   if (!timevar_enable)
 188     return;
 189
 190   {
 191 #ifdef USE_TIMES
 192     struct tms tms;
 193     now->wall = times (&tms)  * ticks_to_msec;
 194     now->user = tms.tms_utime * ticks_to_msec;
 195     now->sys  = tms.tms_stime * ticks_to_msec;
 196 #endif
 197 #ifdef USE_GETRUSAGE
 198     struct rusage rusage;
 199     getrusage (RUSAGE_SELF, &rusage);
 200     now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
 201     now->sys  = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
 202 #endif
 203 #ifdef USE_CLOCK
 204     now->user = clock () * clocks_to_msec;
 205 #endif
 206   }
 207 }
 208
 209 /* Add the difference between STOP_TIME and START_TIME to TIMER.  */
 210
 211 static void
 212 timevar_accumulate (struct timevar_time_def *timer,
 213                     struct timevar_time_def *start_time,
 214                     struct timevar_time_def *stop_time)
 215 {
 216   timer->user += stop_time->user - start_time->user;
 217   timer->sys += stop_time->sys - start_time->sys;
 218   timer->wall += stop_time->wall - start_time->wall;
 219   timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
 220 }
 221
 222 /* Initialize timing variables.  */
 223
 224 void
 225 timevar_init (void)
 226 {
 227   timevar_enable = true;
 228
 229   /* Zero all elapsed times.  */
 230   memset (timevars, 0, sizeof (timevars));
 231
 232   /* Initialize the names of timing variables.  */
 233 #define DEFTIMEVAR(identifier__, name__) \
 234   timevars[identifier__].name = name__;
 235 #include "timevar.def"
 236 #undef DEFTIMEVAR
 237
 238 #ifdef USE_TIMES
 239   ticks_to_msec = TICKS_TO_MSEC;
 240 #endif
 241 #ifdef USE_CLOCK
 242   clocks_to_msec = CLOCKS_TO_MSEC;
 243 #endif
 244 }
 245
 246 /* Push TIMEVAR onto the timing stack.  No further elapsed time is
 247    attributed to the previous topmost timing variable on the stack;
 248    subsequent elapsed time is attributed to TIMEVAR, until it is
 249    popped or another element is pushed on top.
 250
 251    TIMEVAR cannot be running as a standalone timer.  */
 252
 253 void
 254 timevar_push_1 (timevar_id_t timevar)
 255 {
 256   struct timevar_def *tv = &timevars[timevar];
 257   struct timevar_stack_def *context;
 258   struct timevar_time_def now;
 259
 260   /* Mark this timing variable as used.  */
 261   tv->used = 1;
 262
 263   /* Can't push a standalone timer.  */
 264   gcc_assert (!tv->standalone);
 265
 266   /* What time is it?  */
 267   get_time (&now);
 268
 269   /* If the stack isn't empty, attribute the current elapsed time to
 270      the old topmost element.  */
 271   if (stack)
 272     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 273
 274   /* Reset the start time; from now on, time is attributed to
 275      TIMEVAR.  */
 276   start_time = now;
 277
 278   /* See if we have a previously-allocated stack instance.  If so,
 279      take it off the list.  If not, malloc a new one.  */
 280   if (unused_stack_instances != NULL)
 281     {
 282       context = unused_stack_instances;
 283       unused_stack_instances = unused_stack_instances->next;
 284     }
 285   else
 286     context = XNEW (struct timevar_stack_def);
 287
 288   /* Fill it in and put it on the stack.  */
 289   context->timevar = tv;
 290   context->next = stack;
 291   stack = context;
 292 }
 293
 294 /* Pop the topmost timing variable element off the timing stack.  The
 295    popped variable must be TIMEVAR.  Elapsed time since the that
 296    element was pushed on, or since it was last exposed on top of the
 297    stack when the element above it was popped off, is credited to that
 298    timing variable.  */
 299
 300 void
 301 timevar_pop_1 (timevar_id_t timevar)
 302 {
 303   struct timevar_time_def now;
 304   struct timevar_stack_def *popped = stack;
 305
 306   gcc_assert (&timevars[timevar] == stack->timevar);
 307
 308   /* What time is it?  */
 309   get_time (&now);
 310
 311   /* Attribute the elapsed time to the element we're popping.  */
 312   timevar_accumulate (&popped->timevar->elapsed, &start_time, &now);
 313
 314   /* Reset the start time; from now on, time is attributed to the
 315      element just exposed on the stack.  */
 316   start_time = now;
 317
 318   /* Take the item off the stack.  */
 319   stack = stack->next;
 320
 321   /* Don't delete the stack element; instead, add it to the list of
 322      unused elements for later use.  */
 323   popped->next = unused_stack_instances;
 324   unused_stack_instances = popped;
 325 }
 326
 327 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 328    time until timevar_stop is called for the same timing variable is
 329    attributed to TIMEVAR.  */
 330
 331 void
 332 timevar_start (timevar_id_t timevar)
 333 {
 334   struct timevar_def *tv = &timevars[timevar];
 335
 336   if (!timevar_enable)
 337     return;
 338
 339   /* Mark this timing variable as used.  */
 340   tv->used = 1;
 341
 342   /* Don't allow the same timing variable to be started more than
 343      once.  */
 344   gcc_assert (!tv->standalone);
 345   tv->standalone = 1;
 346
 347   get_time (&tv->start_time);
 348 }
 349
 350 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 351    is attributed to it.  */
 352
 353 void
 354 timevar_stop (timevar_id_t timevar)
 355 {
 356   struct timevar_def *tv = &timevars[timevar];
 357   struct timevar_time_def now;
 358
 359   if (!timevar_enable)
 360     return;
 361
 362   /* TIMEVAR must have been started via timevar_start.  */
 363   gcc_assert (tv->standalone);
 364   tv->standalone = 0; /* Enable a restart.  */
 365
 366   get_time (&now);
 367   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 368 }
 369
 370
 371 /* Conditionally start timing TIMEVAR independently of the timing stack.
 372    If the timer is already running, leave it running and return true.
 373    Otherwise, start the timer and return false.
 374    Elapsed time until the corresponding timevar_cond_stop
 375    is called for the same timing variable is attributed to TIMEVAR.  */
 376
 377 bool
 378 timevar_cond_start (timevar_id_t timevar)
 379 {
 380   struct timevar_def *tv = &timevars[timevar];
 381
 382   if (!timevar_enable)
 383     return false;
 384
 385   /* Mark this timing variable as used.  */
 386   tv->used = 1;
 387
 388   if (tv->standalone)
 389     return true;  /* The timevar is already running.  */
 390
 391   /* Don't allow the same timing variable
 392      to be unconditionally started more than once.  */
 393   tv->standalone = 1;
 394
 395   get_time (&tv->start_time);
 396   return false;  /* The timevar was not already running.  */
 397 }
 398
 399 /* Conditionally stop timing TIMEVAR.  The RUNNING parameter must come
 400    from the return value of a dynamically matching timevar_cond_start.
 401    If the timer had already been RUNNING, do nothing.  Otherwise, time
 402    elapsed since timevar_cond_start was called is attributed to it.  */
 403
 404 void
 405 timevar_cond_stop (timevar_id_t timevar, bool running)
 406 {
 407   struct timevar_def *tv;
 408   struct timevar_time_def now;
 409
 410   if (!timevar_enable || running)
 411     return;
 412
 413   tv = &timevars[timevar];
 414
 415   /* TIMEVAR must have been started via timevar_cond_start.  */
 416   gcc_assert (tv->standalone);
 417   tv->standalone = 0; /* Enable a restart.  */
 418
 419   get_time (&now);
 420   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 421 }
 422
 423
 424 /* Validate that phase times are consistent.  */
 425
 426 static void
 427 validate_phases (FILE *fp)
 428 {
 429   unsigned int /* timevar_id_t */ id;
 430   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 431   double phase_user = 0.0;
 432   double phase_sys = 0.0;
 433   double phase_wall = 0.0;
 434   unsigned phase_ggc_mem = 0;
 435   static char phase_prefix[] = "phase ";
 436   const double tolerance = 1.000001;  /* One part in a million.  */
 437
 438   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 439     {
 440       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 441
 442       /* Don't evaluate timing variables that were never used.  */
 443       if (!tv->used)
 444         continue;
 445
 446       if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
 447         {
 448           phase_user += tv->elapsed.user;
 449           phase_sys += tv->elapsed.sys;
 450           phase_wall += tv->elapsed.wall;
 451           phase_ggc_mem += tv->elapsed.ggc_mem;
 452         }
 453     }
 454
 455   if (phase_user > total->user * tolerance
 456       || phase_sys > total->sys * tolerance
 457       || phase_wall > total->wall * tolerance
 458       || phase_ggc_mem > total->ggc_mem * tolerance)
 459     {
 460
 461       fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
 462       if (phase_user > total->user)
 463         fprintf (fp, "user    %24.18e > %24.18e\n", phase_user, total->user);
 464       if (phase_sys > total->sys)
 465         fprintf (fp, "sys     %24.18e > %24.18e\n", phase_sys, total->sys);
 466       if (phase_wall > total->wall)
 467         fprintf (fp, "wall    %24.18e > %24.18e\n", phase_wall, total->wall);
 468       if (phase_ggc_mem > total->ggc_mem)
 469         fprintf (fp, "ggc_mem %24u > %24u\n", phase_ggc_mem, 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 }