gcc/timevar.c

   1 /* Timing variables for measuring compiler performance.
   2    Copyright (C) 2000, 2003, 2004, 2005 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, 51 Franklin Street, Fifth Floor, Boston, MA
  20 02110-1301, 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 bool timevar_enable;
 117
 118 /* Total amount of memory allocated by garbage collector.  */
 119
 120 size_t timevar_ggc_mem_total;
 121
 122 /* The amount of memory that will cause us to report the timevar even
 123    if the time spent is not significant.  */
 124
 125 #define GGC_MEM_BOUND (1 << 20)
 126
 127 /* See timevar.h for an explanation of timing variables.  */
 128
 129 /* A timing variable.  */
 130
 131 struct timevar_def
 132 {
 133   /* Elapsed time for this variable.  */
 134   struct timevar_time_def elapsed;
 135
 136   /* If this variable is timed independently of the timing stack,
 137      using timevar_start, this contains the start time.  */
 138   struct timevar_time_def start_time;
 139
 140   /* The name of this timing variable.  */
 141   const char *name;
 142
 143   /* Nonzero if this timing variable is running as a standalone
 144      timer.  */
 145   unsigned standalone : 1;
 146
 147   /* Nonzero if this timing variable was ever started or pushed onto
 148      the timing stack.  */
 149   unsigned used : 1;
 150 };
 151
 152 /* An element on the timing stack.  Elapsed time is attributed to the
 153    topmost timing variable on the stack.  */
 154
 155 struct timevar_stack_def
 156 {
 157   /* The timing variable at this stack level.  */
 158   struct timevar_def *timevar;
 159
 160   /* The next lower timing variable context in the stack.  */
 161   struct timevar_stack_def *next;
 162 };
 163
 164 /* Declared timing variables.  Constructed from the contents of
 165    timevar.def.  */
 166 static struct timevar_def timevars[TIMEVAR_LAST];
 167
 168 /* The top of the timing stack.  */
 169 static struct timevar_stack_def *stack;
 170
 171 /* A list of unused (i.e. allocated and subsequently popped)
 172    timevar_stack_def instances.  */
 173 static struct timevar_stack_def *unused_stack_instances;
 174
 175 /* The time at which the topmost element on the timing stack was
 176    pushed.  Time elapsed since then is attributed to the topmost
 177    element.  */
 178 static struct timevar_time_def start_time;
 179
 180 static void get_time (struct timevar_time_def *);
 181 static void timevar_accumulate (struct timevar_time_def *,
 182                                 struct timevar_time_def *,
 183                                 struct timevar_time_def *);
 184
 185 /* Fill the current times into TIME.  The definition of this function
 186    also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
 187    HAVE_WALL_TIME macros.  */
 188
 189 static void
 190 get_time (struct timevar_time_def *now)
 191 {
 192   now->user = 0;
 193   now->sys  = 0;
 194   now->wall = 0;
 195   now->ggc_mem = timevar_ggc_mem_total;
 196
 197   if (!timevar_enable)
 198     return;
 199
 200   {
 201 #ifdef USE_TIMES
 202     struct tms tms;
 203     now->wall = times (&tms)  * ticks_to_msec;
 204     now->user = tms.tms_utime * ticks_to_msec;
 205     now->sys  = tms.tms_stime * ticks_to_msec;
 206 #endif
 207 #ifdef USE_GETRUSAGE
 208     struct rusage rusage;
 209     getrusage (RUSAGE_SELF, &rusage);
 210     now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
 211     now->sys  = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
 212 #endif
 213 #ifdef USE_CLOCK
 214     now->user = clock () * clocks_to_msec;
 215 #endif
 216   }
 217 }
 218
 219 /* Add the difference between STOP_TIME and START_TIME to TIMER.  */
 220
 221 static void
 222 timevar_accumulate (struct timevar_time_def *timer,
 223                     struct timevar_time_def *start_time,
 224                     struct timevar_time_def *stop_time)
 225 {
 226   timer->user += stop_time->user - start_time->user;
 227   timer->sys += stop_time->sys - start_time->sys;
 228   timer->wall += stop_time->wall - start_time->wall;
 229   timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
 230 }
 231
 232 /* Initialize timing variables.  */
 233
 234 void
 235 timevar_init (void)
 236 {
 237   timevar_enable = true;
 238
 239   /* Zero all elapsed times.  */
 240   memset (timevars, 0, sizeof (timevars));
 241
 242   /* Initialize the names of timing variables.  */
 243 #define DEFTIMEVAR(identifier__, name__) \
 244   timevars[identifier__].name = name__;
 245 #include "timevar.def"
 246 #undef DEFTIMEVAR
 247
 248 #ifdef USE_TIMES
 249   ticks_to_msec = TICKS_TO_MSEC;
 250 #endif
 251 #ifdef USE_CLOCK
 252   clocks_to_msec = CLOCKS_TO_MSEC;
 253 #endif
 254 }
 255
 256 /* Push TIMEVAR onto the timing stack.  No further elapsed time is
 257    attributed to the previous topmost timing variable on the stack;
 258    subsequent elapsed time is attributed to TIMEVAR, until it is
 259    popped or another element is pushed on top.
 260
 261    TIMEVAR cannot be running as a standalone timer.  */
 262
 263 void
 264 timevar_push_1 (timevar_id_t timevar)
 265 {
 266   struct timevar_def *tv = &timevars[timevar];
 267   struct timevar_stack_def *context;
 268   struct timevar_time_def now;
 269
 270   /* Mark this timing variable as used.  */
 271   tv->used = 1;
 272
 273   /* Can't push a standalone timer.  */
 274   gcc_assert (!tv->standalone);
 275
 276   /* What time is it?  */
 277   get_time (&now);
 278
 279   /* If the stack isn't empty, attribute the current elapsed time to
 280      the old topmost element.  */
 281   if (stack)
 282     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 283
 284   /* Reset the start time; from now on, time is attributed to
 285      TIMEVAR.  */
 286   start_time = now;
 287
 288   /* See if we have a previously-allocated stack instance.  If so,
 289      take it off the list.  If not, malloc a new one.  */
 290   if (unused_stack_instances != NULL)
 291     {
 292       context = unused_stack_instances;
 293       unused_stack_instances = unused_stack_instances->next;
 294     }
 295   else
 296     context = XNEW (struct timevar_stack_def);
 297
 298   /* Fill it in and put it on the stack.  */
 299   context->timevar = tv;
 300   context->next = stack;
 301   stack = context;
 302 }
 303
 304 /* Pop the topmost timing variable element off the timing stack.  The
 305    popped variable must be TIMEVAR.  Elapsed time since the that
 306    element was pushed on, or since it was last exposed on top of the
 307    stack when the element above it was popped off, is credited to that
 308    timing variable.  */
 309
 310 void
 311 timevar_pop_1 (timevar_id_t timevar)
 312 {
 313   struct timevar_time_def now;
 314   struct timevar_stack_def *popped = stack;
 315
 316   gcc_assert (&timevars[timevar] == stack->timevar);
 317
 318   /* What time is it?  */
 319   get_time (&now);
 320
 321   /* Attribute the elapsed time to the element we're popping.  */
 322   timevar_accumulate (&popped->timevar->elapsed, &start_time, &now);
 323
 324   /* Reset the start time; from now on, time is attributed to the
 325      element just exposed on the stack.  */
 326   start_time = now;
 327
 328   /* Take the item off the stack.  */
 329   stack = stack->next;
 330
 331   /* Don't delete the stack element; instead, add it to the list of
 332      unused elements for later use.  */
 333   popped->next = unused_stack_instances;
 334   unused_stack_instances = popped;
 335 }
 336
 337 /* Start timing TIMEVAR independently of the timing stack.  Elapsed
 338    time until timevar_stop is called for the same timing variable is
 339    attributed to TIMEVAR.  */
 340
 341 void
 342 timevar_start (timevar_id_t timevar)
 343 {
 344   struct timevar_def *tv = &timevars[timevar];
 345
 346   if (!timevar_enable)
 347     return;
 348
 349   /* Mark this timing variable as used.  */
 350   tv->used = 1;
 351
 352   /* Don't allow the same timing variable to be started more than
 353      once.  */
 354   gcc_assert (!tv->standalone);
 355   tv->standalone = 1;
 356
 357   get_time (&tv->start_time);
 358 }
 359
 360 /* Stop timing TIMEVAR.  Time elapsed since timevar_start was called
 361    is attributed to it.  */
 362
 363 void
 364 timevar_stop (timevar_id_t timevar)
 365 {
 366   struct timevar_def *tv = &timevars[timevar];
 367   struct timevar_time_def now;
 368
 369   if (!timevar_enable)
 370     return;
 371
 372   /* TIMEVAR must have been started via timevar_start.  */
 373   gcc_assert (tv->standalone);
 374
 375   get_time (&now);
 376   timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
 377 }
 378
 379 /* Summarize timing variables to FP.  The timing variable TV_TOTAL has
 380    a special meaning -- it's considered to be the total elapsed time,
 381    for normalizing the others, and is displayed last.  */
 382
 383 void
 384 timevar_print (FILE *fp)
 385 {
 386   /* Only print stuff if we have some sort of time information.  */
 387 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
 388   unsigned int /* timevar_id_t */ id;
 389   struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed;
 390   struct timevar_time_def now;
 391
 392   if (!timevar_enable)
 393     return;
 394
 395   /* Update timing information in case we're calling this from GDB.  */
 396
 397   if (fp == 0)
 398     fp = stderr;
 399
 400   /* What time is it?  */
 401   get_time (&now);
 402
 403   /* If the stack isn't empty, attribute the current elapsed time to
 404      the old topmost element.  */
 405   if (stack)
 406     timevar_accumulate (&stack->timevar->elapsed, &start_time, &now);
 407
 408   /* Reset the start time; from now on, time is attributed to
 409      TIMEVAR.  */
 410   start_time = now;
 411
 412   fputs (_("\nExecution times (seconds)\n"), fp);
 413   for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
 414     {
 415       struct timevar_def *tv = &timevars[(timevar_id_t) id];
 416       const double tiny = 5e-3;
 417
 418       /* Don't print the total execution time here; that goes at the
 419          end.  */
 420       if ((timevar_id_t) id == TV_TOTAL)
 421         continue;
 422
 423       /* Don't print timing variables that were never used.  */
 424       if (!tv->used)
 425         continue;
 426
 427       /* Don't print timing variables if we're going to get a row of
 428          zeroes.  */
 429       if (tv->elapsed.user < tiny
 430           && tv->elapsed.sys < tiny
 431           && tv->elapsed.wall < tiny
 432           && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
 433         continue;
 434
 435       /* The timing variable name.  */
 436       fprintf (fp, " %-22s:", tv->name);
 437
 438 #ifdef HAVE_USER_TIME
 439       /* Print user-mode time for this process.  */
 440       fprintf (fp, "%7.2f (%2.0f%%) usr",
 441                tv->elapsed.user,
 442                (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
 443 #endif /* HAVE_USER_TIME */
 444
 445 #ifdef HAVE_SYS_TIME
 446       /* Print system-mode time for this process.  */
 447       fprintf (fp, "%7.2f (%2.0f%%) sys",
 448                tv->elapsed.sys,
 449                (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
 450 #endif /* HAVE_SYS_TIME */
 451
 452 #ifdef HAVE_WALL_TIME
 453       /* Print wall clock time elapsed.  */
 454       fprintf (fp, "%7.2f (%2.0f%%) wall",
 455                tv->elapsed.wall,
 456                (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
 457 #endif /* HAVE_WALL_TIME */
 458
 459       /* Print the amount of ggc memory allocated.  */
 460       fprintf (fp, "%8u kB (%2.0f%%) ggc",
 461                (unsigned) (tv->elapsed.ggc_mem >> 10),
 462                (total->ggc_mem == 0
 463                 ? 0
 464                 : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
 465
 466       putc ('\n', fp);
 467     }
 468
 469   /* Print total time.  */
 470   fputs (_(" TOTAL                 :"), fp);
 471 #ifdef HAVE_USER_TIME
 472   fprintf (fp, "%7.2f          ", total->user);
 473 #endif
 474 #ifdef HAVE_SYS_TIME
 475   fprintf (fp, "%7.2f          ", total->sys);
 476 #endif
 477 #ifdef HAVE_WALL_TIME
 478   fprintf (fp, "%7.2f           ", total->wall);
 479 #endif
 480   fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10));
 481
 482 #ifdef ENABLE_CHECKING
 483   fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
 484   fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
 485 #endif
 486 #ifndef ENABLE_ASSERT_CHECKING
 487   fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
 488   fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
 489 #endif
 490
 491 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
 492           || defined (HAVE_WALL_TIME) */
 493 }
 494
 495 /* Prints a message to stderr stating that time elapsed in STR is
 496    TOTAL (given in microseconds).  */
 497
 498 void
 499 print_time (const char *str, long total)
 500 {
 501   long all_time = get_run_time ();
 502   fprintf (stderr,
 503            _("time in %s: %ld.%06ld (%ld%%)\n"),
 504            str, total / 1000000, total % 1000000,
 505            all_time == 0 ? 0
 506            : (long) (((100.0 * (double) total) / (double) all_time) + .5));
 507 }