deal.II version GIT relicensing-1936-ge55124254b 2024-10-04 21:10:00+00:00
\(\newcommand{\dealvcentcolon}{\mathrel{\mathop{:}}}\) \(\newcommand{\dealcoloneq}{\dealvcentcolon\mathrel{\mkern-1.2mu}=}\) \(\newcommand{\jump}[1]{\left[\!\left[ #1 \right]\!\right]}\) \(\newcommand{\average}[1]{\left\{\!\left\{ #1 \right\}\!\right\}}\)
Loading...
Searching...
No Matches
timer.cc
Go to the documentation of this file.
1// ------------------------------------------------------------------------
2//
3// SPDX-License-Identifier: LGPL-2.1-or-later
4// Copyright (C) 1998 - 2024 by the deal.II authors
5//
6// This file is part of the deal.II library.
7//
8// Part of the source code is dual licensed under Apache-2.0 WITH
9// LLVM-exception OR LGPL-2.1-or-later. Detailed license information
10// governing the source code and code contributions can be found in
11// LICENSE.md and CONTRIBUTING.md at the top level directory of deal.II.
12//
13// ------------------------------------------------------------------------
14
16#include <deal.II/base/mpi.h>
18#include <deal.II/base/timer.h>
20
21#include <boost/io/ios_state.hpp>
22
23#include <algorithm>
24#include <chrono>
25#include <iomanip>
26#include <iostream>
27#include <map>
28#include <sstream>
29#include <string>
30#include <type_traits>
31
32#ifdef DEAL_II_HAVE_SYS_RESOURCE_H
33# include <sys/resource.h>
34#endif
35
36#ifdef DEAL_II_MSVC
37# include <windows.h>
38#endif
39
40
41
43
44namespace internal
45{
46 namespace TimerImplementation
47 {
48 namespace
49 {
54 template <typename T>
55 struct is_duration : std::false_type
56 {};
57
61 template <typename Rep, typename Period>
62 struct is_duration<std::chrono::duration<Rep, Period>> : std::true_type
63 {};
64
70 template <typename T>
71 T
72 from_seconds(const double time)
73 {
74 static_assert(is_duration<T>::value,
75 "The template type should be a duration type.");
76 return T(std::lround(T::period::den * (time / T::period::num)));
77 }
78
83 template <typename Rep, typename Period>
84 double
85 to_seconds(const std::chrono::duration<Rep, Period> duration)
86 {
87 return Period::num * double(duration.count()) / Period::den;
88 }
89
93 void
94 clear_timing_data(Utilities::MPI::MinMaxAvg &data)
95 {
96 data.sum = numbers::signaling_nan<double>();
97 data.min = numbers::signaling_nan<double>();
98 data.max = numbers::signaling_nan<double>();
99 data.avg = numbers::signaling_nan<double>();
102 }
103 } // namespace
104 } // namespace TimerImplementation
105} // namespace internal
106
107
108
111{
112 double system_cpu_duration = 0.0;
113#ifdef DEAL_II_MSVC
114 FILETIME cpuTime, sysTime, createTime, exitTime;
115 const auto succeeded = GetProcessTimes(
116 GetCurrentProcess(), &createTime, &exitTime, &sysTime, &cpuTime);
117 if (succeeded)
118 {
119 system_cpu_duration =
120 (double)(((unsigned long long)cpuTime.dwHighDateTime << 32) |
121 cpuTime.dwLowDateTime) /
122 1e7;
123 }
124 // keep the zero value if GetProcessTimes didn't work
125#elif defined(DEAL_II_HAVE_SYS_RESOURCE_H)
126 rusage usage;
127 getrusage(RUSAGE_SELF, &usage);
128 system_cpu_duration = usage.ru_utime.tv_sec + 1.e-6 * usage.ru_utime.tv_usec;
129#else
130 DEAL_II_WARNING("Unsupported platform. Porting not finished.")
131#endif
132 return time_point(
133 internal::TimerImplementation::from_seconds<duration>(system_cpu_duration));
134}
135
136
137
138template <typename clock_type_>
140 : current_lap_start_time(clock_type::now())
141 , accumulated_time(duration_type::zero())
142 , last_lap_time(duration_type::zero())
143{}
144
145
146
147template <typename clock_type_>
148void
150{
151 current_lap_start_time = clock_type::now();
152 accumulated_time = duration_type::zero();
153 last_lap_time = duration_type::zero();
154}
155
156
157
159 : Timer(MPI_COMM_SELF, /*sync_lap_times=*/false)
160{}
161
162
163
164Timer::Timer(const MPI_Comm mpi_communicator, const bool sync_lap_times_)
165 : running(false)
166 , mpi_communicator(mpi_communicator)
167 , sync_lap_times(sync_lap_times_)
168{
169 reset();
170 start();
171}
172
173
174
175void
177{
178 running = true;
179#ifdef DEAL_II_WITH_MPI
180 if (sync_lap_times)
181 {
182 const int ierr = MPI_Barrier(mpi_communicator);
183 AssertThrowMPI(ierr);
184 }
185#endif
186 wall_times.current_lap_start_time = wall_clock_type::now();
187 cpu_times.current_lap_start_time = cpu_clock_type::now();
188}
189
190
191
192double
194{
195 if (running)
196 {
197 running = false;
198
200 wall_clock_type::now() - wall_times.current_lap_start_time;
201 cpu_times.last_lap_time =
202 cpu_clock_type::now() - cpu_times.current_lap_start_time;
203
205 Utilities::MPI::min_max_avg(internal::TimerImplementation::to_seconds(
208 if (sync_lap_times)
209 {
211 internal::TimerImplementation::from_seconds<
212 decltype(wall_times)::duration_type>(last_lap_wall_time_data.max);
213 cpu_times.last_lap_time = internal::TimerImplementation::from_seconds<
214 decltype(cpu_times)::duration_type>(
216 internal::TimerImplementation::to_seconds(
217 cpu_times.last_lap_time),
219 .max);
220 }
222 cpu_times.accumulated_time += cpu_times.last_lap_time;
224 Utilities::MPI::min_max_avg(internal::TimerImplementation::to_seconds(
227 }
228 return internal::TimerImplementation::to_seconds(cpu_times.accumulated_time);
229}
230
231
232
233double
235{
236 if (running)
237 {
238 const double running_time = internal::TimerImplementation::to_seconds(
239 cpu_clock_type::now() - cpu_times.current_lap_start_time +
240 cpu_times.accumulated_time);
241 return Utilities::MPI::sum(running_time, mpi_communicator);
242 }
243 else
244 {
245 return Utilities::MPI::sum(internal::TimerImplementation::to_seconds(
246 cpu_times.accumulated_time),
248 }
249}
250
251
252
253double
255{
256 return internal::TimerImplementation::to_seconds(cpu_times.last_lap_time);
257}
258
259
260
261double
263{
264 wall_clock_type::duration current_elapsed_wall_time;
265 if (running)
266 current_elapsed_wall_time = wall_clock_type::now() -
269 else
270 current_elapsed_wall_time = wall_times.accumulated_time;
271
272 return internal::TimerImplementation::to_seconds(current_elapsed_wall_time);
273}
274
275
276
277double
279{
280 return internal::TimerImplementation::to_seconds(wall_times.last_lap_time);
281}
282
283
284
285void
287{
289 cpu_times.reset();
290 running = false;
291 internal::TimerImplementation::clear_timing_data(last_lap_wall_time_data);
292 internal::TimerImplementation::clear_timing_data(accumulated_wall_time_data);
293}
294
296
297/* ---------------------------- TimerOutput -------------------------- */
298
299TimerOutput::TimerOutput(std::ostream &stream,
300 const OutputFrequency output_frequency,
301 const OutputType output_type)
302 : output_frequency(output_frequency)
303 , output_type(output_type)
304 , out_stream(stream, true)
305 , output_is_enabled(true)
306 , mpi_communicator(MPI_COMM_SELF)
307{}
308
309
310
312 const OutputFrequency output_frequency,
313 const OutputType output_type)
314 : output_frequency(output_frequency)
315 , output_type(output_type)
316 , out_stream(stream)
317 , output_is_enabled(true)
318 , mpi_communicator(MPI_COMM_SELF)
319{}
320
321
322
323TimerOutput::TimerOutput(const MPI_Comm mpi_communicator,
324 std::ostream &stream,
325 const OutputFrequency output_frequency,
326 const OutputType output_type)
327 : output_frequency(output_frequency)
328 , output_type(output_type)
329 , out_stream(stream, true)
330 , output_is_enabled(true)
331 , mpi_communicator(mpi_communicator)
332{}
333
334
335
336TimerOutput::TimerOutput(const MPI_Comm mpi_communicator,
337 ConditionalOStream &stream,
338 const OutputFrequency output_frequency,
339 const OutputType output_type)
340 : output_frequency(output_frequency)
341 , output_type(output_type)
342 , out_stream(stream)
343 , output_is_enabled(true)
344 , mpi_communicator(mpi_communicator)
345{}
346
347
348
350{
351 auto do_exit = [this]() {
352 try
353 {
354 while (active_sections.size() > 0)
356 // don't print unless we leave all subsections
357 if ((output_frequency == summary ||
359 output_is_enabled == true)
361 }
362 catch (...)
363 {}
364 };
365
366 // avoid communicating with other processes if there is an uncaught
367 // exception
368#ifdef DEAL_II_WITH_MPI
369 if (std::uncaught_exceptions() > 0 && mpi_communicator != MPI_COMM_SELF)
370 {
371 const unsigned int myid =
373 if (myid == 0)
374 std::cerr
375 << "---------------------------------------------------------\n"
376 << "TimerOutput objects finalize timed values printed to the\n"
377 << "screen by communicating over MPI in their destructors.\n"
378 << "Since an exception is currently uncaught, this\n"
379 << "synchronization (and subsequent output) will be skipped\n"
380 << "to avoid a possible deadlock.\n"
381 << "---------------------------------------------------------"
382 << std::endl;
383 }
384 else
385 {
386 do_exit();
387 }
388#else
389 do_exit();
390#endif
391}
392
393
394
395void
396TimerOutput::enter_subsection(const std::string &section_name)
397{
398 std::lock_guard<std::mutex> lock(mutex);
399
400 Assert(section_name.empty() == false, ExcMessage("Section string is empty."));
401
402 Assert(std::find(active_sections.begin(),
403 active_sections.end(),
404 section_name) == active_sections.end(),
405 ExcMessage(std::string("Cannot enter the already active section <") +
406 section_name + ">."));
407
408 if (sections.find(section_name) == sections.end())
409 {
410 if (mpi_communicator != MPI_COMM_SELF)
411 {
412 // create a new timer for this section. the second argument
413 // will ensure that we have an MPI barrier before starting
414 // and stopping a timer, and this ensures that we get the
415 // maximum run time for this section over all processors.
416 // The mpi_communicator from TimerOutput is passed to the
417 // Timer here, so this Timer will collect timing information
418 // among all processes inside mpi_communicator.
419 sections[section_name].timer = Timer(mpi_communicator, true);
420 }
421
422
423 sections[section_name].total_cpu_time = 0;
424 sections[section_name].total_wall_time = 0;
425 sections[section_name].n_calls = 0;
426 }
427
428 sections[section_name].timer.reset();
429 sections[section_name].timer.start();
430 ++sections[section_name].n_calls;
431
432 active_sections.push_back(section_name);
433}
434
435
436
437void
438TimerOutput::leave_subsection(const std::string &section_name)
439{
440 Assert(!active_sections.empty(),
441 ExcMessage("Cannot exit any section because none has been entered!"));
442
443 std::lock_guard<std::mutex> lock(mutex);
444
445 if (!section_name.empty())
446 {
447 Assert(sections.find(section_name) != sections.end(),
448 ExcMessage("Cannot delete a section that was never created."));
449 Assert(std::find(active_sections.begin(),
450 active_sections.end(),
451 section_name) != active_sections.end(),
452 ExcMessage("Cannot delete a section that has not been entered."));
453 }
454
455 // if no string is given, exit the last
456 // active section.
457 const std::string actual_section_name =
458 (section_name.empty() ? active_sections.back() : section_name);
459
460 sections[actual_section_name].timer.stop();
461 sections[actual_section_name].total_wall_time +=
462 sections[actual_section_name].timer.last_wall_time();
463
464 // Get cpu time. On MPI systems, if constructed with an mpi_communicator
465 // like MPI_COMM_WORLD, then the Timer will sum up the CPU time between
466 // processors among the provided mpi_communicator. Therefore, no
467 // communication is needed here.
468 const double cpu_time = sections[actual_section_name].timer.last_cpu_time();
469 sections[actual_section_name].total_cpu_time += cpu_time;
470
471 // in case we have to print out something, do that here...
474 output_is_enabled == true)
475 {
476 std::string output_time;
477 std::ostringstream cpu;
478 cpu << cpu_time << "s";
479 std::ostringstream wall;
480 wall << sections[actual_section_name].timer.last_wall_time() << "s";
481 if (output_type == cpu_times)
482 output_time = ", CPU time: " + cpu.str();
483 else if (output_type == wall_times)
484 output_time = ", wall time: " + wall.str() + ".";
485 else
486 output_time =
487 ", CPU/wall time: " + cpu.str() + " / " + wall.str() + ".";
488
489 out_stream << actual_section_name << output_time << std::endl;
490 }
491
492 // delete the index from the list of
493 // active ones
494 active_sections.erase(std::find(active_sections.begin(),
495 active_sections.end(),
496 actual_section_name));
497}
498
499
500
501std::map<std::string, double>
503{
504 std::map<std::string, double> output;
505 for (const auto &section : sections)
506 {
507 switch (kind)
508 {
510 output[section.first] = section.second.total_cpu_time;
511 break;
513 output[section.first] = section.second.total_wall_time;
514 break;
516 output[section.first] = section.second.n_calls;
517 break;
518 default:
520 }
521 }
522 return output;
523}
524
525
526
527void
529{
530 // we are going to change the precision and width of output below. store the
531 // old values so the get restored when exiting this function
532 const boost::io::ios_base_all_saver restore_stream(out_stream.get_stream());
533
534 // get the maximum width among all sections
535 unsigned int max_width = 0;
536 for (const auto &i : sections)
537 max_width = std::max(max_width, static_cast<unsigned int>(i.first.size()));
538
539 // 32 is the default width until | character
540 max_width = std::max(max_width + 1, static_cast<unsigned int>(32));
541 const std::string extra_dash = std::string(max_width - 32, '-');
542 const std::string extra_space = std::string(max_width - 32, ' ');
543
545 {
546 // in case we want to write CPU times
547 if (output_type != wall_times)
548 {
549 double total_cpu_time =
551
552 // check that the sum of all times is less or equal than the total
553 // time. otherwise, we might have generated a lot of overhead in this
554 // function.
555 double check_time = 0.;
556 for (const auto &i : sections)
557 check_time += i.second.total_cpu_time;
558
559 const double time_gap = check_time - total_cpu_time;
560 if (time_gap > 0.0)
561 total_cpu_time = check_time;
562
563 // generate a nice table
564 out_stream << "\n\n"
565 << "+---------------------------------------------"
566 << extra_dash << "+------------"
567 << "+------------+\n"
568 << "| Total CPU time elapsed since start "
569 << extra_space << "|";
570 out_stream << std::setw(10) << std::setprecision(3) << std::right;
571 out_stream << total_cpu_time << "s | |\n";
572 out_stream << "| "
573 << extra_space << "| "
574 << "| |\n";
575 out_stream << "| Section " << extra_space
576 << "| no. calls |";
577 out_stream << std::setw(10);
578 out_stream << std::setprecision(3);
579 out_stream << " CPU time "
580 << " | % of total |\n";
581 out_stream << "+---------------------------------" << extra_dash
582 << "+-----------+------------"
583 << "+------------+";
584 for (const auto &i : sections)
585 {
586 std::string name_out = i.first;
587
588 // resize the array so that it is always of the same size
589 unsigned int pos_non_space = name_out.find_first_not_of(' ');
590 name_out.erase(0, pos_non_space);
591 name_out.resize(max_width, ' ');
592 out_stream << std::endl;
593 out_stream << "| " << name_out;
594 out_stream << "| ";
595 out_stream << std::setw(9);
596 out_stream << i.second.n_calls << " |";
597 out_stream << std::setw(10);
598 out_stream << std::setprecision(3);
599 out_stream << i.second.total_cpu_time << "s |";
600 out_stream << std::setw(10);
601 if (total_cpu_time != 0)
602 {
603 // if run time was less than 0.1%, just print a zero to avoid
604 // printing silly things such as "2.45e-6%". otherwise print
605 // the actual percentage
606 const double fraction =
607 i.second.total_cpu_time / total_cpu_time;
608 if (fraction > 0.001)
609 {
610 out_stream << std::setprecision(2);
611 out_stream << fraction * 100;
612 }
613 else
614 out_stream << 0.0;
615
616 out_stream << "% |";
617 }
618 else
619 out_stream << 0.0 << "% |";
620 }
621 out_stream << std::endl
622 << "+---------------------------------" << extra_dash
623 << "+-----------+"
624 << "------------+------------+\n"
625 << std::endl;
626
627 if (time_gap > 0.0)
629 << std::endl
630 << "Note: The sum of counted times is " << time_gap
631 << " seconds larger than the total time.\n"
632 << "(Timer function may have introduced too much overhead, or different\n"
633 << "section timers may have run at the same time.)" << std::endl;
634 }
635
636 // in case we want to write out wallclock times
637 if (output_type != cpu_times)
638 {
640
641 // now generate a nice table
642 out_stream << "\n\n"
643 << "+---------------------------------------------"
644 << extra_dash << "+------------"
645 << "+------------+\n"
646 << "| Total wallclock time elapsed since start "
647 << extra_space << "|";
648 out_stream << std::setw(10) << std::setprecision(3) << std::right;
649 out_stream << total_wall_time << "s | |\n";
650 out_stream << "| "
651 << extra_space << "| "
652 << "| |\n";
653 out_stream << "| Section " << extra_space
654 << "| no. calls |";
655 out_stream << std::setw(10);
656 out_stream << std::setprecision(3);
657 out_stream << " wall time | % of total |\n";
658 out_stream << "+---------------------------------" << extra_dash
659 << "+-----------+------------"
660 << "+------------+";
661 for (const auto &i : sections)
662 {
663 std::string name_out = i.first;
664
665 // resize the array so that it is always of the same size
666 unsigned int pos_non_space = name_out.find_first_not_of(' ');
667 name_out.erase(0, pos_non_space);
668 name_out.resize(max_width, ' ');
669 out_stream << std::endl;
670 out_stream << "| " << name_out;
671 out_stream << "| ";
672 out_stream << std::setw(9);
673 out_stream << i.second.n_calls << " |";
674 out_stream << std::setw(10);
675 out_stream << std::setprecision(3);
676 out_stream << i.second.total_wall_time << "s |";
677 out_stream << std::setw(10);
678
679 if (total_wall_time != 0)
680 {
681 // if run time was less than 0.1%, just print a zero to avoid
682 // printing silly things such as "2.45e-6%". otherwise print
683 // the actual percentage
684 const double fraction =
685 i.second.total_wall_time / total_wall_time;
686 if (fraction > 0.001)
687 {
688 out_stream << std::setprecision(2);
689 out_stream << fraction * 100;
690 }
691 else
692 out_stream << 0.0;
693
694 out_stream << "% |";
695 }
696 else
697 out_stream << 0.0 << "% |";
698 }
699 out_stream << std::endl
700 << "+---------------------------------" << extra_dash
701 << "+-----------+"
702 << "------------+------------+\n"
703 << std::endl;
704 }
705 }
706 else
707 // output_type == cpu_and_wall_times_grouped
708 {
709 const double total_wall_time = timer_all.wall_time();
710 double total_cpu_time =
712
713 // check that the sum of all times is less or equal than the total time.
714 // otherwise, we might have generated a lot of overhead in this function.
715 double check_time = 0.;
716
717 for (const auto &i : sections)
718 check_time += i.second.total_cpu_time;
719
720 const double time_gap = check_time - total_cpu_time;
721 if (time_gap > 0.0)
722 total_cpu_time = check_time;
723
724 // generate a nice table
725 out_stream << "\n\n+---------------------------------------------"
726 << extra_dash << "+"
727 << "------------+------------+"
728 << "------------+------------+" << '\n'
729 << "| Total CPU/wall time elapsed since start "
730 << extra_space << "|" << std::setw(10) << std::setprecision(3)
731 << std::right << total_cpu_time << "s | "
732 << extra_space << "|" << std::setw(10) << std::setprecision(3)
733 << total_wall_time << "s | |"
734 << "\n| "
735 << extra_space << "|"
736 << " | |"
737 << " | |"
738 << "\n| Section " << extra_space
739 << "| no. calls |"
740 << " CPU time | % of total |"
741 << " wall time | % of total |"
742 << "\n+---------------------------------" << extra_dash
743 << "+-----------+"
744 << "------------+------------+"
745 << "------------+------------+" << std::endl;
746
747 for (const auto &i : sections)
748 {
749 std::string name_out = i.first;
750
751 // resize the array so that it is always of the same size
752 unsigned int pos_non_space = name_out.find_first_not_of(' ');
753 name_out.erase(0, pos_non_space);
754 name_out.resize(max_width, ' ');
755 out_stream << "| " << name_out << "| ";
756
757 out_stream << std::setw(9);
758 out_stream << i.second.n_calls << " |";
759
760 if (output_type != wall_times)
761 {
762 out_stream << std::setw(10);
763 out_stream << std::setprecision(3);
764 out_stream << i.second.total_cpu_time << "s |";
765 out_stream << std::setw(10);
766 if (total_cpu_time != 0)
767 {
768 // if run time was less than 0.1%, just print a zero to avoid
769 // printing silly things such as "2.45e-6%". otherwise print
770 // the actual percentage
771 const double fraction =
772 i.second.total_cpu_time / total_cpu_time;
773 if (fraction > 0.001)
774 {
775 out_stream << std::setprecision(2);
776 out_stream << fraction * 100;
777 }
778 else
779 out_stream << 0.0;
780
781 out_stream << "% |";
782 }
783 else
784 out_stream << 0.0 << "% |";
785 }
786
787 if (output_type != cpu_times)
788 {
789 out_stream << std::setw(10);
790 out_stream << std::setprecision(3);
791 out_stream << i.second.total_wall_time << "s |";
792 out_stream << std::setw(10);
793
794 if (total_wall_time != 0)
795 {
796 // if run time was less than 0.1%, just print a zero to avoid
797 // printing silly things such as "2.45e-6%". otherwise print
798 // the actual percentage
799 const double fraction =
800 i.second.total_wall_time / total_wall_time;
801 if (fraction > 0.001)
802 {
803 out_stream << std::setprecision(2);
804 out_stream << fraction * 100;
805 }
806 else
807 out_stream << 0.0;
808
809 out_stream << "% |";
810 }
811 else
812 out_stream << 0.0 << "% |";
813 }
814 out_stream << std::endl;
815 }
816
817 out_stream << "+---------------------------------" << extra_dash
818 << "+-----------+"
819 << "------------+------------+"
820 << "------------+------------+" << std::endl
821 << std::endl;
822
823 if (output_type != wall_times && time_gap > 0.0)
825 << std::endl
826 << "Note: The sum of counted times is " << time_gap
827 << " seconds larger than the total time.\n"
828 << "(Timer function may have introduced too much overhead, or different\n"
829 << "section timers may have run at the same time.)" << std::endl;
830 }
831}
832
833
834
835void
837 const double quantile) const
838{
839 // we are going to change the precision and width of output below. store the
840 // old values so the get restored when exiting this function
841 const boost::io::ios_base_all_saver restore_stream(out_stream.get_stream());
842
844 Utilities::MPI::max(sections.size(), mpi_comm));
845 Assert(quantile >= 0. && quantile <= 0.5,
846 ExcMessage("The quantile must be between 0 and 0.5"));
847
848 // get the maximum width among all sections
849 unsigned int max_width = 0;
850 for (const auto &i : sections)
851 max_width = std::max(max_width, static_cast<unsigned int>(i.first.size()));
852
853 // 17 is the default width until | character
854 max_width = std::max(max_width + 1, static_cast<unsigned int>(17));
855 const std::string extra_dash = std::string(max_width - 17, '-');
856 const std::string extra_space = std::string(max_width - 17, ' ');
857
858 // function to print data in a nice table
859 const auto print_statistics = [&](const double given_time) {
860 const unsigned int n_ranks = Utilities::MPI::n_mpi_processes(mpi_comm);
861 if (n_ranks == 1 || quantile == 0.)
862 {
864 Utilities::MPI::min_max_avg(given_time, mpi_comm);
865
866 out_stream << std::setw(10) << std::setprecision(4) << std::right;
867 out_stream << data.min << "s ";
868 out_stream << std::setw(5) << std::right;
869 out_stream << data.min_index << (n_ranks > 99999 ? "" : " ") << "|";
870 out_stream << std::setw(10) << std::setprecision(4) << std::right;
871 out_stream << data.avg << "s |";
872 out_stream << std::setw(10) << std::setprecision(4) << std::right;
873 out_stream << data.max << "s ";
874 out_stream << std::setw(5) << std::right;
875 out_stream << data.max_index << (n_ranks > 99999 ? "" : " ") << "|\n";
876 }
877 else
878 {
879 const unsigned int my_rank = Utilities::MPI::this_mpi_process(mpi_comm);
880 std::vector<double> receive_data(my_rank == 0 ? n_ranks : 0);
881 std::vector<double> result(9);
882#ifdef DEAL_II_WITH_MPI
883 int ierr = MPI_Gather(&given_time,
884 1,
885 MPI_DOUBLE,
886 receive_data.data(),
887 1,
888 MPI_DOUBLE,
889 0,
890 mpi_comm);
891 AssertThrowMPI(ierr);
892 if (my_rank == 0)
893 {
894 // fill the received data in a pair and sort; on the way, also
895 // compute the average
896 std::vector<std::pair<double, unsigned int>> data_rank;
897 data_rank.reserve(n_ranks);
898 for (unsigned int i = 0; i < n_ranks; ++i)
899 {
900 data_rank.emplace_back(receive_data[i], i);
901 result[4] += receive_data[i];
902 }
903 result[4] /= n_ranks;
904 std::sort(data_rank.begin(), data_rank.end());
905
906 const unsigned int quantile_index =
907 static_cast<unsigned int>(std::round(quantile * n_ranks));
908 AssertIndexRange(quantile_index, data_rank.size());
909 result[0] = data_rank[0].first;
910 result[1] = data_rank[0].second;
911 result[2] = data_rank[quantile_index].first;
912 result[3] = data_rank[quantile_index].second;
913 result[5] = data_rank[n_ranks - 1 - quantile_index].first;
914 result[6] = data_rank[n_ranks - 1 - quantile_index].second;
915 result[7] = data_rank[n_ranks - 1].first;
916 result[8] = data_rank[n_ranks - 1].second;
917 }
918 ierr = MPI_Bcast(result.data(), 9, MPI_DOUBLE, 0, mpi_comm);
919 AssertThrowMPI(ierr);
920#endif
921 out_stream << std::setw(10) << std::setprecision(4) << std::right;
922 out_stream << result[0] << "s ";
923 out_stream << std::setw(5) << std::right;
924 out_stream << static_cast<unsigned int>(result[1])
925 << (n_ranks > 99999 ? "" : " ") << "|";
926 out_stream << std::setw(10) << std::setprecision(4) << std::right;
927 out_stream << result[2] << "s ";
928 out_stream << std::setw(5) << std::right;
929 out_stream << static_cast<unsigned int>(result[3])
930 << (n_ranks > 99999 ? "" : " ") << "|";
931 out_stream << std::setw(10) << std::setprecision(4) << std::right;
932 out_stream << result[4] << "s |";
933 out_stream << std::setw(10) << std::setprecision(4) << std::right;
934 out_stream << result[5] << "s ";
935 out_stream << std::setw(5) << std::right;
936 out_stream << static_cast<unsigned int>(result[6])
937 << (n_ranks > 99999 ? "" : " ") << "|";
938 out_stream << std::setw(10) << std::setprecision(4) << std::right;
939 out_stream << result[7] << "s ";
940 out_stream << std::setw(5) << std::right;
941 out_stream << static_cast<unsigned int>(result[8])
942 << (n_ranks > 99999 ? "" : " ") << "|\n";
943 }
944 };
945
946 // in case we want to write out wallclock times
947 {
948 const unsigned int n_ranks = Utilities::MPI::n_mpi_processes(mpi_comm);
949
950 const std::string time_rank_column = "------------------+";
951 const std::string time_rank_space = " |";
952
953 // now generate a nice table
954 out_stream << '\n'
955 << "+------------------------------" << extra_dash << "+"
956 << time_rank_column
957 << (n_ranks > 1 && quantile > 0. ? time_rank_column : "")
958 << "------------+"
959 << (n_ranks > 1 && quantile > 0. ? time_rank_column : "")
960 << time_rank_column << '\n'
961 << "| Total wallclock time elapsed " << extra_space << "|";
962
963 print_statistics(timer_all.wall_time());
964
965 out_stream << "| " << extra_space << "|"
966 << time_rank_space
967 << (n_ranks > 1 && quantile > 0. ? time_rank_space : "")
968 << " "
969 << (n_ranks > 1 && quantile > 0. ? time_rank_space : "")
970 << time_rank_space << '\n';
971 out_stream << "| Section " << extra_space << "| no. calls "
972 << "| min time rank |";
973 if (n_ranks > 1 && quantile > 0.)
974 out_stream << " " << std::setw(5) << std::setprecision(2) << std::right
975 << quantile << "-tile rank |";
976 out_stream << " avg time |";
977 if (n_ranks > 1 && quantile > 0.)
978 out_stream << " " << std::setw(5) << std::setprecision(2) << std::right
979 << 1. - quantile << "-tile rank |";
980 out_stream << " max time rank |\n";
981 out_stream << "+------------------------------" << extra_dash << "+"
982 << time_rank_column
983 << (n_ranks > 1 && quantile > 0. ? time_rank_column : "")
984 << "------------+"
985 << (n_ranks > 1 && quantile > 0. ? time_rank_column : "")
986 << time_rank_column << '\n';
987 for (const auto &i : sections)
988 {
989 std::string name_out = i.first;
990
991 // resize the array so that it is always of the same size
992 unsigned int pos_non_space = name_out.find_first_not_of(' ');
993 name_out.erase(0, pos_non_space);
994 name_out.resize(max_width, ' ');
995 out_stream << "| " << name_out;
996 out_stream << "| ";
997 out_stream << std::setw(9);
998 out_stream << i.second.n_calls << " |";
999
1000 print_statistics(i.second.total_wall_time);
1001 }
1002 out_stream << "+------------------------------" << extra_dash << "+"
1003 << time_rank_column
1004 << (n_ranks > 1 && quantile > 0. ? time_rank_column : "")
1005 << "------------+"
1006 << (n_ranks > 1 && quantile > 0. ? time_rank_column : "")
1007 << time_rank_column << '\n';
1008 }
1009}
1010
1011
1012
1013void
1019
1020
1021
1022void
1028
1029void
1031{
1032 std::lock_guard<std::mutex> lock(mutex);
1033 sections.clear();
1034 active_sections.clear();
1036}
1037
1039{
1040 try
1041 {
1042 stop();
1043 }
1044 catch (...)
1045 {}
1046}
1047
1048
std::ostream & get_stream() const
void set_condition(const bool active)
void reset()
Definition timer.cc:1030
MPI_Comm mpi_communicator
Definition timer.h:881
void print_summary() const
Definition timer.cc:528
@ cpu_and_wall_times_grouped
Definition timer.h:659
@ cpu_times
Definition timer.h:647
@ wall_times
Definition timer.h:651
OutputFrequency output_frequency
Definition timer.h:828
void disable_output()
Definition timer.cc:1014
std::map< std::string, Section > sections
Definition timer.h:857
void enable_output()
Definition timer.cc:1023
void leave_subsection(const std::string &section_name="")
Definition timer.cc:438
OutputType output_type
Definition timer.h:833
OutputFrequency
Definition timer.h:599
@ every_call
Definition timer.h:603
@ every_call_and_summary
Definition timer.h:611
void print_wall_time_statistics(const MPI_Comm mpi_comm, const double print_quantile=0.) const
Definition timer.cc:836
std::list< std::string > active_sections
Definition timer.h:876
Threads::Mutex mutex
Definition timer.h:887
ConditionalOStream out_stream
Definition timer.h:862
@ total_wall_time
Definition timer.h:631
@ total_cpu_time
Definition timer.h:627
std::map< std::string, double > get_summary_data(const OutputData kind) const
Definition timer.cc:502
bool output_is_enabled
Definition timer.h:868
~TimerOutput()
Definition timer.cc:349
Timer timer_all
Definition timer.h:840
void enter_subsection(const std::string &section_name)
Definition timer.cc:396
TimerOutput(std::ostream &stream, const OutputFrequency output_frequency, const OutputType output_type)
Definition timer.cc:299
Definition timer.h:117
double last_cpu_time() const
Definition timer.cc:254
bool sync_lap_times
Definition timer.h:334
void start()
Definition timer.cc:176
bool running
Definition timer.h:321
Utilities::MPI::MinMaxAvg accumulated_wall_time_data
Definition timer.h:349
double cpu_time() const
Definition timer.cc:234
Timer()
Definition timer.cc:158
double wall_time() const
Definition timer.cc:262
MPI_Comm mpi_communicator
Definition timer.h:328
ClockMeasurements< wall_clock_type > wall_times
Definition timer.h:311
ClockMeasurements< cpu_clock_type > cpu_times
Definition timer.h:316
void reset()
Definition timer.cc:286
double stop()
Definition timer.cc:193
Utilities::MPI::MinMaxAvg last_lap_wall_time_data
Definition timer.h:341
void restart()
Definition timer.h:896
double last_wall_time() const
Definition timer.cc:278
#define DEAL_II_NAMESPACE_OPEN
Definition config.h:498
#define DEAL_II_WARNING(desc)
Definition config.h:587
#define DEAL_II_NAMESPACE_CLOSE
Definition config.h:499
#define Assert(cond, exc)
#define AssertDimension(dim1, dim2)
#define AssertThrowMPI(error_code)
#define AssertIndexRange(index, range)
static ::ExceptionBase & ExcMessage(std::string arg1)
#define DEAL_II_NOT_IMPLEMENTED()
T sum(const T &t, const MPI_Comm mpi_communicator)
unsigned int n_mpi_processes(const MPI_Comm mpi_communicator)
Definition mpi.cc:92
T max(const T &t, const MPI_Comm mpi_communicator)
unsigned int this_mpi_process(const MPI_Comm mpi_communicator)
Definition mpi.cc:107
MinMaxAvg min_max_avg(const double my_value, const MPI_Comm mpi_communicator)
Definition mpi.cc:66
static const unsigned int invalid_unsigned_int
Definition types.h:220
STL namespace.
::VectorizedArray< Number, width > max(const ::VectorizedArray< Number, width > &, const ::VectorizedArray< Number, width > &)
static time_point now() noexcept
Definition timer.cc:110
std::chrono::time_point< CPUClock, duration > time_point
Definition timer.h:58
clock_type_ clock_type
Definition timer.h:256
time_point_type current_lap_start_time
Definition timer.h:272
typename clock_type::duration duration_type
Definition timer.h:266
duration_type accumulated_time
Definition timer.h:277
duration_type last_lap_time
Definition timer.h:282
unsigned int max_index
Definition mpi.h:938
unsigned int min_index
Definition mpi.h:928