From: Martin Kronbichler Date: Mon, 3 Feb 2020 13:46:10 +0000 (+0100) Subject: Add MPI statistics to TimerOutput X-Git-Tag: v9.2.0-rc1~556^2~3 X-Git-Url: https://gitweb.dealii.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=3d7541320cb7275b759d676abb33c9075ef69b54;p=dealii.git Add MPI statistics to TimerOutput --- diff --git a/include/deal.II/base/timer.h b/include/deal.II/base/timer.h index fdc03bb4f8..8d67048f19 100644 --- a/include/deal.II/base/timer.h +++ b/include/deal.II/base/timer.h @@ -558,7 +558,7 @@ private: * do with the run time of the section on other processors but instead with * the run time of the previous section on another processor. * - * The usual way to avoid this is to introduce a barrier into the parallel + * The first way to avoid this is to introduce a barrier into the parallel * code just before we start and stop timing sections. This ensures that all * processes are at the same place and the timing information then reflects * the maximal run time across all processors. To achieve this, you need to @@ -574,6 +574,32 @@ private: * sure that we only generate output on a single processor. See the step-32, * step-40, and step-42 tutorial programs for this kind of usage of this class. * + * The second variant to cope with this issue is print more information about + * the recorded times to be able to understand this kind of imbalances without + * actually adding the barriers. While this approach is still affected by + * imbalances between different MPI processes, its output is not the arbitrary + * time of rank 0, but the minimum, average and maximum of the MPI results, + * using information from Utilities::MPI::MinMaxAvg. As the data is also + * equipped with the rank id where the minimum and maximum are attained, this + * approach allows to identify on which ranks certain slowdowns occur. In case + * some imbalance between the MPI ranks from one section to the next can be + * tolerated, this strategy can hence be advantageous over the barrier variant + * as it does not synchronize the program in places where it is not + * necessary. The usage of this variant is to initialize the output object + * without any native print settings and without communicator, + * @code + * TimerOutput timer (pcout, + * TimerOutput::never, + * TimerOutput::wall_times); + * @endcode + * and then call + * @code + * timer.print_summary_statistics(MPI_COMM_WORLD); + * @endcode + * Here, the output is written to the pcout object of type + * ConditionalOStream passed to the constructor, making sure the information + * is only printed once. See step-67 for an example usage of this variant. + * * @ingroup utilities * @author M. Kronbichler, 2009. */ @@ -824,6 +850,18 @@ public: void print_summary() const; + /** + * Print a formatted table that summarizes the wall time consumed in the + * various sections, using statistics in terms of the minimum, average, and + * maximum of times in the various sections and the MPI ranks where the + * minimum and maximum are attained. Note that this call only provides + * useful information when the TimerOutput object is constructed without an + * MPI_Comm argument, to let individual sections run without being disturbed + * by barriers. + */ + void + print_summary_of_wall_time_statistics(const MPI_Comm mpi_comm) const; + /** * By calling this function, all output can be disabled. This function * together with enable_output() can be useful if one wants to control the diff --git a/source/base/timer.cc b/source/base/timer.cc index f83ba7d1a6..26943b36bb 100644 --- a/source/base/timer.cc +++ b/source/base/timer.cc @@ -861,6 +861,96 @@ TimerOutput::print_summary() const +void +TimerOutput::print_summary_of_wall_time_statistics( + const MPI_Comm mpi_comm) const +{ + // we are going to change the precision and width of output below. store the + // old values so we can restore it later on + const std::istream::fmtflags old_flags = out_stream.get_stream().flags(); + const std::streamsize old_precision = out_stream.get_stream().precision(); + const std::streamsize old_width = out_stream.get_stream().width(); + + AssertDimension(sections.size(), + Utilities::MPI::max(sections.size(), mpi_comm)); + + // get the maximum width among all sections + unsigned int max_width = 0; + for (const auto &i : sections) + max_width = + std::max(max_width, static_cast(i.first.length())); + + // 20 is the default width until | character + max_width = std::max(max_width + 1, static_cast(20)); + const std::string extra_dash = std::string(max_width - 20, '-'); + const std::string extra_space = std::string(max_width - 20, ' '); + + // in case we want to write out wallclock times + { + double total_wall_time = timer_all.wall_time(); + + Utilities::MPI::MinMaxAvg data = + Utilities::MPI::min_max_avg(total_wall_time, mpi_comm); + const unsigned int n_ranks = Utilities::MPI::n_mpi_processes(mpi_comm); + + // now generate a nice table + out_stream << "\n\n" + << "+---------------------------------" << extra_dash + << "+------------+------+------------+------------+------+\n" + << "| Total wallclock time elapsed " << extra_space << "|"; + out_stream << std::setw(10) << std::setprecision(4) << std::right; + out_stream << data.min << "s |"; + out_stream << std::setw(5) << std::right; + out_stream << data.min_index << (n_ranks > 99999 ? "" : " ") << "|"; + out_stream << std::setw(10) << std::setprecision(4) << std::right; + out_stream << data.avg << "s |"; + out_stream << std::setw(10) << std::setprecision(4) << std::right; + out_stream << data.max << "s |"; + out_stream << std::setw(5) << std::right; + out_stream << data.max_index << (n_ranks > 99999 ? "" : " ") << "|\n"; + out_stream << "| " << extra_space + << "| | min | | | max |\n"; + out_stream << "| Section " << extra_space << "| no. calls " + << "| min time | rank | avg time | max time | rank |\n"; + out_stream << "+---------------------" << extra_dash << "+-----------+" + << "------------+------+------------+------------+------+\n"; + for (const auto &i : sections) + { + std::string name_out = i.first; + + // resize the array so that it is always of the same size + unsigned int pos_non_space = name_out.find_first_not_of(' '); + name_out.erase(0, pos_non_space); + name_out.resize(max_width, ' '); + out_stream << "| " << name_out; + out_stream << "| "; + out_stream << std::setw(9); + out_stream << i.second.n_calls << " |"; + data = Utilities::MPI::min_max_avg(i.second.total_wall_time, mpi_comm); + out_stream << std::setw(10) << std::setprecision(4) << std::right; + out_stream << data.min << "s |"; + out_stream << std::setw(5) << std::right; + out_stream << data.min_index << (n_ranks > 99999 ? "" : " ") << "|"; + out_stream << std::setw(10) << std::setprecision(4) << std::right; + out_stream << data.avg << "s |"; + out_stream << std::setw(10) << std::setprecision(4) << std::right; + out_stream << data.max << "s |"; + out_stream << std::setw(5) << std::right; + out_stream << data.max_index << (n_ranks > 99999 ? "" : " ") << "|\n"; + } + out_stream << "+---------------------" << extra_dash << "+-----------+" + << "------------+------+------------+------------+------+\n" + << std::endl; + } + + // restore previous precision and width + out_stream.get_stream().precision(old_precision); + out_stream.get_stream().width(old_width); + out_stream.get_stream().flags(old_flags); +} + + + void TimerOutput::disable_output() {