gcc/timevar.c

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