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