1 | /* Timing variables for measuring compiler performance. |
2 | Copyright (C) 2000-2023 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 | timer::named_items::named_items (timer *t) |
160 | : m_timer (t), |
161 | m_hash_map (), |
162 | m_names () |
163 | { |
164 | } |
165 | |
166 | /* The destructor for class timer::named_items. */ |
167 | |
168 | timer::named_items::~named_items () |
169 | { |
170 | } |
171 | |
172 | /* Push the named item onto the timer stack. */ |
173 | |
174 | void |
175 | timer::named_items::push (const char *item_name) |
176 | { |
177 | gcc_assert (item_name); |
178 | |
179 | bool existed; |
180 | timer::timevar_def *def = &m_hash_map.get_or_insert (k: item_name, existed: &existed); |
181 | if (!existed) |
182 | { |
183 | def->elapsed.user = 0; |
184 | def->elapsed.sys = 0; |
185 | def->elapsed.wall = 0; |
186 | def->name = item_name; |
187 | def->standalone = 0; |
188 | m_names.safe_push (obj: item_name); |
189 | } |
190 | m_timer->push_internal (tv: def); |
191 | } |
192 | |
193 | /* Pop the top item from the timer stack. */ |
194 | |
195 | void |
196 | timer::named_items::pop () |
197 | { |
198 | m_timer->pop_internal (); |
199 | } |
200 | |
201 | /* Print the given client item. Helper function for timer::print. */ |
202 | |
203 | void |
204 | timer::named_items::print (FILE *fp, const timevar_time_def *total) |
205 | { |
206 | fprintf (stream: fp, format: "Client items:\n" ); |
207 | for (const char *item_name : m_names) |
208 | { |
209 | timer::timevar_def *def = m_hash_map.get (k: item_name); |
210 | gcc_assert (def); |
211 | m_timer->print_row (fp, total, name: def->name, elapsed: def->elapsed); |
212 | } |
213 | } |
214 | |
215 | /* Create a json value representing this object, suitable for use |
216 | in SARIF output. */ |
217 | |
218 | json::value * |
219 | timer::named_items::make_json () const |
220 | { |
221 | json::array *arr = new json::array (); |
222 | for (const char *item_name : m_names) |
223 | { |
224 | hash_map_t &mut_map = const_cast <hash_map_t &> (m_hash_map); |
225 | timer::timevar_def *def = mut_map.get (k: item_name); |
226 | gcc_assert (def); |
227 | arr->append (v: def->make_json ()); |
228 | } |
229 | 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 | get_time (struct timevar_time_def *now) |
238 | { |
239 | now->user = 0; |
240 | now->sys = 0; |
241 | now->wall = 0; |
242 | now->ggc_mem = timevar_ggc_mem_total; |
243 | |
244 | { |
245 | #ifdef USE_TIMES |
246 | struct tms tms; |
247 | now->wall = times (buffer: &tms) * ticks_to_nanosec; |
248 | now->user = tms.tms_utime * ticks_to_nanosec; |
249 | 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 | } |
264 | |
265 | /* Add the difference between STOP_TIME and START_TIME to TIMER. */ |
266 | |
267 | static void |
268 | timevar_accumulate (struct timevar_time_def *timer, |
269 | struct timevar_time_def *start_time, |
270 | struct timevar_time_def *stop_time) |
271 | { |
272 | timer->user += stop_time->user - start_time->user; |
273 | timer->sys += stop_time->sys - start_time->sys; |
274 | timer->wall += stop_time->wall - start_time->wall; |
275 | timer->ggc_mem += stop_time->ggc_mem - start_time->ggc_mem; |
276 | } |
277 | |
278 | /* Get the difference between STOP_TIME and START_TIME. */ |
279 | |
280 | static void |
281 | timevar_diff (struct timevar_time_def *out, |
282 | const timevar_time_def &start_time, |
283 | const timevar_time_def &stop_time) |
284 | { |
285 | out->user = stop_time.user - start_time.user; |
286 | out->sys = stop_time.sys - start_time.sys; |
287 | out->wall = stop_time.wall - start_time.wall; |
288 | out->ggc_mem = stop_time.ggc_mem - start_time.ggc_mem; |
289 | } |
290 | |
291 | /* Class timer's constructor. */ |
292 | |
293 | timer::timer () : |
294 | m_stack (NULL), |
295 | m_unused_stack_instances (NULL), |
296 | m_start_time (), |
297 | m_jit_client_items (NULL) |
298 | { |
299 | /* Zero all elapsed times. */ |
300 | memset (s: m_timevars, c: 0, n: 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 | ticks_to_nanosec = TICKS_TO_NANOSEC; |
312 | #endif |
313 | #ifdef USE_CLOCK |
314 | clocks_to_nanosec = CLOCKS_TO_NANOSEC; |
315 | #endif |
316 | } |
317 | |
318 | /* Class timer's destructor. */ |
319 | |
320 | timer::~timer () |
321 | { |
322 | timevar_stack_def *iter, *next; |
323 | |
324 | for (iter = m_stack; iter; iter = next) |
325 | { |
326 | next = iter->next; |
327 | free (ptr: iter); |
328 | } |
329 | for (iter = m_unused_stack_instances; iter; iter = next) |
330 | { |
331 | next = iter->next; |
332 | free (ptr: iter); |
333 | } |
334 | for (unsigned i = 0; i < TIMEVAR_LAST; ++i) |
335 | delete m_timevars[i].children; |
336 | |
337 | delete m_jit_client_items; |
338 | } |
339 | |
340 | /* Initialize timing variables. */ |
341 | |
342 | void |
343 | timevar_init (void) |
344 | { |
345 | if (g_timer) |
346 | return; |
347 | |
348 | 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 | timer::push (timevar_id_t timevar) |
360 | { |
361 | struct timevar_def *tv = &m_timevars[timevar]; |
362 | push_internal (tv); |
363 | } |
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 | timer::push_internal (struct timevar_def *tv) |
370 | { |
371 | struct timevar_stack_def *context; |
372 | struct timevar_time_def now; |
373 | |
374 | gcc_assert (tv); |
375 | |
376 | /* Mark this timing variable as used. */ |
377 | tv->used = 1; |
378 | |
379 | /* Can't push a standalone timer. */ |
380 | gcc_assert (!tv->standalone); |
381 | |
382 | /* What time is it? */ |
383 | get_time (now: &now); |
384 | |
385 | /* If the stack isn't empty, attribute the current elapsed time to |
386 | the old topmost element. */ |
387 | if (m_stack) |
388 | timevar_accumulate (timer: &m_stack->timevar->elapsed, start_time: &m_start_time, stop_time: &now); |
389 | |
390 | /* Reset the start time; from now on, time is attributed to |
391 | TIMEVAR. */ |
392 | 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 | if (m_unused_stack_instances != NULL) |
397 | { |
398 | context = m_unused_stack_instances; |
399 | m_unused_stack_instances = m_unused_stack_instances->next; |
400 | } |
401 | else |
402 | context = XNEW (struct timevar_stack_def); |
403 | |
404 | /* Fill it in and put it on the stack. */ |
405 | context->timevar = tv; |
406 | context->next = m_stack; |
407 | m_stack = context; |
408 | } |
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 | timer::pop (timevar_id_t timevar) |
418 | { |
419 | gcc_assert (&m_timevars[timevar] == m_stack->timevar); |
420 | |
421 | pop_internal (); |
422 | } |
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 | timer::pop_internal () |
429 | { |
430 | struct timevar_time_def now; |
431 | struct timevar_stack_def *popped = m_stack; |
432 | |
433 | /* What time is it? */ |
434 | get_time (now: &now); |
435 | |
436 | /* Attribute the elapsed time to the element we're popping. */ |
437 | timevar_accumulate (timer: &popped->timevar->elapsed, start_time: &m_start_time, stop_time: &now); |
438 | |
439 | /* Take the item off the stack. */ |
440 | m_stack = m_stack->next; |
441 | |
442 | /* Record the elapsed sub-time to the parent as well. */ |
443 | if (m_stack && time_report_details) |
444 | { |
445 | if (! m_stack->timevar->children) |
446 | m_stack->timevar->children = new child_map_t (5); |
447 | bool existed_p; |
448 | timevar_time_def &time |
449 | = m_stack->timevar->children->get_or_insert (k: popped->timevar, existed: &existed_p); |
450 | if (! existed_p) |
451 | memset (s: &time, c: 0, n: sizeof (timevar_time_def)); |
452 | timevar_accumulate (timer: &time, start_time: &m_start_time, stop_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 | 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 | popped->next = m_unused_stack_instances; |
462 | m_unused_stack_instances = popped; |
463 | } |
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 | timevar_start (timevar_id_t timevar) |
471 | { |
472 | if (!g_timer) |
473 | return; |
474 | |
475 | g_timer->start (tv: timevar); |
476 | } |
477 | |
478 | /* See timevar_start above. */ |
479 | |
480 | void |
481 | timer::start (timevar_id_t timevar) |
482 | { |
483 | struct timevar_def *tv = &m_timevars[timevar]; |
484 | |
485 | /* Mark this timing variable as used. */ |
486 | tv->used = 1; |
487 | |
488 | /* Don't allow the same timing variable to be started more than |
489 | once. */ |
490 | gcc_assert (!tv->standalone); |
491 | tv->standalone = 1; |
492 | |
493 | get_time (now: &tv->start_time); |
494 | } |
495 | |
496 | /* Stop timing TIMEVAR. Time elapsed since timevar_start was called |
497 | is attributed to it. */ |
498 | |
499 | void |
500 | timevar_stop (timevar_id_t timevar) |
501 | { |
502 | if (!g_timer) |
503 | return; |
504 | |
505 | g_timer->stop (tv: timevar); |
506 | } |
507 | |
508 | /* See timevar_stop above. */ |
509 | |
510 | void |
511 | timer::stop (timevar_id_t timevar) |
512 | { |
513 | struct timevar_def *tv = &m_timevars[timevar]; |
514 | struct timevar_time_def now; |
515 | |
516 | /* TIMEVAR must have been started via timevar_start. */ |
517 | gcc_assert (tv->standalone); |
518 | tv->standalone = 0; /* Enable a restart. */ |
519 | |
520 | get_time (now: &now); |
521 | timevar_accumulate (timer: &tv->elapsed, start_time: &tv->start_time, stop_time: &now); |
522 | } |
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 | timevar_cond_start (timevar_id_t timevar) |
533 | { |
534 | if (!g_timer) |
535 | return false; |
536 | |
537 | return g_timer->cond_start (tv: timevar); |
538 | } |
539 | |
540 | /* See timevar_cond_start above. */ |
541 | |
542 | bool |
543 | timer::cond_start (timevar_id_t timevar) |
544 | { |
545 | struct timevar_def *tv = &m_timevars[timevar]; |
546 | |
547 | /* Mark this timing variable as used. */ |
548 | tv->used = 1; |
549 | |
550 | 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 | tv->standalone = 1; |
556 | |
557 | get_time (now: &tv->start_time); |
558 | 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 | timevar_cond_stop (timevar_id_t timevar, bool running) |
568 | { |
569 | if (!g_timer || running) |
570 | return; |
571 | |
572 | g_timer->cond_stop (tv: timevar); |
573 | } |
574 | |
575 | /* See timevar_cond_stop above. */ |
576 | |
577 | void |
578 | timer::cond_stop (timevar_id_t timevar) |
579 | { |
580 | struct timevar_def *tv; |
581 | struct timevar_time_def now; |
582 | |
583 | tv = &m_timevars[timevar]; |
584 | |
585 | /* TIMEVAR must have been started via timevar_cond_start. */ |
586 | gcc_assert (tv->standalone); |
587 | tv->standalone = 0; /* Enable a restart. */ |
588 | |
589 | get_time (now: &now); |
590 | timevar_accumulate (timer: &tv->elapsed, start_time: &tv->start_time, stop_time: &now); |
591 | } |
592 | |
593 | /* Push the named item onto the timing stack. */ |
594 | |
595 | void |
596 | timer::push_client_item (const char *item_name) |
597 | { |
598 | gcc_assert (item_name); |
599 | |
600 | /* Lazily create the named_items instance. */ |
601 | if (!m_jit_client_items) |
602 | m_jit_client_items = new named_items (this); |
603 | |
604 | m_jit_client_items->push (item_name); |
605 | } |
606 | |
607 | /* Pop the top-most client item from the timing stack. */ |
608 | |
609 | void |
610 | timer::pop_client_item () |
611 | { |
612 | gcc_assert (m_jit_client_items); |
613 | m_jit_client_items->pop (); |
614 | } |
615 | |
616 | /* Validate that phase times are consistent. */ |
617 | |
618 | void |
619 | timer::validate_phases (FILE *fp) const |
620 | { |
621 | unsigned int /* timevar_id_t */ id; |
622 | const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed; |
623 | uint64_t phase_user = 0; |
624 | uint64_t phase_sys = 0; |
625 | uint64_t phase_wall = 0; |
626 | size_t phase_ggc_mem = 0; |
627 | static char phase_prefix[] = "phase " ; |
628 | |
629 | for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id) |
630 | { |
631 | const timevar_def *tv = &m_timevars[(timevar_id_t) id]; |
632 | |
633 | /* Don't evaluate timing variables that were never used. */ |
634 | if (!tv->used) |
635 | continue; |
636 | |
637 | if (startswith (str: tv->name, prefix: phase_prefix)) |
638 | { |
639 | phase_user += tv->elapsed.user; |
640 | phase_sys += tv->elapsed.sys; |
641 | phase_wall += tv->elapsed.wall; |
642 | phase_ggc_mem += tv->elapsed.ggc_mem; |
643 | } |
644 | } |
645 | |
646 | if (phase_user > total->user |
647 | || phase_sys > total->sys |
648 | || phase_wall > total->wall |
649 | || phase_ggc_mem > total->ggc_mem) |
650 | { |
651 | |
652 | fprintf (stream: fp, format: "Timing error: total of phase timers exceeds total time.\n" ); |
653 | if (phase_user > total->user) |
654 | fprintf (stream: fp, format: "user %13" PRIu64 " > %13" PRIu64 "\n" , |
655 | phase_user, total->user); |
656 | if (phase_sys > total->sys) |
657 | fprintf (stream: fp, format: "sys %13" PRIu64 " > %13" PRIu64 "\n" , |
658 | phase_sys, total->sys); |
659 | if (phase_wall > total->wall) |
660 | fprintf (stream: fp, format: "wall %13" PRIu64 " > %13" PRIu64 "\n" , |
661 | phase_wall, total->wall); |
662 | if (phase_ggc_mem > total->ggc_mem) |
663 | fprintf (stream: fp, format: "ggc_mem %13lu > %13lu\n" , (unsigned long)phase_ggc_mem, |
664 | (unsigned long)total->ggc_mem); |
665 | gcc_unreachable (); |
666 | } |
667 | } |
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 | 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 | fprintf (stream: fp, format: " %-35s:" , name); |
681 | |
682 | #ifdef HAVE_USER_TIME |
683 | /* Print user-mode time for this process. */ |
684 | fprintf (stream: fp, format: "%7.2f (%3.0f%%)" , |
685 | nanosec_to_floating_sec (elapsed.user), |
686 | 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 | fprintf (stream: fp, format: "%7.2f (%3.0f%%)" , |
692 | nanosec_to_floating_sec (elapsed.sys), |
693 | percent_of (total->sys, elapsed.sys)); |
694 | #endif /* HAVE_SYS_TIME */ |
695 | |
696 | #ifdef HAVE_WALL_TIME |
697 | /* Print wall clock time elapsed. */ |
698 | fprintf (stream: fp, format: "%7.2f (%3.0f%%)" , |
699 | nanosec_to_floating_sec (elapsed.wall), |
700 | percent_of (total->wall, elapsed.wall)); |
701 | #endif /* HAVE_WALL_TIME */ |
702 | |
703 | /* Print the amount of ggc memory allocated. */ |
704 | fprintf (stream: fp, PRsa (6) " (%3.0f%%)" , |
705 | SIZE_AMOUNT (elapsed.ggc_mem), |
706 | (total->ggc_mem == 0 |
707 | ? 0 |
708 | : (float) elapsed.ggc_mem / total->ggc_mem) * 100); |
709 | |
710 | putc (c: '\n', stream: fp); |
711 | } |
712 | |
713 | /* Return whether ELAPSED is all zero. */ |
714 | |
715 | bool |
716 | timer::all_zero (const timevar_time_def &elapsed) |
717 | { |
718 | /* 5000000 nanosec == 5e-3 seconds. */ |
719 | uint64_t tiny = 5000000; |
720 | return (elapsed.user < tiny |
721 | && elapsed.sys < tiny |
722 | && elapsed.wall < tiny |
723 | && 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 | 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 | unsigned int /* timevar_id_t */ id; |
736 | const timevar_time_def *total = &m_timevars[TV_TOTAL].elapsed; |
737 | struct timevar_time_def now; |
738 | |
739 | /* Update timing information in case we're calling this from GDB. */ |
740 | |
741 | if (fp == 0) |
742 | fp = stderr; |
743 | |
744 | /* What time is it? */ |
745 | get_time (now: &now); |
746 | |
747 | /* If the stack isn't empty, attribute the current elapsed time to |
748 | the old topmost element. */ |
749 | if (m_stack) |
750 | timevar_accumulate (timer: &m_stack->timevar->elapsed, start_time: &m_start_time, stop_time: &now); |
751 | |
752 | /* Reset the start time; from now on, time is attributed to |
753 | TIMEVAR. */ |
754 | m_start_time = now; |
755 | |
756 | fprintf (stream: fp, format: "\n%-35s%16s%14s%14s%14s\n" , "Time variable" , "usr" , "sys" , |
757 | "wall" , "GGC" ); |
758 | if (m_jit_client_items) |
759 | fputs (s: "GCC items:\n" , stream: fp); |
760 | for (id = 0; id < (unsigned int) TIMEVAR_LAST; ++id) |
761 | { |
762 | 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 | if ((timevar_id_t) id == TV_TOTAL) |
767 | continue; |
768 | |
769 | /* Don't print timing variables that were never used. */ |
770 | if (!tv->used) |
771 | continue; |
772 | |
773 | bool any_children_with_time = false; |
774 | if (tv->children) |
775 | for (child_map_t::iterator i = tv->children->begin (); |
776 | i != tv->children->end (); ++i) |
777 | if (! all_zero (elapsed: (*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 | if (! any_children_with_time |
786 | && all_zero (elapsed: tv->elapsed)) |
787 | continue; |
788 | |
789 | print_row (fp, total, name: tv->name, elapsed: tv->elapsed); |
790 | |
791 | if (tv->children) |
792 | for (child_map_t::iterator i = tv->children->begin (); |
793 | i != tv->children->end (); ++i) |
794 | { |
795 | timevar_def *tv2 = (*i).first; |
796 | /* Don't print timing variables if we're going to get a row of |
797 | zeroes. */ |
798 | if (! all_zero (elapsed: (*i).second)) |
799 | { |
800 | char lname[256]; |
801 | snprintf (s: lname, maxlen: 256, format: "`- %s" , tv2->name); |
802 | print_row (fp, total, name: lname, elapsed: (*i).second); |
803 | } |
804 | } |
805 | } |
806 | if (m_jit_client_items) |
807 | m_jit_client_items->print (fp, total); |
808 | |
809 | /* Print total time. */ |
810 | fprintf (stream: fp, format: " %-35s:" , "TOTAL" ); |
811 | #ifdef HAVE_USER_TIME |
812 | fprintf (stream: fp, format: "%7.2f " , nanosec_to_floating_sec (total->user)); |
813 | #endif |
814 | #ifdef HAVE_SYS_TIME |
815 | fprintf (stream: fp, format: "%8.2f " , nanosec_to_floating_sec (total->sys)); |
816 | #endif |
817 | #ifdef HAVE_WALL_TIME |
818 | fprintf (stream: fp, format: "%8.2f " , nanosec_to_floating_sec (total->wall)); |
819 | #endif |
820 | fprintf (stream: fp, PRsa (7) "\n" , SIZE_AMOUNT (total->ggc_mem)); |
821 | |
822 | if (CHECKING_P || flag_checking) |
823 | fprintf (stream: fp, format: "Extra diagnostic checks enabled; compiler may run slowly.\n" ); |
824 | if (CHECKING_P) |
825 | fprintf (stream: fp, format: "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 | validate_phases (fp); |
835 | } |
836 | |
837 | /* Create a json value representing this object, suitable for use |
838 | in SARIF output. */ |
839 | |
840 | json::object * |
841 | make_json_for_timevar_time_def (const timevar_time_def &ttd) |
842 | { |
843 | json::object *obj = new json::object (); |
844 | obj->set (key: "user" , |
845 | v: new json::float_number (nanosec_to_floating_sec (ttd.user))); |
846 | obj->set (key: "sys" , v: new json::float_number (nanosec_to_floating_sec (ttd.sys))); |
847 | obj->set (key: "wall" , |
848 | v: new json::float_number (nanosec_to_floating_sec (ttd.wall))); |
849 | obj->set (key: "ggc_mem" , v: new json::integer_number (ttd.ggc_mem)); |
850 | return obj; |
851 | } |
852 | #undef nanosec_to_floating_sec |
853 | #undef percent_of |
854 | |
855 | /* Create a json value representing this object, suitable for use |
856 | in SARIF output. */ |
857 | |
858 | json::value * |
859 | timer::timevar_def::make_json () const |
860 | { |
861 | json::object *timevar_obj = new json::object (); |
862 | timevar_obj->set (key: "name" , v: new json::string (name)); |
863 | timevar_obj->set (key: "elapsed" , v: make_json_for_timevar_time_def (ttd: elapsed)); |
864 | |
865 | if (children) |
866 | { |
867 | bool any_children_with_time = false; |
868 | for (auto i : *children) |
869 | if (!all_zero (elapsed: i.second)) |
870 | { |
871 | any_children_with_time = true; |
872 | break; |
873 | } |
874 | if (any_children_with_time) |
875 | { |
876 | json::array *children_arr = new json::array (); |
877 | timevar_obj->set (key: "children" , v: children_arr); |
878 | for (auto i : *children) |
879 | { |
880 | /* Don't emit timing variables if we're going to get a row of |
881 | zeroes. */ |
882 | if (all_zero (elapsed: i.second)) |
883 | continue; |
884 | json::object *child_obj = new json::object; |
885 | children_arr->append (v: child_obj); |
886 | child_obj->set (key: "name" , v: new json::string (i.first->name)); |
887 | child_obj->set (key: "elapsed" , |
888 | v: make_json_for_timevar_time_def (ttd: i.second)); |
889 | } |
890 | } |
891 | } |
892 | |
893 | return timevar_obj; |
894 | } |
895 | |
896 | /* Create a json value representing this object, suitable for use |
897 | in SARIF output. */ |
898 | |
899 | json::value * |
900 | timer::make_json () const |
901 | { |
902 | /* Only generate stuff if we have some sort of time information. */ |
903 | #if defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) || defined (HAVE_WALL_TIME) |
904 | json::object *report_obj = new json::object (); |
905 | json::array *json_arr = new json::array (); |
906 | report_obj->set (key: "timevars" , v: json_arr); |
907 | |
908 | for (unsigned id = 0; id < (unsigned int) TIMEVAR_LAST; ++id) |
909 | { |
910 | const timevar_def *tv = &m_timevars[(timevar_id_t) id]; |
911 | |
912 | /* Don't print the total execution time here; this isn't initialized |
913 | by the time the sarif output runs. */ |
914 | if ((timevar_id_t) id == TV_TOTAL) |
915 | continue; |
916 | |
917 | /* Don't emit timing variables that were never used. */ |
918 | if (!tv->used) |
919 | continue; |
920 | |
921 | bool any_children_with_time = false; |
922 | if (tv->children) |
923 | for (child_map_t::iterator i = tv->children->begin (); |
924 | i != tv->children->end (); ++i) |
925 | if (! all_zero (elapsed: (*i).second)) |
926 | { |
927 | any_children_with_time = true; |
928 | break; |
929 | } |
930 | |
931 | /* Don't emit timing variables if we're going to get a row of |
932 | zeroes. Unless there are children with non-zero time. */ |
933 | if (! any_children_with_time |
934 | && all_zero (elapsed: tv->elapsed)) |
935 | continue; |
936 | |
937 | json_arr->append (v: tv->make_json ()); |
938 | } |
939 | |
940 | /* Special-case for total. */ |
941 | { |
942 | /* Get our own total up till now, without affecting TV_TOTAL. */ |
943 | struct timevar_time_def total_now; |
944 | struct timevar_time_def total_elapsed; |
945 | get_time (now: &total_now); |
946 | timevar_diff (out: &total_elapsed, start_time: m_timevars[TV_TOTAL].start_time, stop_time: total_now); |
947 | |
948 | json::object *total_obj = new json::object(); |
949 | json_arr->append (v: total_obj); |
950 | total_obj->set (key: "name" , v: new json::string ("TOTAL" )); |
951 | total_obj->set (key: "elapsed" , v: make_json_for_timevar_time_def (ttd: total_elapsed)); |
952 | } |
953 | |
954 | if (m_jit_client_items) |
955 | report_obj->set (key: "client_items" , v: m_jit_client_items->make_json ()); |
956 | |
957 | report_obj->set (key: "CHECKING_P" , v: new json::literal ((bool)CHECKING_P)); |
958 | report_obj->set (key: "flag_checking" , v: new json::literal ((bool)flag_checking)); |
959 | |
960 | return report_obj; |
961 | |
962 | #else /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) |
963 | || defined (HAVE_WALL_TIME) */ |
964 | return NULL; |
965 | #endif /* defined (HAVE_USER_TIME) || defined (HAVE_SYS_TIME) |
966 | || defined (HAVE_WALL_TIME) */ |
967 | } |
968 | |
969 | /* Get the name of the topmost item. For use by jit for validating |
970 | inputs to gcc_jit_timer_pop. */ |
971 | const char * |
972 | timer::get_topmost_item_name () const |
973 | { |
974 | if (m_stack) |
975 | return m_stack->timevar->name; |
976 | else |
977 | return NULL; |
978 | } |
979 | |
980 | /* Prints a message to stderr stating that time elapsed in STR is |
981 | TOTAL (given in microseconds). */ |
982 | |
983 | void |
984 | print_time (const char *str, long total) |
985 | { |
986 | long all_time = get_run_time (); |
987 | fprintf (stderr, |
988 | format: "time in %s: %ld.%06ld (%ld%%)\n" , |
989 | str, total / 1000000, total % 1000000, |
990 | all_time == 0 ? 0 |
991 | : (long) (((100.0 * (double) total) / (double) all_time) + .5)); |
992 | } |
993 | |