Line data Source code
1 : // The libMesh Finite Element Library.
2 : // Copyright (C) 2002-2026 Benjamin S. Kirk, John W. Peterson, Roy H. Stogner
3 :
4 : // This library is free software; you can redistribute it and/or
5 : // modify it under the terms of the GNU Lesser General Public
6 : // License as published by the Free Software Foundation; either
7 : // version 2.1 of the License, or (at your option) any later version.
8 :
9 : // This library is distributed in the hope that it will be useful,
10 : // but WITHOUT ANY WARRANTY; without even the implied warranty of
11 : // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
12 : // Lesser General Public License for more details.
13 :
14 : // You should have received a copy of the GNU Lesser General Public
15 : // License along with this library; if not, write to the Free Software
16 : // Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
17 :
18 :
19 :
20 : #ifndef LIBMESH_PERFLOG_H
21 : #define LIBMESH_PERFLOG_H
22 :
23 :
24 : // Local includes
25 : #include "libmesh/libmesh_common.h"
26 :
27 : #include "libmesh/threads.h"
28 :
29 : // C++ includes
30 : #include <cstddef>
31 : #include <map>
32 : #include <stack>
33 : #include <string>
34 : #include <vector>
35 : #include <deque>
36 : #include <memory>
37 : #ifdef LIBMESH_HAVE_SYS_TIME_H
38 : #include <sys/time.h> // gettimeofday() on Unix
39 : #endif
40 : #ifndef LIBMESH_HAVE_GETTIMEOFDAY
41 : #include "libmesh/win_gettimeofday.h" // gettimeofday() on Windows
42 : #endif
43 : #ifdef LIBMESH_HAVE_NVTX_API
44 : #include <nvtx3/nvtx3.hpp>
45 : #endif
46 : #ifdef LIBMESH_HAVE_OPENMP
47 : #include <omp.h>
48 : #endif
49 :
50 : namespace libMesh
51 : {
52 :
53 : /**
54 : * The \p PerfData class simply contains the performance
55 : * data that is recorded for individual events.
56 : *
57 : * \author Benjamin Kirk
58 : * \date 2003
59 : * \brief Data object managed by PerfLog
60 : */
61 : class PerfData
62 : {
63 : public:
64 :
65 : /**
66 : * Constructor. Initializes data to be empty.
67 : */
68 119529 : PerfData () :
69 64041 : tot_time(0.),
70 64041 : tot_time_incl_sub(0.),
71 64041 : tstart(),
72 64041 : tstart_incl_sub(),
73 64041 : count(0),
74 64041 : open(false),
75 119529 : called_recursively(0)
76 36144 : {}
77 :
78 :
79 : /**
80 : * Total time spent in this event.
81 : */
82 : double tot_time;
83 :
84 : /**
85 : * Total time spent in this event, including sub-events.
86 : */
87 : double tot_time_incl_sub;
88 :
89 : /**
90 : * Structure defining when the event
91 : * was last started.
92 : */
93 : struct timeval tstart;
94 :
95 : /**
96 : * Structure defining when the event
97 : * was last started, including sub-events.
98 : */
99 : struct timeval tstart_incl_sub;
100 :
101 : /**
102 : * The number of times this event has
103 : * been executed
104 : */
105 : unsigned int count;
106 :
107 : /**
108 : * Flag indicating if we are currently
109 : * monitoring this event. Should only
110 : * be true while the event is executing.
111 : */
112 : bool open;
113 :
114 : void start ();
115 : void restart ();
116 : double pause ();
117 : double pause_for(PerfData & other);
118 : double stopit ();
119 :
120 : /**
121 : * Sums timing results from \p other
122 : */
123 1832 : PerfData & operator += (const PerfData & other)
124 : {
125 1832 : libmesh_assert(!open);
126 3664 : tot_time += other.tot_time;
127 3664 : tot_time_incl_sub += other.tot_time_incl_sub;
128 3664 : count += other.count;
129 :
130 1832 : return *this;
131 : }
132 :
133 : int called_recursively;
134 :
135 : protected:
136 : double stop_or_pause(const bool do_stop);
137 : };
138 :
139 :
140 :
141 :
142 : /**
143 : * The \p PerfLog class allows monitoring of specific events.
144 : * An event is defined by a unique string that functions as
145 : * a label. Each time the event is executed data are recorded.
146 : * This class is particularly useful for finding performance
147 : * bottlenecks.
148 : *
149 : * \author Benjamin Kirk
150 : * \date 2003
151 : * \brief Responsible for timing and summarizing events.
152 : */
153 : class PerfLog
154 : {
155 : public:
156 :
157 : /**
158 : * Constructor. \p label_name is the name of the object, which
159 : * will bw print in the log to distinguish it from other objects.
160 : * \p log_events is a flag to optionally
161 : * disable logging. You can use this flag to turn off
162 : * logging without touching any other code.
163 : */
164 : PerfLog(std::string label_name="",
165 : const bool log_events=true);
166 :
167 : /**
168 : * Destructor. Calls \p clear() and \p print_log().
169 : */
170 : ~PerfLog();
171 :
172 : /**
173 : * Clears all the internal data and restores the
174 : * data structures to a pristine state. This function
175 : * checks to see if it is currently monitoring any
176 : * events, and if so errors. Be sure you are not
177 : * logging any events when you call this function.
178 : */
179 : void clear();
180 :
181 : /**
182 : * Disables performance logging for an active object.
183 : */
184 6092 : void disable_logging() { log_events = false; }
185 :
186 : /**
187 : * Enables performance logging for an active object.
188 : */
189 6092 : void enable_logging() { log_events = true; }
190 :
191 : /**
192 : * \returns \p true iff performance logging is enabled
193 : */
194 3048 : bool logging_enabled() const { return log_events; }
195 :
196 : /**
197 : * Tells the PerfLog to only print log results summarized by header
198 : */
199 : void enable_summarized_logs() { summarize_logs = true; }
200 :
201 : /**
202 : * Tells the PerfLog to print detailed log results (this is the
203 : * default behavior)
204 : */
205 : void disable_summarized_logs() { summarize_logs = false; }
206 :
207 : /**
208 : * \returns \p true iff log results will be summarized by header
209 : */
210 : bool summarized_logs_enabled() { return summarize_logs; }
211 :
212 : /**
213 : * Push the event \p label onto the stack, pausing any active event.
214 : *
215 : * Note - for speed the PerfLog directly considers the *pointers*
216 : * here. Supply pointers to string literals or other character
217 : * arrays whose lifetime will exceed the lifetime of the PerfLog
218 : * object, not to temporarily allocated arrays.
219 : *
220 : * Supply \p per_entity = \p true for events that fire once per mesh entity
221 : * or more often. Such events are timed in the performance log but are
222 : * left out of trace-style profiler annotations: when the library is built
223 : * with NVTX support, every other event also opens an NVTX range. Per-entity
224 : * events would produce large numbers of short ranges in a profiler capture,
225 : * which adds recording overhead, enlarges the capture, and crowds the
226 : * timeline and NVTX summaries.
227 : */
228 : void fast_push (const char * label,
229 : const char * header="",
230 : bool per_entity=false);
231 :
232 : /**
233 : * Push the event \p label onto the stack, pausing any active event.
234 : *
235 : * This method will eventually be deprecated. For backwards
236 : * compatibility, the PerfLog must copy the contents of these
237 : * character arrays into strings, which ironically damages the
238 : * performance we are trying to profile. Use fast_push() (with
239 : * compatible long-lived character array data) instead.
240 : */
241 : void push (const char * label,
242 : const char * header="");
243 :
244 : /**
245 : * Push the event \p label onto the stack, pausing any active event.
246 : *
247 : * This method will eventually be deprecated. String manipulation
248 : * is too low performance to use when performance monitoring hot
249 : * spots. Use fast_push() instead.
250 : */
251 : void push (const std::string & label,
252 : const std::string & header="");
253 :
254 : /**
255 : * Pop the event \p label off the stack, resuming any lower event.
256 : *
257 : * This method must be passed the exact same pointers as were passed
258 : * to fast_push, not merely pointers to identical strings.
259 : * This method is called from the PerfItem destructor, so it should
260 : * not throw. We have therefore marked it noexcept as a reminder.
261 : *
262 : * \p per_entity must match the value supplied to the corresponding
263 : * fast_push(), so that the NVTX range stack stays balanced.
264 : */
265 : void fast_pop (const char * label,
266 : const char * header="",
267 : bool per_entity=false) noexcept;
268 :
269 : /**
270 : * Pop the event \p label off the stack, resuming any lower event.
271 : *
272 : * This method will eventually be deprecated. Use fast_pop() (with
273 : * the exact same pointers supplied to fast_push()) instead.
274 : */
275 : void pop (const char * label,
276 : const char * header="");
277 :
278 : /**
279 : * Pop the event \p label off the stack, resuming any lower event.
280 : *
281 : * This method will eventually be deprecated. String manipulation
282 : * is too low performance to use when performance monitoring hot
283 : * spots. Use fast_pop() instead.
284 : */
285 : void pop (const std::string & label,
286 : const std::string & header="");
287 :
288 : /**
289 : * Start monitoring the event named \p label.
290 : */
291 : void start_event(const std::string & label,
292 : const std::string & header="");
293 :
294 : /**
295 : * Stop monitoring the event named \p label.
296 : */
297 : void stop_event(const std::string & label,
298 : const std::string & header="");
299 :
300 : /**
301 : * Suspend monitoring of the event.
302 : */
303 : void pause_event(const std::string & label,
304 : const std::string & header="");
305 :
306 : /**
307 : * Restart monitoring the event.
308 : */
309 : void restart_event(const std::string & label,
310 : const std::string & header="");
311 :
312 : /**
313 : * \returns A string containing:
314 : * (1) Basic machine information (if first call)
315 : * (2) The performance log
316 : */
317 : std::string get_log() const;
318 :
319 : /**
320 : * \returns A string containing ONLY the information header.
321 : */
322 : std::string get_info_header() const;
323 :
324 : /**
325 : * \returns A string containing ONLY the log information
326 : */
327 : std::string get_perf_info() const;
328 :
329 : /**
330 : * Print the log.
331 : */
332 : void print_log() const;
333 :
334 : /**
335 : * \returns The total time spent on this event.
336 : */
337 : double get_elapsed_time() const;
338 :
339 : /**
340 : * \returns The active time
341 : */
342 : double get_active_time() const;
343 :
344 : /**
345 : * Return the PerfData object associated with a label and header.
346 : */
347 : PerfData get_perf_data(const std::string & label, const std::string & header="");
348 :
349 : /**
350 : * Typdef for the underlying logging data structure.
351 : */
352 : typedef std::map<std::pair<const char *,
353 : const char *>,
354 : PerfData> log_type;
355 :
356 : private:
357 :
358 :
359 : /**
360 : * The label for this object.
361 : */
362 : const std::string label_name;
363 :
364 : /**
365 : * Flag to optionally disable all logging.
366 : */
367 : bool log_events;
368 :
369 : /**
370 : * Flag to optionally summarize logs
371 : */
372 : bool summarize_logs;
373 :
374 : /**
375 : * The total running time for recorded events.
376 : */
377 : double total_time;
378 :
379 : /**
380 : * The time we were constructed or last cleared.
381 : */
382 : struct timeval tstart;
383 :
384 : /**
385 : * The actual log.
386 : *
387 : * An unsorted_map would work fine here and would be asymptotically
388 : * faster, but in my tests for our log sizes there was no
389 : * improvement.
390 : */
391 : log_type log;
392 :
393 : /**
394 : * A stack to hold the current performance log trace.
395 : */
396 : std::stack<PerfData*> log_stack;
397 :
398 : /**
399 : * Flag indicating if print_log() has been called.
400 : * This is used to print a header with machine-specific
401 : * data the first time that print_log() is called.
402 : */
403 : static bool called;
404 :
405 : /**
406 : * Splits a string on whitespace into a vector of separate strings. This is used to make the
407 : * LIBMESH_CONFIGURE_INFO a little more manageable.
408 : */
409 : void split_on_whitespace(const std::string & input,
410 : std::vector<std::string> & output) const;
411 :
412 : /**
413 : * Workaround to give us fixed pointers to character arrays for
414 : * every string. Using std::set instead might work: it won't
415 : * invalidate iterators, which I *think* means it doesn't have any
416 : * reason to modify or copy their contents or otherwise invalidate
417 : * their c_str() pointers... but I can't prove it from the standards
418 : * doc, so let's be safe.
419 : */
420 : std::map<std::string, std::unique_ptr<const char[]>> non_temporary_strings;
421 : };
422 :
423 :
424 :
425 : // ------------------------------------------------------------
426 : // PerfData class member functions
427 : inline
428 10434375 : void PerfData::start ()
429 : {
430 20288602 : this->count++;
431 20288602 : this->called_recursively++;
432 20288602 : gettimeofday (&(this->tstart), nullptr);
433 20288602 : this->tstart_incl_sub = this->tstart;
434 10434375 : }
435 :
436 :
437 :
438 : inline
439 46074284 : void PerfData::restart ()
440 : {
441 91736263 : gettimeofday (&(this->tstart), nullptr);
442 46074686 : }
443 :
444 :
445 :
446 : inline
447 : double PerfData::pause ()
448 : {
449 : return this->stop_or_pause(false);
450 : }
451 :
452 :
453 : inline
454 112028399 : double PerfData::stop_or_pause(const bool do_stop)
455 : {
456 : // save the start times, reuse the structure we have rather than create
457 : // a new one.
458 : const time_t
459 112028399 : tstart_tv_sec = this->tstart.tv_sec,
460 112028399 : tstart_tv_usec = this->tstart.tv_usec;
461 :
462 112028399 : gettimeofday (&(this->tstart), nullptr);
463 :
464 223524584 : const double elapsed_time = (static_cast<double>(this->tstart.tv_sec - tstart_tv_sec) +
465 112028399 : static_cast<double>(this->tstart.tv_usec - tstart_tv_usec)*1.e-6);
466 :
467 112028399 : this->tot_time += elapsed_time;
468 :
469 112028399 : if (do_stop)
470 : {
471 223524584 : const double elapsed_time_incl_sub = (static_cast<double>(this->tstart.tv_sec - this->tstart_incl_sub.tv_sec) +
472 112028399 : static_cast<double>(this->tstart.tv_usec - this->tstart_incl_sub.tv_usec)*1.e-6);
473 :
474 112028399 : this->tot_time_incl_sub += elapsed_time_incl_sub;
475 : }
476 :
477 112028399 : return elapsed_time;
478 : }
479 :
480 :
481 :
482 : inline
483 91920646 : double PerfData::pause_for(PerfData & other)
484 : {
485 91920646 : gettimeofday (&(other.tstart), nullptr);
486 :
487 183840890 : const double elapsed_time = (static_cast<double>(other.tstart.tv_sec - this->tstart.tv_sec) +
488 91920646 : static_cast<double>(other.tstart.tv_usec - this->tstart.tv_usec)*1.e-6);
489 91920646 : this->tot_time += elapsed_time;
490 :
491 91920646 : other.count++;
492 91920646 : other.called_recursively++;
493 91920646 : other.tstart_incl_sub = other.tstart;
494 :
495 91920646 : return elapsed_time;
496 : }
497 :
498 :
499 :
500 : inline
501 55976847 : double PerfData::stopit ()
502 : {
503 : // stopit is just similar to pause except that it decrements the
504 : // recursive call counter
505 :
506 112028399 : this->called_recursively--;
507 112028399 : return this->stop_or_pause(true);
508 : }
509 :
510 :
511 :
512 : // ------------------------------------------------------------
513 : // PerfLog class inline member functions
514 : inline
515 132553320 : void PerfLog::fast_push (const char * label,
516 : const char * header,
517 : bool per_entity)
518 : {
519 : #ifndef LIBMESH_HAVE_NVTX_API
520 66145491 : libmesh_ignore(per_entity);
521 : #endif
522 :
523 132553320 : if (this->log_events)
524 : {
525 : // The global perflog stack may not be thread-safe, but if we're
526 : // creating threads we should have disabled it already
527 55976847 : libmesh_assert_equal_to(Threads::active_threads, 1);
528 : #ifdef LIBMESH_HAVE_OPENMP
529 : // Users might be doing their own non-libMesh threading. We
530 : // can't catch every case of that but we can catch OpenMP
531 55976847 : libmesh_assert_equal_to(omp_get_num_threads(), 1);
532 : #endif
533 :
534 : // Get a reference to the event data to avoid
535 : // repeated map lookups
536 224162942 : PerfData * perf_data = &(log[std::make_pair(header,label)]);
537 :
538 112209248 : if (!log_stack.empty())
539 91920646 : total_time += log_stack.top()->pause_for(*perf_data);
540 : else
541 10434375 : perf_data->start();
542 55976847 : log_stack.push(perf_data);
543 :
544 : #ifdef LIBMESH_HAVE_NVTX_API
545 : // This takes a single const char *, and we don't want to waste
546 : // time allocating a new string on every push, so for now we'll
547 : // drop the header. Maybe we should allocate a new string in
548 : // the PerfData?
549 : if (!per_entity)
550 : nvtxRangePushA(label);
551 : #endif
552 : }
553 132553320 : }
554 :
555 :
556 :
557 : inline
558 132380135 : void PerfLog::fast_pop(const char * libmesh_dbg_var(label),
559 : const char * libmesh_dbg_var(header),
560 : bool per_entity) noexcept
561 : {
562 : #ifndef LIBMESH_HAVE_NVTX_API
563 66145491 : libmesh_ignore(per_entity);
564 : #endif
565 :
566 132380135 : if (this->log_events)
567 : {
568 : // The global perflog stack may not be thread-safe, but if we're
569 : // creating threads we should have disabled it already
570 55976847 : libmesh_exceptionless_assert(Threads::active_threads == 1);
571 : #ifdef LIBMESH_HAVE_OPENMP
572 : // Users might be doing their own non-libMesh threading. We
573 : // can't catch every case of that but we can catch OpenMP.
574 55976847 : libmesh_exceptionless_assert(omp_get_num_threads() == 1);
575 : #endif
576 :
577 : #ifdef LIBMESH_HAVE_NVTX_API
578 : if (!per_entity)
579 : nvtxRangePop();
580 : #endif
581 : // If there's nothing on the stack, then we can't pop anything. Previously we
582 : // asserted that the log_stack was not empty, but we should not throw from
583 : // this function, so instead just return in that case.
584 112028399 : if (log_stack.empty())
585 0 : return;
586 :
587 : #ifndef NDEBUG
588 : // In debug mode, we carefully check that before popping the stack,
589 : // we have the correct event.
590 :
591 : // Get pointer to corresponding PerfData, or nullptr if it does not exist.
592 55976847 : auto it = log.find(std::make_pair(header, label));
593 55976847 : PerfData * perf_data = (it == log.end()) ? nullptr : &(it->second);
594 :
595 : // If this event is not found in the log, then it could indicate
596 : // that you have a STOP_LOG(a,b) without a corresponding
597 : // START_LOG(a,b) call. We don't pop anything from the log_stack
598 : // in this case.
599 55976847 : if (!perf_data)
600 : {
601 0 : libMesh::err << "PerfLog can't pop (" << header << ',' << label << ')' << std::endl;
602 0 : libMesh::err << "No such event was found in the log, you may have a mismatched START/STOP_LOG statement." << std::endl;
603 0 : return;
604 : }
605 :
606 55976847 : if (perf_data != log_stack.top())
607 : {
608 : // We've been asked to pop an event which is not at the
609 : // top() of the log_stack. The event may be deeper in the
610 : // stack instead, so search for it now. If we find it, we'll
611 : // pop all intermediate items off the stack (abandoning any
612 : // attempt to time them accurately) and let the optimized
613 : // code path take over from there.
614 0 : std::deque<PerfData*> tmp_stack;
615 :
616 0 : while (!log_stack.empty() && perf_data != log_stack.top())
617 : {
618 0 : tmp_stack.push_front(log_stack.top());
619 0 : log_stack.pop();
620 : }
621 :
622 : // If we exhaustively searched the log_stack without finding
623 : // the event, we can't do anything else so just put
624 : // everything back and return, not doing anything for this
625 : // event.
626 0 : if (log_stack.empty())
627 : {
628 0 : while (!tmp_stack.empty())
629 : {
630 0 : log_stack.push(tmp_stack.back());
631 0 : tmp_stack.pop_back();
632 : }
633 :
634 0 : return;
635 : }
636 : }
637 : #endif
638 :
639 : // In optimized mode, we just pop from the top of the stack and
640 : // resume timing the next entry.
641 112028399 : total_time += log_stack.top()->stopit();
642 :
643 55976847 : log_stack.pop();
644 :
645 112028399 : if (!log_stack.empty())
646 91736263 : log_stack.top()->restart();
647 : }
648 : }
649 :
650 :
651 :
652 : inline
653 : double PerfLog::get_elapsed_time () const
654 : {
655 : struct timeval tnow;
656 :
657 : gettimeofday (&tnow, nullptr);
658 :
659 : const double elapsed_time = (static_cast<double>(tnow.tv_sec - tstart.tv_sec) +
660 : static_cast<double>(tnow.tv_usec - tstart.tv_usec)*1.e-6);
661 : return elapsed_time;
662 : }
663 :
664 : inline
665 : double PerfLog::get_active_time() const
666 : {
667 : return total_time;
668 : }
669 :
670 : } // namespace libMesh
671 :
672 :
673 :
674 : #endif // LIBMESH_PERFLOG_H
|
