Branch data Line data Source code
1 : : /* Timing variables for measuring compiler performance.
2 : : Copyright (C) 2000-2024 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 : : #include "coretypes.h"
24 : : #include "timevar.h"
25 : : #include "options.h"
26 : : #include "json.h"
27 : :
28 : : #ifndef HAVE_CLOCK_T
29 : : typedef int clock_t;
30 : : #endif
31 : :
32 : : #ifndef HAVE_STRUCT_TMS
33 : : struct tms
34 : : {
35 : : clock_t tms_utime;
36 : : clock_t tms_stime;
37 : : clock_t tms_cutime;
38 : : clock_t tms_cstime;
39 : : };
40 : : #endif
41 : :
42 : : #ifndef RUSAGE_SELF
43 : : # define RUSAGE_SELF 0
44 : : #endif
45 : :
46 : : /* Calculation of scale factor to convert ticks to seconds.
47 : : We mustn't use CLOCKS_PER_SEC except with clock(). */
48 : : #if HAVE_SYSCONF && defined _SC_CLK_TCK
49 : : # define TICKS_PER_SECOND sysconf (_SC_CLK_TCK) /* POSIX 1003.1-1996 */
50 : : #else
51 : : # ifdef CLK_TCK
52 : : # define TICKS_PER_SECOND CLK_TCK /* POSIX 1003.1-1988; obsolescent */
53 : : # else
54 : : # ifdef HZ
55 : : # define TICKS_PER_SECOND HZ /* traditional UNIX */
56 : : # else
57 : : # define TICKS_PER_SECOND 100 /* often the correct value */
58 : : # endif
59 : : # endif
60 : : #endif
61 : :
62 : : /* Prefer times to getrusage to clock (each gives successively less
63 : : information). */
64 : : #ifdef HAVE_TIMES
65 : : # if defined HAVE_DECL_TIMES && !HAVE_DECL_TIMES
66 : : extern clock_t times (struct tms *);
67 : : # endif
68 : : # define USE_TIMES
69 : : # define HAVE_USER_TIME
70 : : # define HAVE_SYS_TIME
71 : : # define HAVE_WALL_TIME
72 : : #else
73 : : #ifdef HAVE_GETRUSAGE
74 : : # if defined HAVE_DECL_GETRUSAGE && !HAVE_DECL_GETRUSAGE
75 : : extern int getrusage (int, struct rusage *);
76 : : # endif
77 : : # define USE_GETRUSAGE
78 : : # define HAVE_USER_TIME
79 : : # define HAVE_SYS_TIME
80 : : #else
81 : : #ifdef HAVE_CLOCK
82 : : # if defined HAVE_DECL_CLOCK && !HAVE_DECL_CLOCK
83 : : extern clock_t clock (void);
84 : : # endif
85 : : # define USE_CLOCK
86 : : # define HAVE_USER_TIME
87 : : #endif
88 : : #endif
89 : : #endif
90 : :
91 : : /* libc is very likely to have snuck a call to sysconf() into one of
92 : : the underlying constants, and that can be very slow, so we have to
93 : : precompute them. Whose wonderful idea was it to make all those
94 : : _constants_ variable at run time, anyway? */
95 : : #define NANOSEC_PER_SEC 1000000000
96 : : #ifdef USE_TIMES
97 : : static uint64_t ticks_to_nanosec;
98 : : #define TICKS_TO_NANOSEC (NANOSEC_PER_SEC / TICKS_PER_SECOND)
99 : : #endif
100 : :
101 : : #ifdef USE_CLOCK
102 : : static uint64_t clocks_to_nanosec;
103 : : #define CLOCKS_TO_NANOSEC (NANOSEC_PER_SEC / CLOCKS_PER_SEC)
104 : : #endif
105 : :
106 : : /* Non-NULL if timevars should be used. In GCC, this happens with
107 : : the -ftime-report flag. */
108 : :
109 : : timer *g_timer;
110 : :
111 : : /* Total amount of memory allocated by garbage collector. */
112 : :
113 : : size_t timevar_ggc_mem_total;
114 : :
115 : : /* The amount of memory that will cause us to report the timevar even
116 : : if the time spent is not significant. */
117 : :
118 : : #define GGC_MEM_BOUND (1 << 20)
119 : :
120 : : /* See timevar.h for an explanation of timing variables. */
121 : :
122 : : static void get_time (struct timevar_time_def *);
123 : : static void timevar_accumulate (struct timevar_time_def *,
124 : : struct timevar_time_def *,
125 : : struct timevar_time_def *);
126 : :
127 : : /* The implementation of timing events for jit client code, allowing
128 : : arbitrary named items to appear on the timing stack. */
129 : :
130 : : class timer::named_items
131 : : {
132 : : public:
133 : : named_items (timer *t);
134 : : ~named_items ();
135 : :
136 : : void push (const char *item_name);
137 : : void pop ();
138 : : void print (FILE *fp, const timevar_time_def *total);
139 : :
140 : : json::value *make_json () const;
141 : :
142 : : private:
143 : : /* Which timer instance does this relate to? */
144 : : timer *m_timer;
145 : :
146 : : /* Dictionary, mapping from item names to timevar_def.
147 : : Note that currently we merely store/compare the raw string
148 : : pointers provided by client code; we don't take a copy,
149 : : or use strcmp. */
150 : : typedef hash_map <const char *, timer::timevar_def> hash_map_t;
151 : : hash_map_t m_hash_map;
152 : :
153 : : /* The order in which items were originally inserted. */
154 : : auto_vec <const char *> m_names;
155 : : };
156 : :
157 : : /* The constructor for class timer::named_items. */
158 : :
159 : 9 : timer::named_items::named_items (timer *t)
160 : 9 : : m_timer (t),
161 : 9 : m_hash_map (),
162 : 9 : m_names ()
163 : : {
164 : 9 : }
165 : :
166 : : /* The destructor for class timer::named_items. */
167 : :
168 : 9 : timer::named_items::~named_items ()
169 : : {
170 : 9 : }
171 : :
172 : : /* Push the named item onto the timer stack. */
173 : :
174 : : void
175 : 1605 : timer::named_items::push (const char *item_name)
176 : : {
177 : 1605 : gcc_assert (item_name);
178 : :
179 : 1605 : bool existed;
180 : 1605 : timer::timevar_def *def = &m_hash_map.get_or_insert (item_name, &existed);
181 : 1605 : if (!existed)
182 : : {
183 : 21 : def->elapsed.user = 0;
184 : 21 : def->elapsed.sys = 0;
185 : 21 : def->elapsed.wall = 0;
186 : 21 : def->name = item_name;
187 : 21 : def->standalone = 0;
188 : 21 : m_names.safe_push (item_name);
189 : : }
190 : 1605 : m_timer->push_internal (def);
191 : 1605 : }
192 : :
193 : : /* Pop the top item from the timer stack. */
194 : :
195 : : void
196 : 1600 : timer::named_items::pop ()
197 : : {
198 : 1600 : m_timer->pop_internal ();
199 : 1600 : }
200 : :
201 : : /* Print the given client item. Helper function for timer::print. */
202 : :
203 : : void
204 : 4 : timer::named_items::print (FILE *fp, const timevar_time_def *total)
205 : : {
206 : 4 : fprintf (fp, "Client items:\n");
207 : 28 : for (const char *item_name : m_names)
208 : : {
209 : 16 : timer::timevar_def *def = m_hash_map.get (item_name);
210 : 16 : gcc_assert (def);
211 : 16 : m_timer->print_row (fp, total, def->name, def->elapsed);
212 : : }
213 : 4 : }
214 : :
215 : : /* Create a json value representing this object, suitable for use
216 : : in SARIF output. */
217 : :
218 : : json::value *
219 : 0 : timer::named_items::make_json () const
220 : : {
221 : 0 : json::array *arr = new json::array ();
222 : 0 : for (const char *item_name : m_names)
223 : : {
224 : 0 : hash_map_t &mut_map = const_cast <hash_map_t &> (m_hash_map);
225 : 0 : timer::timevar_def *def = mut_map.get (item_name);
226 : 0 : gcc_assert (def);
227 : 0 : arr->append (def->make_json ());
228 : : }
229 : 0 : return arr;
230 : : }
231 : :
232 : : /* Fill the current times into TIME. The definition of this function
233 : : also defines any or all of the HAVE_USER_TIME, HAVE_SYS_TIME, and
234 : : HAVE_WALL_TIME macros. */
235 : :
236 : : static void
237 : 1320979 : get_time (struct timevar_time_def *now)
238 : : {
239 : 1320979 : now->user = 0;
240 : 1320979 : now->sys = 0;
241 : 1320979 : now->wall = 0;
242 : 1320979 : now->ggc_mem = timevar_ggc_mem_total;
243 : :
244 : 1320979 : {
245 : : #ifdef USE_TIMES
246 : 1320979 : struct tms tms;
247 : 1320979 : now->wall = times (&tms) * ticks_to_nanosec;
248 : 1320979 : now->user = tms.tms_utime * ticks_to_nanosec;
249 : 1320979 : now->sys = tms.tms_stime * ticks_to_nanosec;
250 : : #endif
251 : : #ifdef USE_GETRUSAGE
252 : : struct rusage rusage;
253 : : getrusage (RUSAGE_SELF, &rusage);
254 : : now->user = rusage.ru_utime.tv_sec * NANOSEC_PER_SEC
255 : : + rusage.ru_utime.tv_usec * 1000;
256 : : now->sys = rusage.ru_stime.tv_sec * NANOSEC_PER_SEC
257 : : + rusage.ru_stime.tv_usec * 1000;
258 : : #endif
259 : : #ifdef USE_CLOCK
260 : : now->user = clock () * clocks_to_nanosec;
261 : : #endif
262 : : }
263 : 1320979 : }
264 : :
265 : : /* Add the difference between STOP_TIME and START_TIME to TIMER. */
266 : :
267 : : static void
268 : 1258730 : timevar_accumulate (struct timevar_time_def *timer,
269 : : struct timevar_time_def *start_time,
270 : : struct timevar_time_def *stop_time)
271 : : {
272 : 1258730 : timer->user += stop_time->user - start_time->user;
273 : 1258730 : timer->sys += stop_time->sys - start_time->sys;
274 : 1258730 : timer->wall += stop_time->wall - start_time->wall;
275 : 1258730 : timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem;
276 : 1258730 : }
277 : :
278 : : /* Get the difference between STOP_TIME and START_TIME. */
279 : :
280 : : static void
281 : 10 : timevar_diff (struct timevar_time_def *out,
282 : : const timevar_time_def &start_time,
283 : : const timevar_time_def &stop_time)
284 : : {
285 : 10 : out->user = stop_time.user - start_time.user;
286 : 10 : out->sys = stop_time.sys - start_time.sys;
287 : 10 : out->wall = stop_time.wall - start_time.wall;
288 : 10 : out->ggc_mem = stop_time.ggc_mem - start_time.ggc_mem;
289 : 0 : }
290 : :
291 : : /* Class timer's constructor. */
292 : :
293 : 32 : timer::timer () :
294 : 32 : m_stack (NULL),
295 : 32 : m_unused_stack_instances (NULL),
296 : 32 : m_start_time (),
297 : 32 : m_jit_client_items (NULL)
298 : : {
299 : : /* Zero all elapsed times. */
300 : 32 : memset (m_timevars, 0, sizeof (m_timevars));
301 : :
302 : : /* Initialize the names of timing variables. */
303 : : #define DEFTIMEVAR(identifier__, name__) \
304 : : m_timevars[identifier__].name = name__;
305 : : #include "timevar.def"
306 : : #undef DEFTIMEVAR
307 : :
308 : : /* Initialize configuration-specific state.
309 : : Ideally this would be one-time initialization. */
310 : : #ifdef USE_TIMES
311 : 32 : ticks_to_nanosec = TICKS_TO_NANOSEC;
312 : : #endif
313 : : #ifdef USE_CLOCK
314 : : clocks_to_nanosec = CLOCKS_TO_NANOSEC;
315 : : #endif
316 : 32 : }
317 : :
318 : : /* Class timer's destructor. */
319 : :
320 : 32 : timer::~timer ()
321 : : {
322 : 32 : timevar_stack_def *iter, *next;
323 : :
324 : 51 : for (iter = m_stack; iter; iter = next)
325 : : {
326 : 19 : next = iter->next;
327 : 19 : free (iter);
328 : : }
329 : 162 : for (iter = m_unused_stack_instances; iter; iter = next)
330 : : {
331 : 130 : next = iter->next;
332 : 130 : free (iter);
333 : : }
334 : 9280 : for (unsigned i = 0; i < TIMEVAR_LAST; ++i)
335 : 9274 : delete m_timevars[i].children;
336 : :
337 : 32 : delete m_jit_client_items;
338 : 32 : }
339 : :
340 : : /* Initialize timing variables. */
341 : :
342 : : void
343 : 18 : timevar_init (void)
344 : : {
345 : 18 : if (g_timer)
346 : : return;
347 : :
348 : 18 : g_timer = new timer ();
349 : : }
350 : :
351 : : /* Push TIMEVAR onto the timing stack. No further elapsed time is
352 : : attributed to the previous topmost timing variable on the stack;
353 : : subsequent elapsed time is attributed to TIMEVAR, until it is
354 : : popped or another element is pushed on top.
355 : :
356 : : TIMEVAR cannot be running as a standalone timer. */
357 : :
358 : : void
359 : 596481 : timer::push (timevar_id_t timevar)
360 : : {
361 : 596481 : struct timevar_def *tv = &m_timevars[timevar];
362 : 596481 : push_internal (tv);
363 : 596481 : }
364 : :
365 : : /* Push TV onto the timing stack, either one of the builtin ones
366 : : for a timevar_id_t, or one provided by client code to libgccjit. */
367 : :
368 : : void
369 : 598086 : timer::push_internal (struct timevar_def *tv)
370 : : {
371 : 598086 : struct timevar_stack_def *context;
372 : 598086 : struct timevar_time_def now;
373 : :
374 : 598086 : gcc_assert (tv);
375 : :
376 : : /* Mark this timing variable as used. */
377 : 598086 : tv->used = 1;
378 : :
379 : : /* Can't push a standalone timer. */
380 : 598086 : gcc_assert (!tv->standalone);
381 : :
382 : : /* What time is it? */
383 : 598086 : get_time (&now);
384 : :
385 : : /* If the stack isn't empty, attribute the current elapsed time to
386 : : the old topmost element. */
387 : 598086 : if (m_stack)
388 : 597982 : timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
389 : :
390 : : /* Reset the start time; from now on, time is attributed to
391 : : TIMEVAR. */
392 : 598086 : m_start_time = now;
393 : :
394 : : /* See if we have a previously-allocated stack instance. If so,
395 : : take it off the list. If not, malloc a new one. */
396 : 598086 : if (m_unused_stack_instances != NULL)
397 : : {
398 : 597937 : context = m_unused_stack_instances;
399 : 597937 : m_unused_stack_instances = m_unused_stack_instances->next;
400 : : }
401 : : else
402 : 149 : context = XNEW (struct timevar_stack_def);
403 : :
404 : : /* Fill it in and put it on the stack. */
405 : 598086 : context->timevar = tv;
406 : 598086 : context->next = m_stack;
407 : 598086 : m_stack = context;
408 : 598086 : }
409 : :
410 : : /* Pop the topmost timing variable element off the timing stack. The
411 : : popped variable must be TIMEVAR. Elapsed time since the that
412 : : element was pushed on, or since it was last exposed on top of the
413 : : stack when the element above it was popped off, is credited to that
414 : : timing variable. */
415 : :
416 : : void
417 : 596467 : timer::pop (timevar_id_t timevar)
418 : : {
419 : 596467 : gcc_assert (&m_timevars[timevar] == m_stack->timevar);
420 : :
421 : 596467 : pop_internal ();
422 : 596467 : }
423 : :
424 : : /* Pop the topmost item from the stack, either one of the builtin ones
425 : : for a timevar_id_t, or one provided by client code to libgccjit. */
426 : :
427 : : void
428 : 598067 : timer::pop_internal ()
429 : : {
430 : 598067 : struct timevar_time_def now;
431 : 598067 : struct timevar_stack_def *popped = m_stack;
432 : :
433 : : /* What time is it? */
434 : 598067 : get_time (&now);
435 : :
436 : : /* Attribute the elapsed time to the element we're popping. */
437 : 598067 : timevar_accumulate (&popped->timevar->elapsed, &m_start_time, &now);
438 : :
439 : : /* Take the item off the stack. */
440 : 598067 : m_stack = m_stack->next;
441 : :
442 : : /* Record the elapsed sub-time to the parent as well. */
443 : 598067 : if (m_stack && time_report_details)
444 : : {
445 : 291 : if (! m_stack->timevar->children)
446 : 26 : m_stack->timevar->children = new child_map_t (5);
447 : 291 : bool existed_p;
448 : 291 : timevar_time_def &time
449 : 291 : = m_stack->timevar->children->get_or_insert (popped->timevar, &existed_p);
450 : 291 : if (! existed_p)
451 : 86 : memset (&time, 0, sizeof (timevar_time_def));
452 : 291 : timevar_accumulate (&time, &m_start_time, &now);
453 : : }
454 : :
455 : : /* Reset the start time; from now on, time is attributed to the
456 : : element just exposed on the stack. */
457 : 598067 : m_start_time = now;
458 : :
459 : : /* Don't delete the stack element; instead, add it to the list of
460 : : unused elements for later use. */
461 : 598067 : popped->next = m_unused_stack_instances;
462 : 598067 : m_unused_stack_instances = popped;
463 : 598067 : }
464 : :
465 : : /* Start timing TIMEVAR independently of the timing stack. Elapsed
466 : : time until timevar_stop is called for the same timing variable is
467 : : attributed to TIMEVAR. */
468 : :
469 : : void
470 : 270135489 : timevar_start (timevar_id_t timevar)
471 : : {
472 : 270135489 : if (!g_timer)
473 : : return;
474 : :
475 : 3000 : g_timer->start (timevar);
476 : : }
477 : :
478 : : /* See timevar_start above. */
479 : :
480 : : void
481 : 3018 : timer::start (timevar_id_t timevar)
482 : : {
483 : 3018 : struct timevar_def *tv = &m_timevars[timevar];
484 : :
485 : : /* Mark this timing variable as used. */
486 : 3018 : tv->used = 1;
487 : :
488 : : /* Don't allow the same timing variable to be started more than
489 : : once. */
490 : 3018 : gcc_assert (!tv->standalone);
491 : 3018 : tv->standalone = 1;
492 : :
493 : 3018 : get_time (&tv->start_time);
494 : 3018 : }
495 : :
496 : : /* Stop timing TIMEVAR. Time elapsed since timevar_start was called
497 : : is attributed to it. */
498 : :
499 : : void
500 : 269854183 : timevar_stop (timevar_id_t timevar)
501 : : {
502 : 269854183 : if (!g_timer)
503 : : return;
504 : :
505 : 2982 : g_timer->stop (timevar);
506 : : }
507 : :
508 : : /* See timevar_stop above. */
509 : :
510 : : void
511 : 2994 : timer::stop (timevar_id_t timevar)
512 : : {
513 : 2994 : struct timevar_def *tv = &m_timevars[timevar];
514 : 2994 : struct timevar_time_def now;
515 : :
516 : : /* TIMEVAR must have been started via timevar_start. */
517 : 2994 : gcc_assert (tv->standalone);
518 : 2994 : tv->standalone = 0; /* Enable a restart. */
519 : :
520 : 2994 : get_time (&now);
521 : 2994 : timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
522 : 2994 : }
523 : :
524 : :
525 : : /* Conditionally start timing TIMEVAR independently of the timing stack.
526 : : If the timer is already running, leave it running and return true.
527 : : Otherwise, start the timer and return false.
528 : : Elapsed time until the corresponding timevar_cond_stop
529 : : is called for the same timing variable is attributed to TIMEVAR. */
530 : :
531 : : bool
532 : 0 : timevar_cond_start (timevar_id_t timevar)
533 : : {
534 : 0 : if (!g_timer)
535 : : return false;
536 : :
537 : 0 : return g_timer->cond_start (timevar);
538 : : }
539 : :
540 : : /* See timevar_cond_start above. */
541 : :
542 : : bool
543 : 81216 : timer::cond_start (timevar_id_t timevar)
544 : : {
545 : 81216 : struct timevar_def *tv = &m_timevars[timevar];
546 : :
547 : : /* Mark this timing variable as used. */
548 : 81216 : tv->used = 1;
549 : :
550 : 81216 : if (tv->standalone)
551 : : return true; /* The timevar is already running. */
552 : :
553 : : /* Don't allow the same timing variable
554 : : to be unconditionally started more than once. */
555 : 59396 : tv->standalone = 1;
556 : :
557 : 59396 : get_time (&tv->start_time);
558 : 59396 : return false; /* The timevar was not already running. */
559 : : }
560 : :
561 : : /* Conditionally stop timing TIMEVAR. The RUNNING parameter must come
562 : : from the return value of a dynamically matching timevar_cond_start.
563 : : If the timer had already been RUNNING, do nothing. Otherwise, time
564 : : elapsed since timevar_cond_start was called is attributed to it. */
565 : :
566 : : void
567 : 0 : timevar_cond_stop (timevar_id_t timevar, bool running)
568 : : {
569 : 0 : if (!g_timer || running)
570 : : return;
571 : :
572 : 0 : g_timer->cond_stop (timevar);
573 : : }
574 : :
575 : : /* See timevar_cond_stop above. */
576 : :
577 : : void
578 : 59396 : timer::cond_stop (timevar_id_t timevar)
579 : : {
580 : 59396 : struct timevar_def *tv;
581 : 59396 : struct timevar_time_def now;
582 : :
583 : 59396 : tv = &m_timevars[timevar];
584 : :
585 : : /* TIMEVAR must have been started via timevar_cond_start. */
586 : 59396 : gcc_assert (tv->standalone);
587 : 59396 : tv->standalone = 0; /* Enable a restart. */
588 : :
589 : 59396 : get_time (&now);
590 : 59396 : timevar_accumulate (&tv->elapsed, &tv->start_time, &now);
591 : 59396 : }
592 : :
593 : : /* Push the named item onto the timing stack. */
594 : :
595 : : void
596 : 1605 : timer::push_client_item (const char *item_name)
597 : : {
598 : 1605 : gcc_assert (item_name);
599 : :
600 : : /* Lazily create the named_items instance. */
601 : 1605 : if (!m_jit_client_items)
602 : 9 : m_jit_client_items = new named_items (this);
603 : :
604 : 1605 : m_jit_client_items->push (item_name);
605 : 1605 : }
606 : :
607 : : /* Pop the top-most client item from the timing stack. */
608 : :
609 : : void
610 : 1600 : timer::pop_client_item ()
611 : : {
612 : 1600 : gcc_assert (m_jit_client_items);
613 : 1600 : m_jit_client_items->pop ();
614 : 1600 : }
615 : :
616 : : /* Validate that phase times are consistent. */
617 : :
618 : : void
619 : 12 : timer::validate_phases (FILE *fp) const
620 : : {
621 : 12 : unsigned int /* timevar_id_t */ id;
622 : 12 : const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
623 : 12 : uint64_t phase_user = 0;
624 : 12 : uint64_t phase_sys = 0;
625 : 12 : uint64_t phase_wall = 0;
626 : 12 : size_t phase_ggc_mem = 0;
627 : 12 : static char phase_prefix[] = "phase ";
628 : :
629 : 3480 : for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
630 : : {
631 : 3468 : const timevar_def *tv = &m_timevars[(timevar_id_t) id];
632 : :
633 : : /* Don't evaluate timing variables that were never used. */
634 : 3468 : if (!tv->used)
635 : 2464 : continue;
636 : :
637 : 1004 : if (startswith (tv->name, phase_prefix))
638 : : {
639 : 72 : phase_user += tv->elapsed.user;
640 : 72 : phase_sys += tv->elapsed.sys;
641 : 72 : phase_wall += tv->elapsed.wall;
642 : 72 : phase_ggc_mem += tv->elapsed.ggc_mem;
643 : : }
644 : : }
645 : :
646 : 12 : if (phase_user > total->user
647 : 12 : || phase_sys > total->sys
648 : 12 : || phase_wall > total->wall
649 : 12 : || phase_ggc_mem > total->ggc_mem)
650 : : {
651 : :
652 : 0 : fprintf (fp, "Timing error: total of phase timers exceeds total time.\n");
653 : 0 : if (phase_user > total->user)
654 : 0 : fprintf (fp, "user %13" PRIu64 " > %13" PRIu64 "\n",
655 : : phase_user, total->user);
656 : 0 : if (phase_sys > total->sys)
657 : 0 : fprintf (fp, "sys %13" PRIu64 " > %13" PRIu64 "\n",
658 : : phase_sys, total->sys);
659 : 0 : if (phase_wall > total->wall)
660 : 0 : fprintf (fp, "wall %13" PRIu64 " > %13" PRIu64 "\n",
661 : : phase_wall, total->wall);
662 : 0 : if (phase_ggc_mem > total->ggc_mem)
663 : 0 : fprintf (fp, "ggc_mem %13lu > %13lu\n", (unsigned long)phase_ggc_mem,
664 : : (unsigned long)total->ggc_mem);
665 : 0 : gcc_unreachable ();
666 : : }
667 : 12 : }
668 : :
669 : : #define nanosec_to_floating_sec(NANO) ((double)(NANO) * 1e-9)
670 : : #define percent_of(TOTAL, SUBTOTAL) \
671 : : ((TOTAL) == 0 ? 0 : ((double)SUBTOTAL / TOTAL) * 100)
672 : : /* Helper function for timer::print. */
673 : :
674 : : void
675 : 363 : timer::print_row (FILE *fp,
676 : : const timevar_time_def *total,
677 : : const char *name, const timevar_time_def &elapsed)
678 : : {
679 : : /* The timing variable name. */
680 : 363 : fprintf (fp, " %-35s:", name);
681 : :
682 : : #ifdef HAVE_USER_TIME
683 : : /* Print user-mode time for this process. */
684 : 1089 : fprintf (fp, "%7.2f (%3.0f%%)",
685 : 363 : nanosec_to_floating_sec (elapsed.user),
686 : 363 : percent_of (total->user, elapsed.user));
687 : : #endif /* HAVE_USER_TIME */
688 : :
689 : : #ifdef HAVE_SYS_TIME
690 : : /* Print system-mode time for this process. */
691 : 1081 : fprintf (fp, "%7.2f (%3.0f%%)",
692 : 363 : nanosec_to_floating_sec (elapsed.sys),
693 : 363 : percent_of (total->sys, elapsed.sys));
694 : : #endif /* HAVE_SYS_TIME */
695 : :
696 : : #ifdef HAVE_WALL_TIME
697 : : /* Print wall clock time elapsed. */
698 : 1089 : fprintf (fp, "%7.2f (%3.0f%%)",
699 : 363 : nanosec_to_floating_sec (elapsed.wall),
700 : 363 : percent_of (total->wall, elapsed.wall));
701 : : #endif /* HAVE_WALL_TIME */
702 : :
703 : : /* Print the amount of ggc memory allocated. */
704 : 568 : fprintf (fp, PRsa (6) " (%3.0f%%)",
705 : 410 : SIZE_AMOUNT (elapsed.ggc_mem),
706 : 363 : (total->ggc_mem == 0
707 : 363 : ? 0
708 : 363 : : (float) elapsed.ggc_mem / total->ggc_mem) * 100);
709 : :
710 : 363 : putc ('\n', fp);
711 : 363 : }
712 : :
713 : : /* Return whether ELAPSED is all zero. */
714 : :
715 : : bool
716 : 1337 : timer::all_zero (const timevar_time_def &elapsed)
717 : : {
718 : : /* 5000000 nanosec == 5e-3 seconds. */
719 : 1337 : uint64_t tiny = 5000000;
720 : 1337 : return (elapsed.user < tiny
721 : 1089 : && elapsed.sys < tiny
722 : 1062 : && elapsed.wall < tiny
723 : 2309 : && elapsed.ggc_mem < GGC_MEM_BOUND);
724 : : }
725 : :
726 : : /* Summarize timing variables to FP. The timing variable TV_TOTAL has
727 : : a special meaning -- it's considered to be the total elapsed time,
728 : : for normalizing the others, and is displayed last. */
729 : :
730 : : void
731 : 12 : timer::print (FILE *fp)
732 : : {
733 : : /* Only print stuff if we have some sort of time information. */
734 : : #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
735 : 12 : unsigned int /* timevar_id_t */ id;
736 : 12 : const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed;
737 : 12 : struct timevar_time_def now;
738 : :
739 : : /* Update timing information in case we're calling this from GDB. */
740 : :
741 : 12 : if (fp == 0)
742 : 0 : fp = stderr;
743 : :
744 : : /* What time is it? */
745 : 12 : get_time (&now);
746 : :
747 : : /* If the stack isn't empty, attribute the current elapsed time to
748 : : the old topmost element. */
749 : 12 : if (m_stack)
750 : 0 : timevar_accumulate (&m_stack->timevar->elapsed, &m_start_time, &now);
751 : :
752 : : /* Reset the start time; from now on, time is attributed to
753 : : TIMEVAR. */
754 : 12 : m_start_time = now;
755 : :
756 : 12 : fprintf (fp, "\n%-35s%16s%14s%14s%14s\n", "Time variable", "usr", "sys",
757 : : "wall", "GGC");
758 : 12 : if (m_jit_client_items)
759 : 4 : fputs ("GCC items:\n", fp);
760 : 3480 : for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
761 : : {
762 : 3468 : const timevar_def *tv = &m_timevars[(timevar_id_t) id];
763 : :
764 : : /* Don't print the total execution time here; that goes at the
765 : : end. */
766 : 3468 : if ((timevar_id_t) id == TV_TOTAL)
767 : 12 : continue;
768 : :
769 : : /* Don't print timing variables that were never used. */
770 : 3456 : if (!tv->used)
771 : 2464 : continue;
772 : :
773 : 992 : bool any_children_with_time = false;
774 : 992 : if (tv->children)
775 : 0 : for (child_map_t::iterator i = tv->children->begin ();
776 : 0 : i != tv->children->end (); ++i)
777 : 0 : if (! all_zero ((*i).second))
778 : : {
779 : : any_children_with_time = true;
780 : : break;
781 : : }
782 : :
783 : : /* Don't print timing variables if we're going to get a row of
784 : : zeroes. Unless there are children with non-zero time. */
785 : 645 : if (! any_children_with_time
786 : 992 : && all_zero (tv->elapsed))
787 : 645 : continue;
788 : :
789 : 347 : print_row (fp, total, tv->name, tv->elapsed);
790 : :
791 : 347 : if (tv->children)
792 : 0 : for (child_map_t::iterator i = tv->children->begin ();
793 : 0 : i != tv->children->end (); ++i)
794 : : {
795 : 0 : timevar_def *tv2 = (*i).first;
796 : : /* Don't print timing variables if we're going to get a row of
797 : : zeroes. */
798 : 0 : if (! all_zero ((*i).second))
799 : : {
800 : 0 : char lname[256];
801 : 0 : snprintf (lname, 256, "`- %s", tv2->name);
802 : 0 : print_row (fp, total, lname, (*i).second);
803 : : }
804 : : }
805 : : }
806 : 12 : if (m_jit_client_items)
807 : 4 : m_jit_client_items->print (fp, total);
808 : :
809 : : /* Print total time. */
810 : 12 : fprintf (fp, " %-35s:", "TOTAL");
811 : : #ifdef HAVE_USER_TIME
812 : 12 : fprintf (fp, "%7.2f ", nanosec_to_floating_sec (total->user));
813 : : #endif
814 : : #ifdef HAVE_SYS_TIME
815 : 12 : fprintf (fp, "%8.2f ", nanosec_to_floating_sec (total->sys));
816 : : #endif
817 : : #ifdef HAVE_WALL_TIME
818 : 12 : fprintf (fp, "%8.2f ", nanosec_to_floating_sec (total->wall));
819 : : #endif
820 : 16 : fprintf (fp, PRsa (7) "\n", SIZE_AMOUNT (total->ggc_mem));
821 : :
822 : 12 : if (CHECKING_P || flag_checking)
823 : 12 : fprintf (fp, "Extra diagnostic checks enabled; compiler may run slowly.\n");
824 : 12 : if (CHECKING_P)
825 : 12 : fprintf (fp, "Configure with --enable-checking=release to disable checks.\n");
826 : : #ifndef ENABLE_ASSERT_CHECKING
827 : : fprintf (fp, "Internal checks disabled; compiler is not suited for release.\n");
828 : : fprintf (fp, "Configure with --enable-checking=release to enable checks.\n");
829 : : #endif
830 : :
831 : : #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
832 : : || defined (HAVE_WALL_TIME) */
833 : :
834 : 12 : validate_phases (fp);
835 : 12 : }
836 : :
837 : : /* Create a json value representing this object, suitable for use
838 : : in SARIF output. */
839 : :
840 : : json::object *
841 : 28 : make_json_for_timevar_time_def (const timevar_time_def &ttd)
842 : : {
843 : 28 : json::object *obj = new json::object ();
844 : 28 : obj->set_float ("user", nanosec_to_floating_sec (ttd.user));
845 : 28 : obj->set_float ("sys", nanosec_to_floating_sec (ttd.sys));
846 : 28 : obj->set_float ("wall", nanosec_to_floating_sec (ttd.wall));
847 : 28 : obj->set_integer ("ggc_mem", ttd.ggc_mem);
848 : 28 : return obj;
849 : : }
850 : : #undef nanosec_to_floating_sec
851 : : #undef percent_of
852 : :
853 : : /* Create a json value representing this object, suitable for use
854 : : in SARIF output. */
855 : :
856 : : json::value *
857 : 18 : timer::timevar_def::make_json () const
858 : : {
859 : 18 : json::object *timevar_obj = new json::object ();
860 : 18 : timevar_obj->set_string ("name", name);
861 : 18 : timevar_obj->set ("elapsed", make_json_for_timevar_time_def (elapsed));
862 : :
863 : 18 : if (children)
864 : : {
865 : 1 : bool any_children_with_time = false;
866 : 3 : for (auto i : *children)
867 : 1 : if (!all_zero (i.second))
868 : : {
869 : : any_children_with_time = true;
870 : : break;
871 : : }
872 : 1 : if (any_children_with_time)
873 : : {
874 : 0 : json::array *children_arr = new json::array ();
875 : 0 : timevar_obj->set ("children", children_arr);
876 : 0 : for (auto i : *children)
877 : : {
878 : : /* Don't emit timing variables if we're going to get a row of
879 : : zeroes. */
880 : 0 : if (all_zero (i.second))
881 : 0 : continue;
882 : 0 : json::object *child_obj = new json::object;
883 : 0 : children_arr->append (child_obj);
884 : 0 : child_obj->set_string ("name", i.first->name);
885 : 0 : child_obj->set ("elapsed",
886 : 0 : make_json_for_timevar_time_def (i.second));
887 : : }
888 : : }
889 : : }
890 : :
891 : 18 : return timevar_obj;
892 : : }
893 : :
894 : : /* Create a json value representing this object, suitable for use
895 : : in SARIF output. */
896 : :
897 : : json::value *
898 : 10 : timer::make_json () const
899 : : {
900 : : /* Only generate stuff if we have some sort of time information. */
901 : : #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME)
902 : 10 : json::object *report_obj = new json::object ();
903 : 10 : json::array *json_arr = new json::array ();
904 : 10 : report_obj->set ("timevars", json_arr);
905 : :
906 : 2900 : for (unsigned id = 0; id < (unsigned int) TIMEVAR_LAST; ++id)
907 : : {
908 : 2890 : const timevar_def *tv = &m_timevars[(timevar_id_t) id];
909 : :
910 : : /* Don't print the total execution time here; this isn't initialized
911 : : by the time the sarif output runs. */
912 : 2890 : if ((timevar_id_t) id == TV_TOTAL)
913 : 10 : continue;
914 : :
915 : : /* Don't emit timing variables that were never used. */
916 : 2880 : if (!tv->used)
917 : 2622 : continue;
918 : :
919 : 258 : bool any_children_with_time = false;
920 : 258 : if (tv->children)
921 : 112 : for (child_map_t::iterator i = tv->children->begin ();
922 : 198 : i != tv->children->end (); ++i)
923 : 86 : if (! all_zero ((*i).second))
924 : : {
925 : : any_children_with_time = true;
926 : : break;
927 : : }
928 : :
929 : : /* Don't emit timing variables if we're going to get a row of
930 : : zeroes. Unless there are children with non-zero time. */
931 : 266 : if (! any_children_with_time
932 : 258 : && all_zero (tv->elapsed))
933 : 240 : continue;
934 : :
935 : 18 : json_arr->append (tv->make_json ());
936 : : }
937 : :
938 : : /* Special-case for total. */
939 : 10 : {
940 : : /* Get our own total up till now, without affecting TV_TOTAL. */
941 : 10 : struct timevar_time_def total_now;
942 : 10 : struct timevar_time_def total_elapsed;
943 : 10 : get_time (&total_now);
944 : 10 : timevar_diff (&total_elapsed, m_timevars[TV_TOTAL].start_time, total_now);
945 : :
946 : 10 : json::object *total_obj = new json::object();
947 : 10 : json_arr->append (total_obj);
948 : 10 : total_obj->set_string ("name", "TOTAL");
949 : 10 : total_obj->set ("elapsed", make_json_for_timevar_time_def (total_elapsed));
950 : : }
951 : :
952 : 10 : if (m_jit_client_items)
953 : 0 : report_obj->set ("client_items", m_jit_client_items->make_json ());
954 : :
955 : 10 : report_obj->set_bool ("CHECKING_P", CHECKING_P);
956 : 10 : report_obj->set_bool ("flag_checking", flag_checking);
957 : :
958 : 10 : return report_obj;
959 : :
960 : : #else /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
961 : : || defined (HAVE_WALL_TIME) */
962 : : return NULL;
963 : : #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME)
964 : : || defined (HAVE_WALL_TIME) */
965 : : }
966 : :
967 : : /* Get the name of the topmost item. For use by jit for validating
968 : : inputs to gcc_jit_timer_pop. */
969 : : const char *
970 : 1610 : timer::get_topmost_item_name () const
971 : : {
972 : 1610 : if (m_stack)
973 : 1610 : return m_stack->timevar->name;
974 : : else
975 : : return NULL;
976 : : }
977 : :
978 : : /* Prints a message to stderr stating that time elapsed in STR is
979 : : TOTAL (given in microseconds). */
980 : :
981 : : void
982 : 0 : print_time (const char *str, long total)
983 : : {
984 : 0 : long all_time = get_run_time ();
985 : 0 : fprintf (stderr,
986 : : "time in %s: %ld.%06ld (%ld%%)\n",
987 : : str, total / 1000000, total % 1000000,
988 : : all_time == 0 ? 0
989 : 0 : : (long) (((100.0 * (double) total) / (double) all_time) + .5));
990 : 0 : }
|
