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
 365   get_time (&now);
 366   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 367 }
 368
 369 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 370    a special meaning -- it's considered to be the total elapsed time,
 371    for normalizing the others, and is displayed last.  */
 372
 373 void
 374 timevar_print (FILE *fp)
 375 {
 376   /* Only print stuff if we have some sort of time information.  */
 377 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 378   unsigned int /* timevar_id_t */ id;
 379   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 380   struct timevar_time_def now;
 381
 382   if (!timevar_enable)
 383     return;
 384
 385   /* Update timing information in case we're calling this from GDB.  */
 386
 387   if (fp == 0)
 388     fp = stderr;
 389
 390   /* What time is it?  */
 391   get_time (&now);
 392
 393   /* If the stack isn't empty, attribute the current elapsed time to
 394      the old topmost element.  */
 395   if (stack)
 396     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 397
 398   /* Reset the start time; from now on, time is attributed to
 399      TIMEVAR.  */
 400   start_time = now;
 401
 402   fputs ("\nExecution times (seconds)\n", fp);
 403   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 404     {
 405       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 406       const double tiny = 5e-3;
 407
 408       /* Don't print the total execution time here; that goes at the
 409          end.  */
 410       if ((timevar_id_t) id == TV_TOTAL)
 411         continue;
 412
 413       /* Don't print timing variables that were never used.  */
 414       if (!tv->used)
 415         continue;
 416
 417       /* Don't print timing variables if we're going to get a row of
 418          zeroes.  */
 419       if (tv->elapsed.user < tiny
 420           && tv->elapsed.sys < tiny
 421           && tv->elapsed.wall < tiny
 422           && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
 423         continue;
 424
 425       /* The timing variable name.  */
 426       fprintf (fp, " %-22s:", tv->name);
 427
 428 #ifdef HAVE_USER_TIME
 429       /* Print user-mode time for this process.  */
 430       fprintf (fp, "%7.2f (%2.0f%%) usr",
 431                tv->elapsed.user,
 432                (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
 433 #endif /* HAVE_USER_TIME */
 434
 435 #ifdef HAVE_SYS_TIME
 436       /* Print system-mode time for this process.  */
 437       fprintf (fp, "%7.2f (%2.0f%%) sys",
 438                tv->elapsed.sys,
 439                (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
 440 #endif /* HAVE_SYS_TIME */
 441
 442 #ifdef HAVE_WALL_TIME
 443       /* Print wall clock time elapsed.  */
 444       fprintf (fp, "%7.2f (%2.0f%%) wall",
 445                tv->elapsed.wall,
 446                (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
 447 #endif /* HAVE_WALL_TIME */
 448
 449       /* Print the amount of ggc memory allocated.  */
 450       fprintf (fp, "%8u kB (%2.0f%%) ggc",
 451                (unsigned) (tv->elapsed.ggc_mem >> 10),
 452                (total->ggc_mem == 0
 453                 ? 0
 454                 : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
 455
 456       putc ('\n', fp);
 457     }
 458
 459   /* Print total time.  */
 460   fputs (" TOTAL                 :", fp);
 461 #ifdef HAVE_USER_TIME
 462   fprintf (fp, "%7.2f          ", total->user);
 463 #endif
 464 #ifdef HAVE_SYS_TIME
 465   fprintf (fp, "%7.2f          ", total->sys);
 466 #endif
 467 #ifdef HAVE_WALL_TIME
 468   fprintf (fp, "%7.2f           ", total->wall);
 469 #endif
 470   fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10));
 471
 472 #ifdef ENABLE_CHECKING
 473   fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 474   fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
 475 #endif
 476 #ifndef ENABLE_ASSERT_CHECKING
 477   fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
 478   fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
 479 #endif
 480
 481 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 482           || defined (HAVE_WALL_TIME) */
 483 }
 484
 485 /* Prints a message to stderr stating that time elapsed in STR is
 486    TOTAL (given in microseconds).  */
 487
 488 void
 489 print_time (const char *str, long total)
 490 {
 491   long all_time = get_run_time ();
 492   fprintf (stderr,
 493            "time in %s: %ld.%06ld (%ld%%)\n",
 494            str, total / 1000000, total % 1000000,
 495            all_time == 0 ? 0
 496            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 497 }