190075Sobrien/* Timing variables for measuring compiler performance. 2169689Skan Copyright (C) 2000, 2003, 2004, 2005 Free Software Foundation, Inc. 390075Sobrien Contributed by Alex Samuel <samuel@codesourcery.com> 490075Sobrien 590075SobrienThis file is part of GCC. 690075Sobrien 790075SobrienGCC is free software; you can redistribute it and/or modify it under 890075Sobrienthe terms of the GNU General Public License as published by the Free 990075SobrienSoftware Foundation; either version 2, or (at your option) any later 1090075Sobrienversion. 1190075Sobrien 1290075SobrienGCC is distributed in the hope that it will be useful, but WITHOUT ANY 1390075SobrienWARRANTY; without even the implied warranty of MERCHANTABILITY or 1490075SobrienFITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 1590075Sobrienfor more details. 1690075Sobrien 1790075SobrienYou should have received a copy of the GNU General Public License 1890075Sobrienalong with GCC; see the file COPYING. If not, write to the Free 19169689SkanSoftware Foundation, 51 Franklin Street, Fifth Floor, Boston, MA 20169689Skan02110-1301, USA. */ 2190075Sobrien 2290075Sobrien#include "config.h" 2390075Sobrien#include "system.h" 2490075Sobrien#ifdef HAVE_SYS_TIMES_H 2590075Sobrien# include <sys/times.h> 2690075Sobrien#endif 2790075Sobrien#ifdef HAVE_SYS_RESOURCE_H 2890075Sobrien#include <sys/resource.h> 2990075Sobrien#endif 30132718Skan#include "coretypes.h" 31132718Skan#include "tm.h" 32132718Skan#include "intl.h" 33132718Skan#include "rtl.h" 34132718Skan#include "toplev.h" 3590075Sobrien 3690075Sobrien#ifndef HAVE_CLOCK_T 3790075Sobrientypedef int clock_t; 3890075Sobrien#endif 3990075Sobrien 4090075Sobrien#ifndef HAVE_STRUCT_TMS 4190075Sobrienstruct tms 4290075Sobrien{ 4390075Sobrien clock_t tms_utime; 4490075Sobrien clock_t tms_stime; 4590075Sobrien clock_t tms_cutime; 4690075Sobrien clock_t tms_cstime; 4790075Sobrien}; 4890075Sobrien#endif 4990075Sobrien 5090075Sobrien#ifndef RUSAGE_SELF 5190075Sobrien# define RUSAGE_SELF 0 5290075Sobrien#endif 5390075Sobrien 5490075Sobrien/* Calculation of scale factor to convert ticks to microseconds. 5590075Sobrien We mustn't use CLOCKS_PER_SEC except with clock(). */ 5690075Sobrien#if HAVE_SYSCONF && defined _SC_CLK_TCK 5790075Sobrien# define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */ 5890075Sobrien#else 5990075Sobrien# ifdef CLK_TCK 6090075Sobrien# define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */ 6190075Sobrien# else 6290075Sobrien# ifdef HZ 6390075Sobrien# define TICKS_PER_SECOND HZ /* traditional UNIX */ 6490075Sobrien# else 6590075Sobrien# define TICKS_PER_SECOND 100 /* often the correct value */ 6690075Sobrien# endif 6790075Sobrien# endif 6890075Sobrien#endif 6990075Sobrien 7090075Sobrien/* Prefer times to getrusage to clock (each gives successively less 7190075Sobrien information). */ 7290075Sobrien#ifdef HAVE_TIMES 73132718Skan# if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES 74132718Skan extern clock_t times (struct tms *); 75132718Skan# endif 7690075Sobrien# define USE_TIMES 7790075Sobrien# define HAVE_USER_TIME 7890075Sobrien# define HAVE_SYS_TIME 7990075Sobrien# define HAVE_WALL_TIME 8090075Sobrien#else 8190075Sobrien#ifdef HAVE_GETRUSAGE 82132718Skan# if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE 83132718Skan extern int getrusage (int, struct rusage *); 84132718Skan# endif 8590075Sobrien# define USE_GETRUSAGE 8690075Sobrien# define HAVE_USER_TIME 8790075Sobrien# define HAVE_SYS_TIME 8890075Sobrien#else 8990075Sobrien#ifdef HAVE_CLOCK 90132718Skan# if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK 91132718Skan extern clock_t clock (void); 92132718Skan# endif 9390075Sobrien# define USE_CLOCK 9490075Sobrien# define HAVE_USER_TIME 9590075Sobrien#endif 9690075Sobrien#endif 9790075Sobrien#endif 9890075Sobrien 9990075Sobrien/* libc is very likely to have snuck a call to sysconf() into one of 10090075Sobrien the underlying constants, and that can be very slow, so we have to 10190075Sobrien precompute them. Whose wonderful idea was it to make all those 10290075Sobrien _constants_ variable at run time, anyway? */ 10390075Sobrien#ifdef USE_TIMES 104132718Skanstatic double ticks_to_msec; 105132718Skan#define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND) 10690075Sobrien#endif 10790075Sobrien 10890075Sobrien#ifdef USE_CLOCK 109132718Skanstatic double clocks_to_msec; 110132718Skan#define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC) 11190075Sobrien#endif 11290075Sobrien 11390075Sobrien#include "flags.h" 11490075Sobrien#include "timevar.h" 11590075Sobrien 116169689Skanbool timevar_enable; 117132718Skan 118169689Skan/* Total amount of memory allocated by garbage collector. */ 119169689Skan 120169689Skansize_t timevar_ggc_mem_total; 121169689Skan 122169689Skan/* The amount of memory that will cause us to report the timevar even 123169689Skan if the time spent is not significant. */ 124169689Skan 125169689Skan#define GGC_MEM_BOUND (1 << 20) 126169689Skan 12790075Sobrien/* See timevar.h for an explanation of timing variables. */ 12890075Sobrien 12990075Sobrien/* A timing variable. */ 13090075Sobrien 13190075Sobrienstruct timevar_def 13290075Sobrien{ 13390075Sobrien /* Elapsed time for this variable. */ 13490075Sobrien struct timevar_time_def elapsed; 13590075Sobrien 13690075Sobrien /* If this variable is timed independently of the timing stack, 13790075Sobrien using timevar_start, this contains the start time. */ 13890075Sobrien struct timevar_time_def start_time; 13990075Sobrien 14090075Sobrien /* The name of this timing variable. */ 14190075Sobrien const char *name; 14290075Sobrien 143132718Skan /* Nonzero if this timing variable is running as a standalone 14490075Sobrien timer. */ 14590075Sobrien unsigned standalone : 1; 14690075Sobrien 147132718Skan /* Nonzero if this timing variable was ever started or pushed onto 14890075Sobrien the timing stack. */ 14990075Sobrien unsigned used : 1; 15090075Sobrien}; 15190075Sobrien 15290075Sobrien/* An element on the timing stack. Elapsed time is attributed to the 15390075Sobrien topmost timing variable on the stack. */ 15490075Sobrien 15590075Sobrienstruct timevar_stack_def 15690075Sobrien{ 15790075Sobrien /* The timing variable at this stack level. */ 15890075Sobrien struct timevar_def *timevar; 15990075Sobrien 16090075Sobrien /* The next lower timing variable context in the stack. */ 16190075Sobrien struct timevar_stack_def *next; 16290075Sobrien}; 16390075Sobrien 16490075Sobrien/* Declared timing variables. Constructed from the contents of 16590075Sobrien timevar.def. */ 16690075Sobrienstatic struct timevar_def timevars[TIMEVAR_LAST]; 16790075Sobrien 16890075Sobrien/* The top of the timing stack. */ 16990075Sobrienstatic struct timevar_stack_def *stack; 17090075Sobrien 17190075Sobrien/* A list of unused (i.e. allocated and subsequently popped) 17290075Sobrien timevar_stack_def instances. */ 17390075Sobrienstatic struct timevar_stack_def *unused_stack_instances; 17490075Sobrien 17590075Sobrien/* The time at which the topmost element on the timing stack was 17690075Sobrien pushed. Time elapsed since then is attributed to the topmost 17790075Sobrien element. */ 17890075Sobrienstatic struct timevar_time_def start_time; 17990075Sobrien 180132718Skanstatic void get_time (struct timevar_time_def *); 181132718Skanstatic void timevar_accumulate (struct timevar_time_def *, 182132718Skan struct timevar_time_def *, 183132718Skan struct timevar_time_def *); 18490075Sobrien 18590075Sobrien/* Fill the current times into TIME. The definition of this function 18690075Sobrien also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and 187117395Skan HAVE_WALL_TIME macros. */ 18890075Sobrien 18990075Sobrienstatic void 190132718Skanget_time (struct timevar_time_def *now) 19190075Sobrien{ 19290075Sobrien now->user = 0; 19390075Sobrien now->sys = 0; 19490075Sobrien now->wall = 0; 195169689Skan now->ggc_mem = timevar_ggc_mem_total; 19690075Sobrien 197132718Skan if (!timevar_enable) 19890075Sobrien return; 19990075Sobrien 20090075Sobrien { 20190075Sobrien#ifdef USE_TIMES 20290075Sobrien struct tms tms; 20390075Sobrien now->wall = times (&tms) * ticks_to_msec; 20490075Sobrien now->user = tms.tms_utime * ticks_to_msec; 20590075Sobrien now->sys = tms.tms_stime * ticks_to_msec; 20690075Sobrien#endif 20790075Sobrien#ifdef USE_GETRUSAGE 20890075Sobrien struct rusage rusage; 20990075Sobrien getrusage (RUSAGE_SELF, &rusage); 21090075Sobrien now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6; 21190075Sobrien now->sys = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6; 21290075Sobrien#endif 21390075Sobrien#ifdef USE_CLOCK 21490075Sobrien now->user = clock () * clocks_to_msec; 21590075Sobrien#endif 21690075Sobrien } 21790075Sobrien} 21890075Sobrien 21990075Sobrien/* Add the difference between STOP_TIME and START_TIME to TIMER. */ 22090075Sobrien 221117395Skanstatic void 222132718Skantimevar_accumulate (struct timevar_time_def *timer, 223132718Skan struct timevar_time_def *start_time, 224132718Skan struct timevar_time_def *stop_time) 22590075Sobrien{ 22690075Sobrien timer->user += stop_time->user - start_time->user; 22790075Sobrien timer->sys += stop_time->sys - start_time->sys; 22890075Sobrien timer->wall += stop_time->wall - start_time->wall; 229169689Skan timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem; 23090075Sobrien} 23190075Sobrien 23290075Sobrien/* Initialize timing variables. */ 23390075Sobrien 23490075Sobrienvoid 235132718Skantimevar_init (void) 23690075Sobrien{ 237132718Skan timevar_enable = true; 23890075Sobrien 23990075Sobrien /* Zero all elapsed times. */ 240132718Skan memset (timevars, 0, sizeof (timevars)); 24190075Sobrien 24290075Sobrien /* Initialize the names of timing variables. */ 24390075Sobrien#define DEFTIMEVAR(identifier__, name__) \ 24490075Sobrien timevars[identifier__].name = name__; 24590075Sobrien#include "timevar.def" 24690075Sobrien#undef DEFTIMEVAR 24790075Sobrien 24890075Sobrien#ifdef USE_TIMES 24990075Sobrien ticks_to_msec = TICKS_TO_MSEC; 25090075Sobrien#endif 25190075Sobrien#ifdef USE_CLOCK 25290075Sobrien clocks_to_msec = CLOCKS_TO_MSEC; 25390075Sobrien#endif 25490075Sobrien} 25590075Sobrien 25690075Sobrien/* Push TIMEVAR onto the timing stack. No further elapsed time is 25790075Sobrien attributed to the previous topmost timing variable on the stack; 25890075Sobrien subsequent elapsed time is attributed to TIMEVAR, until it is 259117395Skan popped or another element is pushed on top. 26090075Sobrien 26190075Sobrien TIMEVAR cannot be running as a standalone timer. */ 26290075Sobrien 26390075Sobrienvoid 264169689Skantimevar_push_1 (timevar_id_t timevar) 26590075Sobrien{ 26690075Sobrien struct timevar_def *tv = &timevars[timevar]; 26790075Sobrien struct timevar_stack_def *context; 26890075Sobrien struct timevar_time_def now; 26990075Sobrien 27090075Sobrien /* Mark this timing variable as used. */ 27190075Sobrien tv->used = 1; 27290075Sobrien 27390075Sobrien /* Can't push a standalone timer. */ 274169689Skan gcc_assert (!tv->standalone); 27590075Sobrien 27690075Sobrien /* What time is it? */ 27790075Sobrien get_time (&now); 27890075Sobrien 27990075Sobrien /* If the stack isn't empty, attribute the current elapsed time to 28090075Sobrien the old topmost element. */ 28190075Sobrien if (stack) 28290075Sobrien timevar_accumulate (&stack->timevar->elapsed, &start_time, &now); 28390075Sobrien 28490075Sobrien /* Reset the start time; from now on, time is attributed to 28590075Sobrien TIMEVAR. */ 28690075Sobrien start_time = now; 28790075Sobrien 28890075Sobrien /* See if we have a previously-allocated stack instance. If so, 28990075Sobrien take it off the list. If not, malloc a new one. */ 290117395Skan if (unused_stack_instances != NULL) 29190075Sobrien { 29290075Sobrien context = unused_stack_instances; 29390075Sobrien unused_stack_instances = unused_stack_instances->next; 29490075Sobrien } 29590075Sobrien else 296169689Skan context = XNEW (struct timevar_stack_def); 29790075Sobrien 29890075Sobrien /* Fill it in and put it on the stack. */ 29990075Sobrien context->timevar = tv; 30090075Sobrien context->next = stack; 30190075Sobrien stack = context; 30290075Sobrien} 30390075Sobrien 30490075Sobrien/* Pop the topmost timing variable element off the timing stack. The 30590075Sobrien popped variable must be TIMEVAR. Elapsed time since the that 30690075Sobrien element was pushed on, or since it was last exposed on top of the 30790075Sobrien stack when the element above it was popped off, is credited to that 30890075Sobrien timing variable. */ 30990075Sobrien 31090075Sobrienvoid 311169689Skantimevar_pop_1 (timevar_id_t timevar) 31290075Sobrien{ 31390075Sobrien struct timevar_time_def now; 31490075Sobrien struct timevar_stack_def *popped = stack; 31590075Sobrien 316169689Skan gcc_assert (&timevars[timevar] == stack->timevar); 317169689Skan 31890075Sobrien /* What time is it? */ 31990075Sobrien get_time (&now); 32090075Sobrien 32190075Sobrien /* Attribute the elapsed time to the element we're popping. */ 32290075Sobrien timevar_accumulate (&popped->timevar->elapsed, &start_time, &now); 32390075Sobrien 32490075Sobrien /* Reset the start time; from now on, time is attributed to the 32590075Sobrien element just exposed on the stack. */ 32690075Sobrien start_time = now; 32790075Sobrien 32890075Sobrien /* Take the item off the stack. */ 32990075Sobrien stack = stack->next; 33090075Sobrien 33190075Sobrien /* Don't delete the stack element; instead, add it to the list of 33290075Sobrien unused elements for later use. */ 33390075Sobrien popped->next = unused_stack_instances; 33490075Sobrien unused_stack_instances = popped; 33590075Sobrien} 33690075Sobrien 33790075Sobrien/* Start timing TIMEVAR independently of the timing stack. Elapsed 33890075Sobrien time until timevar_stop is called for the same timing variable is 33990075Sobrien attributed to TIMEVAR. */ 34090075Sobrien 34190075Sobrienvoid 342132718Skantimevar_start (timevar_id_t timevar) 34390075Sobrien{ 34490075Sobrien struct timevar_def *tv = &timevars[timevar]; 34590075Sobrien 346132718Skan if (!timevar_enable) 34790075Sobrien return; 34890075Sobrien 34990075Sobrien /* Mark this timing variable as used. */ 35090075Sobrien tv->used = 1; 35190075Sobrien 35290075Sobrien /* Don't allow the same timing variable to be started more than 35390075Sobrien once. */ 354169689Skan gcc_assert (!tv->standalone); 35590075Sobrien tv->standalone = 1; 35690075Sobrien 35790075Sobrien get_time (&tv->start_time); 35890075Sobrien} 35990075Sobrien 36090075Sobrien/* Stop timing TIMEVAR. Time elapsed since timevar_start was called 36190075Sobrien is attributed to it. */ 36290075Sobrien 36390075Sobrienvoid 364132718Skantimevar_stop (timevar_id_t timevar) 36590075Sobrien{ 36690075Sobrien struct timevar_def *tv = &timevars[timevar]; 36790075Sobrien struct timevar_time_def now; 36890075Sobrien 369132718Skan if (!timevar_enable) 37090075Sobrien return; 37190075Sobrien 37290075Sobrien /* TIMEVAR must have been started via timevar_start. */ 373169689Skan gcc_assert (tv->standalone); 37490075Sobrien 37590075Sobrien get_time (&now); 37690075Sobrien timevar_accumulate (&tv->elapsed, &tv->start_time, &now); 37790075Sobrien} 37890075Sobrien 37990075Sobrien/* Summarize timing variables to FP. The timing variable TV_TOTAL has 38090075Sobrien a special meaning -- it's considered to be the total elapsed time, 38190075Sobrien for normalizing the others, and is displayed last. */ 38290075Sobrien 38390075Sobrienvoid 384132718Skantimevar_print (FILE *fp) 38590075Sobrien{ 38690075Sobrien /* Only print stuff if we have some sort of time information. */ 38790075Sobrien#if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME) 38890075Sobrien unsigned int /* timevar_id_t */ id; 38990075Sobrien struct timevar_time_def *total = &timevars[TV_TOTAL].elapsed; 39090075Sobrien struct timevar_time_def now; 39190075Sobrien 392132718Skan if (!timevar_enable) 39390075Sobrien return; 39490075Sobrien 39590075Sobrien /* Update timing information in case we're calling this from GDB. */ 39690075Sobrien 39790075Sobrien if (fp == 0) 39890075Sobrien fp = stderr; 39990075Sobrien 40090075Sobrien /* What time is it? */ 40190075Sobrien get_time (&now); 40290075Sobrien 40390075Sobrien /* If the stack isn't empty, attribute the current elapsed time to 40490075Sobrien the old topmost element. */ 40590075Sobrien if (stack) 40690075Sobrien timevar_accumulate (&stack->timevar->elapsed, &start_time, &now); 40790075Sobrien 40890075Sobrien /* Reset the start time; from now on, time is attributed to 40990075Sobrien TIMEVAR. */ 41090075Sobrien start_time = now; 41190075Sobrien 41290075Sobrien fputs (_("\nExecution times (seconds)\n"), fp); 41390075Sobrien for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id) 41490075Sobrien { 41590075Sobrien struct timevar_def *tv = &timevars[(timevar_id_t) id]; 416132718Skan const double tiny = 5e-3; 41790075Sobrien 41890075Sobrien /* Don't print the total execution time here; that goes at the 41990075Sobrien end. */ 42090075Sobrien if ((timevar_id_t) id == TV_TOTAL) 42190075Sobrien continue; 42290075Sobrien 42390075Sobrien /* Don't print timing variables that were never used. */ 42490075Sobrien if (!tv->used) 42590075Sobrien continue; 42690075Sobrien 42790075Sobrien /* Don't print timing variables if we're going to get a row of 42890075Sobrien zeroes. */ 42990075Sobrien if (tv->elapsed.user < tiny 43090075Sobrien && tv->elapsed.sys < tiny 431169689Skan && tv->elapsed.wall < tiny 432169689Skan && tv->elapsed.ggc_mem < GGC_MEM_BOUND) 43390075Sobrien continue; 43490075Sobrien 43590075Sobrien /* The timing variable name. */ 43690075Sobrien fprintf (fp, " %-22s:", tv->name); 43790075Sobrien 43890075Sobrien#ifdef HAVE_USER_TIME 43990075Sobrien /* Print user-mode time for this process. */ 440117395Skan fprintf (fp, "%7.2f (%2.0f%%) usr", 44190075Sobrien tv->elapsed.user, 44290075Sobrien (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100); 44390075Sobrien#endif /* HAVE_USER_TIME */ 44490075Sobrien 44590075Sobrien#ifdef HAVE_SYS_TIME 44690075Sobrien /* Print system-mode time for this process. */ 447117395Skan fprintf (fp, "%7.2f (%2.0f%%) sys", 44890075Sobrien tv->elapsed.sys, 44990075Sobrien (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100); 45090075Sobrien#endif /* HAVE_SYS_TIME */ 45190075Sobrien 45290075Sobrien#ifdef HAVE_WALL_TIME 45390075Sobrien /* Print wall clock time elapsed. */ 454117395Skan fprintf (fp, "%7.2f (%2.0f%%) wall", 45590075Sobrien tv->elapsed.wall, 45690075Sobrien (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100); 45790075Sobrien#endif /* HAVE_WALL_TIME */ 45890075Sobrien 459169689Skan /* Print the amount of ggc memory allocated. */ 460169689Skan fprintf (fp, "%8u kB (%2.0f%%) ggc", 461169689Skan (unsigned) (tv->elapsed.ggc_mem >> 10), 462169689Skan (total->ggc_mem == 0 463169689Skan ? 0 464169689Skan : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100); 465169689Skan 46690075Sobrien putc ('\n', fp); 46790075Sobrien } 46890075Sobrien 46990075Sobrien /* Print total time. */ 47090075Sobrien fputs (_(" TOTAL :"), fp); 47190075Sobrien#ifdef HAVE_USER_TIME 47290075Sobrien fprintf (fp, "%7.2f ", total->user); 473117395Skan#endif 47490075Sobrien#ifdef HAVE_SYS_TIME 47590075Sobrien fprintf (fp, "%7.2f ", total->sys); 47690075Sobrien#endif 47790075Sobrien#ifdef HAVE_WALL_TIME 478169689Skan fprintf (fp, "%7.2f ", total->wall); 47990075Sobrien#endif 480169689Skan fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10)); 481117395Skan 482169689Skan#ifdef ENABLE_CHECKING 483169689Skan fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n"); 484169689Skan fprintf (fp, "Configure with --disable-checking to disable checks.\n"); 485169689Skan#endif 486169689Skan 487117395Skan#endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) 48890075Sobrien || defined (HAVE_WALL_TIME) */ 48990075Sobrien} 49090075Sobrien 49190075Sobrien/* Prints a message to stderr stating that time elapsed in STR is 49290075Sobrien TOTAL (given in microseconds). */ 49390075Sobrien 49490075Sobrienvoid 495132718Skanprint_time (const char *str, long total) 49690075Sobrien{ 49790075Sobrien long all_time = get_run_time (); 49890075Sobrien fprintf (stderr, 49990075Sobrien _("time in %s: %ld.%06ld (%ld%%)\n"), 50090075Sobrien str, total / 1000000, total % 1000000, 501117395Skan all_time == 0 ? 0 502117395Skan : (long) (((100.0 * (double) total) / (double) all_time) + .5)); 50390075Sobrien} 504