Add MPI statistics to TimerOutput

diff --git a/include/deal.II/base/timer.h b/include/deal.II/base/timer.h
index fdc03bb4f8527d84a51f87e76248e9981c63caed..8d67048f19819b8833b4fbc3f542dc60f432faf5 100644 (file)
--- 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 <i>the previous section</i> 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 <code>pcout</code> 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 f83ba7d1a6ba186c145d1b3a197ca881a8349d19..26943b36bbd2ef3b75a6e33b868a6494f454369b 100644 (file)
--- 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<unsigned int>(i.first.length()));
+
+  // 20 is the default width until | character
+  max_width = std::max(max_width + 1, static_cast<unsigned int>(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()
 {