gcc/
[official-gcc.git] / gcc / timevar.c
blob76ad22ac9ef32fb8f7a35255106f26b2dd01d13c
1 /* Timing variables for measuring compiler performance.
2 Copyright (C) 2000-2015 Free Software Foundation, Inc.
3 Contributed by Alex Samuel <samuel@codesourcery.com>
5 This file is part of GCC.
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.
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.
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/>. */
21 #include "config.h"
22 #include "system.h"
23 #include "timevar.h"
25 #ifndef HAVE_CLOCK_T
26 typedef int clock_t;
27 #endif
29 #ifndef HAVE_STRUCT_TMS
30 struct tms
32 clock_t tms_utime;
33 clock_t tms_stime;
34 clock_t tms_cutime;
35 clock_t tms_cstime;
37 #endif
39 #ifndef RUSAGE_SELF
40 # define RUSAGE_SELF 0
41 #endif
43 /* Calculation of scale factor to convert ticks to microseconds.
44 We mustn't use CLOCKS_PER_SEC except with clock(). */
45 #if HAVE_SYSCONF && defined _SC_CLK_TCK
46 # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
47 #else
48 # ifdef CLK_TCK
49 # define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
50 # else
51 # ifdef HZ
52 # define TICKS_PER_SECOND HZ /* traditional UNIX */
53 # else
54 # define TICKS_PER_SECOND 100 /* often the correct value */
55 # endif
56 # endif
57 #endif
59 /* Prefer times to getrusage to clock (each gives successively less
60 information). */
61 #ifdef HAVE_TIMES
62 # if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
63 extern clock_t times (struct tms *);
64 # endif
65 # define USE_TIMES
66 # define HAVE_USER_TIME
67 # define HAVE_SYS_TIME
68 # define HAVE_WALL_TIME
69 #else
70 #ifdef HAVE_GETRUSAGE
71 # if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
72 extern int getrusage (int, struct rusage *);
73 # endif
74 # define USE_GETRUSAGE
75 # define HAVE_USER_TIME
76 # define HAVE_SYS_TIME
77 #else
78 #ifdef HAVE_CLOCK
79 # if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
80 extern clock_t clock (void);
81 # endif
82 # define USE_CLOCK
83 # define HAVE_USER_TIME
84 #endif
85 #endif
86 #endif
88 /* libc is very likely to have snuck a call to sysconf() into one of
89 the underlying constants, and that can be very slow, so we have to
90 precompute them. Whose wonderful idea was it to make all those
91 _constants_ variable at run time, anyway? */
92 #ifdef USE_TIMES
93 static double ticks_to_msec;
94 #define TICKS_TO_MSEC (1 / (double)TICKS_PER_SECOND)
95 #endif
97 #ifdef USE_CLOCK
98 static double clocks_to_msec;
99 #define CLOCKS_TO_MSEC (1 / (double)CLOCKS_PER_SEC)
100 #endif
102 /* Non-NULL if timevars should be used. In GCC, this happens with
103 the -ftime-report flag. */
105 timer *g_timer;
107 /* Total amount of memory allocated by garbage collector. */
109 size_t timevar_ggc_mem_total;
111 /* The amount of memory that will cause us to report the timevar even
112 if the time spent is not significant. */
114 #define GGC_MEM_BOUND (1 << 20)
116 /* See timevar.h for an explanation of timing variables. */
118 static void get_time (struct timevar_time_def *);
119 static void timevar_accumulate (struct timevar_time_def *,
120 struct timevar_time_def *,
121 struct timevar_time_def *);
123 /* Fill the current times into TIME. The definition of this function
124 also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
125 HAVE_WALL_TIME macros. */
127 static void
128 get_time (struct timevar_time_def *now)
130 now->user = 0;
131 now->sys = 0;
132 now->wall = 0;
133 now->ggc_mem = timevar_ggc_mem_total;
136 #ifdef USE_TIMES
137 struct tms tms;
138 now->wall = times (&tms) * ticks_to_msec;
139 now->user = tms.tms_utime * ticks_to_msec;
140 now->sys = tms.tms_stime * ticks_to_msec;
141 #endif
142 #ifdef USE_GETRUSAGE
143 struct rusage rusage;
144 getrusage (RUSAGE_SELF, &rusage);
145 now->user = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec * 1e-6;
146 now->sys = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec * 1e-6;
147 #endif
148 #ifdef USE_CLOCK
149 now->user = clock () * clocks_to_msec;
150 #endif
154 /* Add the difference between STOP_TIME and START_TIME to TIMER. */
156 static void
157 timevar_accumulate (struct timevar_time_def *timer,
158 struct timevar_time_def *start_time,
159 struct timevar_time_def *stop_time)
161 timer->user += stop_time->user - start_time->user;
162 timer->sys += stop_time->sys - start_time->sys;
163 timer->wall += stop_time->wall - start_time->wall;
164 timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
167 /* Class timer's constructor. */
169 timer::timer () :
170 m_stack (NULL),
171 m_unused_stack_instances (NULL),
172 m_start_time ()
174 /* Zero all elapsed times. */
175 memset (m_timevars, 0, sizeof (m_timevars));
177 /* Initialize the names of timing variables. */
178 #define DEFTIMEVAR(identifier__, name__) \
179 m_timevars[identifier__].name = name__;
180 #include "timevar.def"
181 #undef DEFTIMEVAR
183 /* Initialize configuration-specific state.
184 Ideally this would be one-time initialization. */
185 #ifdef USE_TIMES
186 ticks_to_msec = TICKS_TO_MSEC;
187 #endif
188 #ifdef USE_CLOCK
189 clocks_to_msec = CLOCKS_TO_MSEC;
190 #endif
193 /* Initialize timing variables. */
195 void
196 timevar_init (void)
198 if (g_timer)
199 return;
201 g_timer = new timer ();
204 /* Push TIMEVAR onto the timing stack. No further elapsed time is
205 attributed to the previous topmost timing variable on the stack;
206 subsequent elapsed time is attributed to TIMEVAR, until it is
207 popped or another element is pushed on top.
209 TIMEVAR cannot be running as a standalone timer. */
211 void
212 timer::push (timevar_id_t timevar)
214 struct timevar_def *tv = &m_timevars[timevar];
215 struct timevar_stack_def *context;
216 struct timevar_time_def now;
218 /* Mark this timing variable as used. */
219 tv->used = 1;
221 /* Can't push a standalone timer. */
222 gcc_assert (!tv->standalone);
224 /* What time is it? */
225 get_time (&now);
227 /* If the stack isn't empty, attribute the current elapsed time to
228 the old topmost element. */
229 if (m_stack)
230 timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
232 /* Reset the start time; from now on, time is attributed to
233 TIMEVAR. */
234 m_start_time = now;
236 /* See if we have a previously-allocated stack instance. If so,
237 take it off the list. If not, malloc a new one. */
238 if (m_unused_stack_instances != NULL)
240 context = m_unused_stack_instances;
241 m_unused_stack_instances = m_unused_stack_instances->next;
243 else
244 context = XNEW (struct timevar_stack_def);
246 /* Fill it in and put it on the stack. */
247 context->timevar = tv;
248 context->next = m_stack;
249 m_stack = context;
252 /* Pop the topmost timing variable element off the timing stack. The
253 popped variable must be TIMEVAR. Elapsed time since the that
254 element was pushed on, or since it was last exposed on top of the
255 stack when the element above it was popped off, is credited to that
256 timing variable. */
258 void
259 timer::pop (timevar_id_t timevar)
261 struct timevar_time_def now;
262 struct timevar_stack_def *popped = m_stack;
264 gcc_assert (&m_timevars[timevar] == m_stack->timevar);
266 /* What time is it? */
267 get_time (&now);
269 /* Attribute the elapsed time to the element we're popping. */
270 timevar_accumulate (&popped->timevar->elapsed, &m_start_time, &now);
272 /* Reset the start time; from now on, time is attributed to the
273 element just exposed on the stack. */
274 m_start_time = now;
276 /* Take the item off the stack. */
277 m_stack = m_stack->next;
279 /* Don't delete the stack element; instead, add it to the list of
280 unused elements for later use. */
281 popped->next = m_unused_stack_instances;
282 m_unused_stack_instances = popped;
285 /* Start timing TIMEVAR independently of the timing stack. Elapsed
286 time until timevar_stop is called for the same timing variable is
287 attributed to TIMEVAR. */
289 void
290 timevar_start (timevar_id_t timevar)
292 if (!g_timer)
293 return;
295 g_timer->start (timevar);
298 /* See timevar_start above. */
300 void
301 timer::start (timevar_id_t timevar)
303 struct timevar_def *tv = &m_timevars[timevar];
305 /* Mark this timing variable as used. */
306 tv->used = 1;
308 /* Don't allow the same timing variable to be started more than
309 once. */
310 gcc_assert (!tv->standalone);
311 tv->standalone = 1;
313 get_time (&tv->start_time);
316 /* Stop timing TIMEVAR. Time elapsed since timevar_start was called
317 is attributed to it. */
319 void
320 timevar_stop (timevar_id_t timevar)
322 if (!g_timer)
323 return;
325 g_timer->stop (timevar);
328 /* See timevar_stop above. */
330 void
331 timer::stop (timevar_id_t timevar)
333 struct timevar_def *tv = &m_timevars[timevar];
334 struct timevar_time_def now;
336 /* TIMEVAR must have been started via timevar_start. */
337 gcc_assert (tv->standalone);
338 tv->standalone = 0; /* Enable a restart. */
340 get_time (&now);
341 timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
345 /* Conditionally start timing TIMEVAR independently of the timing stack.
346 If the timer is already running, leave it running and return true.
347 Otherwise, start the timer and return false.
348 Elapsed time until the corresponding timevar_cond_stop
349 is called for the same timing variable is attributed to TIMEVAR. */
351 bool
352 timevar_cond_start (timevar_id_t timevar)
354 if (!g_timer)
355 return false;
357 return g_timer->cond_start (timevar);
360 /* See timevar_cond_start above. */
362 bool
363 timer::cond_start (timevar_id_t timevar)
365 struct timevar_def *tv = &m_timevars[timevar];
367 /* Mark this timing variable as used. */
368 tv->used = 1;
370 if (tv->standalone)
371 return true; /* The timevar is already running. */
373 /* Don't allow the same timing variable
374 to be unconditionally started more than once. */
375 tv->standalone = 1;
377 get_time (&tv->start_time);
378 return false; /* The timevar was not already running. */
381 /* Conditionally stop timing TIMEVAR. The RUNNING parameter must come
382 from the return value of a dynamically matching timevar_cond_start.
383 If the timer had already been RUNNING, do nothing. Otherwise, time
384 elapsed since timevar_cond_start was called is attributed to it. */
386 void
387 timevar_cond_stop (timevar_id_t timevar, bool running)
389 if (!g_timer || running)
390 return;
392 g_timer->cond_stop (timevar);
395 /* See timevar_cond_stop above. */
397 void
398 timer::cond_stop (timevar_id_t timevar)
400 struct timevar_def *tv;
401 struct timevar_time_def now;
403 tv = &m_timevars[timevar];
405 /* TIMEVAR must have been started via timevar_cond_start. */
406 gcc_assert (tv->standalone);
407 tv->standalone = 0; /* Enable a restart. */
409 get_time (&now);
410 timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
414 /* Validate that phase times are consistent. */
416 void
417 timer::validate_phases (FILE *fp) const
419 unsigned int /* timevar_id_t */ id;
420 const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
421 double phase_user = 0.0;
422 double phase_sys = 0.0;
423 double phase_wall = 0.0;
424 size_t phase_ggc_mem = 0;
425 static char phase_prefix[] = "phase ";
426 const double tolerance = 1.000001; /* One part in a million. */
428 for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
430 const timevar_def *tv = &m_timevars[(timevar_id_t) id];
432 /* Don't evaluate timing variables that were never used. */
433 if (!tv->used)
434 continue;
436 if (strncmp (tv->name, phase_prefix, sizeof phase_prefix - 1) == 0)
438 phase_user += tv->elapsed.user;
439 phase_sys += tv->elapsed.sys;
440 phase_wall += tv->elapsed.wall;
441 phase_ggc_mem += tv->elapsed.ggc_mem;
445 if (phase_user > total->user * tolerance
446 || phase_sys > total->sys * tolerance
447 || phase_wall > total->wall * tolerance
448 || phase_ggc_mem > total->ggc_mem * tolerance)
451 fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
452 if (phase_user > total->user)
453 fprintf (fp, "user %24.18e > %24.18e\n", phase_user, total->user);
454 if (phase_sys > total->sys)
455 fprintf (fp, "sys %24.18e > %24.18e\n", phase_sys, total->sys);
456 if (phase_wall > total->wall)
457 fprintf (fp, "wall %24.18e > %24.18e\n", phase_wall, total->wall);
458 if (phase_ggc_mem > total->ggc_mem)
459 fprintf (fp, "ggc_mem %24lu > %24lu\n", (unsigned long)phase_ggc_mem,
460 (unsigned long)total->ggc_mem);
461 gcc_unreachable ();
466 /* Summarize timing variables to FP. The timing variable TV_TOTAL has
467 a special meaning -- it's considered to be the total elapsed time,
468 for normalizing the others, and is displayed last. */
470 void
471 timer::print (FILE *fp)
473 /* Only print stuff if we have some sort of time information. */
474 #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
475 unsigned int /* timevar_id_t */ id;
476 const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
477 struct timevar_time_def now;
479 /* Update timing information in case we're calling this from GDB. */
481 if (fp == 0)
482 fp = stderr;
484 /* What time is it? */
485 get_time (&now);
487 /* If the stack isn't empty, attribute the current elapsed time to
488 the old topmost element. */
489 if (m_stack)
490 timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
492 /* Reset the start time; from now on, time is attributed to
493 TIMEVAR. */
494 m_start_time = now;
496 fputs ("\nExecution times (seconds)\n", fp);
497 for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
499 const timevar_def *tv = &m_timevars[(timevar_id_t) id];
500 const double tiny = 5e-3;
502 /* Don't print the total execution time here; that goes at the
503 end. */
504 if ((timevar_id_t) id == TV_TOTAL)
505 continue;
507 /* Don't print timing variables that were never used. */
508 if (!tv->used)
509 continue;
511 /* Don't print timing variables if we're going to get a row of
512 zeroes. */
513 if (tv->elapsed.user < tiny
514 && tv->elapsed.sys < tiny
515 && tv->elapsed.wall < tiny
516 && tv->elapsed.ggc_mem < GGC_MEM_BOUND)
517 continue;
519 /* The timing variable name. */
520 fprintf (fp, " %-24s:", tv->name);
522 #ifdef HAVE_USER_TIME
523 /* Print user-mode time for this process. */
524 fprintf (fp, "%7.2f (%2.0f%%) usr",
525 tv->elapsed.user,
526 (total->user == 0 ? 0 : tv->elapsed.user / total->user) * 100);
527 #endif /* HAVE_USER_TIME */
529 #ifdef HAVE_SYS_TIME
530 /* Print system-mode time for this process. */
531 fprintf (fp, "%7.2f (%2.0f%%) sys",
532 tv->elapsed.sys,
533 (total->sys == 0 ? 0 : tv->elapsed.sys / total->sys) * 100);
534 #endif /* HAVE_SYS_TIME */
536 #ifdef HAVE_WALL_TIME
537 /* Print wall clock time elapsed. */
538 fprintf (fp, "%7.2f (%2.0f%%) wall",
539 tv->elapsed.wall,
540 (total->wall == 0 ? 0 : tv->elapsed.wall / total->wall) * 100);
541 #endif /* HAVE_WALL_TIME */
543 /* Print the amount of ggc memory allocated. */
544 fprintf (fp, "%8u kB (%2.0f%%) ggc",
545 (unsigned) (tv->elapsed.ggc_mem >> 10),
546 (total->ggc_mem == 0
548 : (float) tv->elapsed.ggc_mem / total->ggc_mem) * 100);
550 putc ('\n', fp);
553 /* Print total time. */
554 fputs (" TOTAL :", fp);
555 #ifdef HAVE_USER_TIME
556 fprintf (fp, "%7.2f ", total->user);
557 #endif
558 #ifdef HAVE_SYS_TIME
559 fprintf (fp, "%7.2f ", total->sys);
560 #endif
561 #ifdef HAVE_WALL_TIME
562 fprintf (fp, "%7.2f ", total->wall);
563 #endif
564 fprintf (fp, "%8u kB\n", (unsigned) (total->ggc_mem >> 10));
566 #ifdef ENABLE_CHECKING
567 fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
568 fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
569 #endif
570 #ifndef ENABLE_ASSERT_CHECKING
571 fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
572 fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
573 #endif
575 #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
576 || defined (HAVE_WALL_TIME) */
578 validate_phases (fp);
581 /* Prints a message to stderr stating that time elapsed in STR is
582 TOTAL (given in microseconds). */
584 void
585 print_time (const char *str, long total)
587 long all_time = get_run_time ();
588 fprintf (stderr,
589 "time in %s: %ld.%06ld (%ld%%)\n",
590 str, total / 1000000, total % 1000000,
591 all_time == 0 ? 0
592 : (long) (((100.0 * (double) total) / (double) all_time) + .5));