gcc/timevar.c

   1 /* Timing variables for measuring compiler performance.
   2    Copyright (C) 2000, 2003, 2004 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 2, 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 COPYING.  If not, write to the Free
  19 Software Foundation, 59 Temple Place - Suite 330, Boston, MA
  20 02111-1307, USA.  */
  21
  22 #include "config.h"
  23 #include "system.h"
  24 #ifdef HAVE_SYS_TIMES_H
  25 # include <sys/times.h>
  26 #endif
  27 #ifdef HAVE_SYS_RESOURCE_H
  28 #include <sys/resource.h>
  29 #endif
  30 #include "coretypes.h"
  31 #include "tm.h"
  32 #include "intl.h"
  33 #include "rtl.h"
  34 #include "toplev.h"
  35
  36 #ifndef HAVE_CLOCK_T
  37 typedef int clock_t;
  38 #endif
  39
  40 #ifndef HAVE_STRUCT_TMS
  41 struct tms
  42 {
  43   clock_t tms_utime;
  44   clock_t tms_stime;
  45   clock_t tms_cutime;
  46   clock_t tms_cstime;
  47 };
  48 #endif
  49
  50 #ifndef RUSAGE_SELF
  51 # define RUSAGE_SELF 0
  52 #endif
  53
  54 /* Calculation of scale factor to convert ticks to microseconds.
  55    We mustn't use CLOCKS_PER_SEC except with clock().  */
  56 #if HAVE_SYSCONF && defined _SC_CLK_TCK
  57 # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
  58 #else
  59 # ifdef CLK_TCK
  60 #  define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
  61 # else
  62 #  ifdef HZ
  63 #   define TICKS_PER_SECOND HZ  /* traditional UNIX */
  64 #  else
  65 #   define TICKS_PER_SECOND 100 /* often the correct value */
  66 #  endif
  67 # endif
  68 #endif
  69
  70 /* Prefer times to getrusage to clock (each gives successively less
  71    information).  */
  72 #ifdef HAVE_TIMES
  73 # if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
  74   extern clock_t times (struct tms *);
  75 # endif
  76 # define USE_TIMES
  77 # define HAVE_USER_TIME
  78 # define HAVE_SYS_TIME
  79 # define HAVE_WALL_TIME
  80 #else
  81 #ifdef HAVE_GETRUSAGE
  82 # if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
  83   extern int getrusage (int, struct rusage *);
  84 # endif
  85 # define USE_GETRUSAGE
  86 # define HAVE_USER_TIME
  87 # define HAVE_SYS_TIME
  88 #else
  89 #ifdef HAVE_CLOCK
  90 # if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
  91   extern clock_t clock (void);
  92 # endif
  93 # define USE_CLOCK
  94 # define HAVE_USER_TIME
  95 #endif
  96 #endif
  97 #endif
  98
  99 /* libc is very likely to have snuck a call to sysconf() into one of
 100    the underlying constants, and that can be very slow, so we have to
 101    precompute them.  Whose wonderful idea was it to make all those
 102    _constants_ variable at run time, anyway?  */
 103 #ifdef USE_TIMES
 104 static double ticks_to_msec;
 105 #define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND)
 106 #endif
 107
 108 #ifdef USE_CLOCK
 109 static double clocks_to_msec;
 110 #define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC)
 111 #endif
 112
 113 #include "flags.h"
 114 #include "timevar.h"
 115
 116 static bool timevar_enable;
 117
 118 /* See timevar.h for an explanation of timing variables.  */
 119
 120 /* A timing variable.  */
 121
 122 struct timevar_def
 123 {
 124   /* Elapsed time for this variable.  */
 125   struct timevar_time_def elapsed;
 126
 127   /* If this variable is timed independently of the timing stack,
 128      using timevar_start, this contains the start time.  */
 129   struct timevar_time_def start_time;
 130
 131   /* The name of this timing variable.  */
 132   const char *name;
 133
 134   /* Nonzero if this timing variable is running as a standalone
 135      timer.  */
 136   unsigned standalone : 1;
 137
 138   /* Nonzero if this timing variable was ever started or pushed onto
 139      the timing stack.  */
 140   unsigned used : 1;
 141 };
 142
 143 /* An element on the timing stack.  Elapsed time is attributed to the
 144    topmost timing variable on the stack.  */
 145
 146 struct timevar_stack_def
 147 {
 148   /* The timing variable at this stack level.  */
 149   struct timevar_def *timevar;
 150
 151   /* The next lower timing variable context in the stack.  */
 152   struct timevar_stack_def *next;
 153 };
 154
 155 /* Declared timing variables.  Constructed from the contents of
 156    timevar.def.  */
 157 static struct timevar_def timevars[TIMEVAR_LAST];
 158
 159 /* The top of the timing stack.  */
 160 static struct timevar_stack_def *stack;
 161
 162 /* A list of unused (i.e. allocated and subsequently popped)
 163    timevar_stack_def instances.  */
 164 static struct timevar_stack_def *unused_stack_instances;
 165
 166 /* The time at which the topmost element on the timing stack was
 167    pushed.  Time elapsed since then is attributed to the topmost
 168    element.  */
 169 static struct timevar_time_def start_time;
 170
 171 static void get_time (struct timevar_time_def *);
 172 static void timevar_accumulate (struct timevar_time_def *,
 173                                 struct timevar_time_def *,
 174                                 struct timevar_time_def *);
 175
 176 /* Fill the current times into TIME.  The definition of this function
 177    also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
 178    HAVE_WALL_TIME macros.  */
 179
 180 static void
 181 get_time (struct timevar_time_def *now)
 182 {
 183   now->user = 0;
 184   now->sys  = 0;
 185   now->wall = 0;
 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 }
 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 (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   if (!timevar_enable)
 260     return;
 261
 262   /* Mark this timing variable as used.  */
 263   tv->used = 1;
 264
 265   /* Can't push a standalone timer.  */
 266   if (tv->standalone)
 267     abort ();
 268
 269   /* What time is it?  */
 270   get_time (&now);
 271
 272   /* If the stack isn't empty, attribute the current elapsed time to
 273      the old topmost element.  */
 274   if (stack)
 275     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 276
 277   /* Reset the start time; from now on, time is attributed to
 278      TIMEVAR.  */
 279   start_time = now;
 280
 281   /* See if we have a previously-allocated stack instance.  If so,
 282      take it off the list.  If not, malloc a new one.  */
 283   if (unused_stack_instances != NULL)
 284     {
 285       context = unused_stack_instances;
 286       unused_stack_instances = unused_stack_instances->next;
 287     }
 288   else
 289     context = xmalloc (sizeof (struct timevar_stack_def));
 290
 291   /* Fill it in and put it on the stack.  */
 292   context->timevar = tv;
 293   context->next = stack;
 294   stack = context;
 295 }
 296
 297 /* Pop the topmost timing variable element off the timing stack.  The
 298    popped variable must be TIMEVAR.  Elapsed time since the that
 299    element was pushed on, or since it was last exposed on top of the
 300    stack when the element above it was popped off, is credited to that
 301    timing variable.  */
 302
 303 void
 304 timevar_pop (timevar_id_t timevar)
 305 {
 306   struct timevar_time_def now;
 307   struct timevar_stack_def *popped = stack;
 308
 309   if (!timevar_enable)
 310     return;
 311
 312   if (&timevars[timevar] != stack->timevar)
 313     {
 314       sorry ("cannot timevar_pop '%s' when top of timevars stack is '%s'",
 315              timevars[timevar].name, stack->timevar->name);
 316       abort ();
 317     }
 318
 319   /* What time is it?  */
 320   get_time (&now);
 321
 322   /* Attribute the elapsed time to the element we're popping.  */
 323   timevar_accumulate (&popped->timevar->elapsed, &start_time, &now);
 324
 325   /* Reset the start time; from now on, time is attributed to the
 326      element just exposed on the stack.  */
 327   start_time = now;
 328
 329   /* Take the item off the stack.  */
 330   stack = stack->next;
 331
 332   /* Don't delete the stack element; instead, add it to the list of
 333      unused elements for later use.  */
 334   popped->next = unused_stack_instances;
 335   unused_stack_instances = popped;
 336 }
 337
 338 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 339    time until timevar_stop is called for the same timing variable is
 340    attributed to TIMEVAR.  */
 341
 342 void
 343 timevar_start (timevar_id_t timevar)
 344 {
 345   struct timevar_def *tv = &timevars[timevar];
 346
 347   if (!timevar_enable)
 348     return;
 349
 350   /* Mark this timing variable as used.  */
 351   tv->used = 1;
 352
 353   /* Don't allow the same timing variable to be started more than
 354      once.  */
 355   if (tv->standalone)
 356     abort ();
 357   tv->standalone = 1;
 358
 359   get_time (&tv->start_time);
 360 }
 361
 362 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 363    is attributed to it.  */
 364
 365 void
 366 timevar_stop (timevar_id_t timevar)
 367 {
 368   struct timevar_def *tv = &timevars[timevar];
 369   struct timevar_time_def now;
 370
 371   if (!timevar_enable)
 372     return;
 373
 374   /* TIMEVAR must have been started via timevar_start.  */
 375   if (!tv->standalone)
 376     abort ();
 377
 378   get_time (&now);
 379   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 380 }
 381
 382 /* Fill the elapsed time for TIMEVAR into ELAPSED.  Returns
 383    update-to-date information even if TIMEVAR is currently running.  */
 384
 385 void
 386 timevar_get (timevar_id_t timevar, struct timevar_time_def *elapsed)
 387 {
 388   struct timevar_def *tv = &timevars[timevar];
 389   struct timevar_time_def now;
 390
 391   *elapsed = tv->elapsed;
 392
 393   /* Is TIMEVAR currently running as a standalone timer?  */
 394   if (tv->standalone)
 395     {
 396       get_time (&now);
 397       timevar_accumulate (elapsed, &tv->start_time, &now);
 398     }
 399   /* Or is TIMEVAR at the top of the timer stack?  */
 400   else if (stack->timevar == tv)
 401     {
 402       get_time (&now);
 403       timevar_accumulate (elapsed, &start_time, &now);
 404     }
 405 }
 406
 407 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 408    a special meaning -- it's considered to be the total elapsed time,
 409    for normalizing the others, and is displayed last.  */
 410
 411 void
 412 timevar_print (FILE *fp)
 413 {
 414   /* Only print stuff if we have some sort of time information.  */
 415 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 416   unsigned int /* timevar_id_t */ id;
 417   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 418   struct timevar_time_def now;
 419
 420   if (!timevar_enable)
 421     return;
 422
 423   /* Update timing information in case we're calling this from GDB.  */
 424
 425   if (fp == 0)
 426     fp = stderr;
 427
 428   /* What time is it?  */
 429   get_time (&now);
 430
 431   /* If the stack isn't empty, attribute the current elapsed time to
 432      the old topmost element.  */
 433   if (stack)
 434     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 435
 436   /* Reset the start time; from now on, time is attributed to
 437      TIMEVAR.  */
 438   start_time = now;
 439
 440   fputs (_("\nExecution times (seconds)\n"), fp);
 441   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 442     {
 443       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 444       const double tiny = 5e-3;
 445
 446       /* Don't print the total execution time here; that goes at the
 447          end.  */
 448       if ((timevar_id_t) id == TV_TOTAL)
 449         continue;
 450
 451       /* Don't print timing variables that were never used.  */
 452       if (!tv->used)
 453         continue;
 454
 455       /* Don't print timing variables if we're going to get a row of
 456          zeroes.  */
 457       if (tv->elapsed.user < tiny
 458           && tv->elapsed.sys < tiny
 459           && tv->elapsed.wall < tiny)
 460         continue;
 461
 462       /* The timing variable name.  */
 463       fprintf (fp, " %-22s:", tv->name);
 464
 465 #ifdef HAVE_USER_TIME
 466       /* Print user-mode time for this process.  */
 467       fprintf (fp, "%7.2f (%2.0f%%) usr",
 468                tv->elapsed.user,
 469                (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
 470 #endif /* HAVE_USER_TIME */
 471
 472 #ifdef HAVE_SYS_TIME
 473       /* Print system-mode time for this process.  */
 474       fprintf (fp, "%7.2f (%2.0f%%) sys",
 475                tv->elapsed.sys,
 476                (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
 477 #endif /* HAVE_SYS_TIME */
 478
 479 #ifdef HAVE_WALL_TIME
 480       /* Print wall clock time elapsed.  */
 481       fprintf (fp, "%7.2f (%2.0f%%) wall",
 482                tv->elapsed.wall,
 483                (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
 484 #endif /* HAVE_WALL_TIME */
 485
 486       putc ('\n', fp);
 487     }
 488
 489   /* Print total time.  */
 490   fputs (_(" TOTAL                 :"), fp);
 491 #ifdef HAVE_USER_TIME
 492   fprintf (fp, "%7.2f          ", total->user);
 493 #endif
 494 #ifdef HAVE_SYS_TIME
 495   fprintf (fp, "%7.2f          ", total->sys);
 496 #endif
 497 #ifdef HAVE_WALL_TIME
 498   fprintf (fp, "%7.2f\n", total->wall);
 499 #endif
 500
 501 #ifdef ENABLE_CHECKING
 502   fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 503   fprintf (fp, "Configure with --disable-checking to disable checks.\n");
 504 #endif
 505
 506 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 507           || defined (HAVE_WALL_TIME) */
 508 }
 509
 510 /* Prints a message to stderr stating that time elapsed in STR is
 511    TOTAL (given in microseconds).  */
 512
 513 void
 514 print_time (const char *str, long total)
 515 {
 516   long all_time = get_run_time ();
 517   fprintf (stderr,
 518            _("time in %s: %ld.%06ld (%ld%%)\n"),
 519            str, total / 1000000, total % 1000000,
 520            all_time == 0 ? 0
 521            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 522 }