Some further cleanup: Refactor relationship between BlockTimer and Ti…

…mer for printing of final results, add another level of structure to timing data in metadata JSON

docs/src/developer.md

@@ -57,7 +57,7 @@ Schema are also installed and can be accessed in `<INSTALL_DIR>/bin`.
 
 ## Timing
 
-Timing facilities are provided by `BlockTimer`.
+Timing facilities are provided by the `Timer` and BlockTimer` clasess.
 
 Creating a block as `BlockTimer b(idx)` where `idx` is a category like `CONSTRUCT`, `SOLVE`,
 etc. will record time so long as `b` is in scope; however, timing may be interrupted by
@@ -67,12 +67,9 @@ are timed without needing to know how timing may be done by the calling function
 
 The `BlockTimer` implementation relies upon a static member object of the `Timer` class,
 which behaves as a stopwatch with some memory functions. It is the responsibility of this
-`Timer BlockTimer::timer` object to record time spent in each recorded category. Other
-`Timer` objects may be created for local timing purposes, but these will not count toward
-time reported at the end of a log file or in the metadata JSON.
-
-Internally, the number of times `BlockTimer b(idx)` was called for each possible value of
-`idx` (timing category) can be queried with `BlockTimer::GetTimer().GetCounts()`.
+`BlockTimer::timer` object to record time spent in each recorded category. Other `Timer`
+objects may be created for local timing purposes, but these will not count toward time
+reported at the end of a log file or in the metadata JSON.
 
 ## Changelog
 

palace/drivers/basesolver.cpp

@@ -135,8 +135,8 @@ void BaseSolver::SaveMetadata(const Timer &timer) const
     {
       auto key = Timer::descriptions[i];
       key.erase(std::remove_if(key.begin(), key.end(), isspace), key.end());
-      meta["ElapsedTime"][key] = timer.GetAvgTime((Timer::Index)i);
-      meta["TimerCounts"][key] = timer.GetCounts((Timer::Index)i);
+      meta["ElapsedTime"]["Durations"][key] = timer.Data((Timer::Index)i);
+      meta["ElapsedTime"]["Counts"][key] = timer.Counts((Timer::Index)i);
     }
     WriteMetadata(post_dir, meta);
   }

palace/main.cpp

@@ -189,7 +189,9 @@ int main(int argc, char *argv[])
   solver->Solve(mesh);
 
   // Print timing summary.
-  BlockTimer::Finalize(world_comm, *solver);
+  BlockTimer::Print(world_comm);
+  solver->SaveMetadata(BlockTimer::GlobalTimer());
+  Mpi::Print(world_comm, "\n");
 
   // Finalize SLEPc/PETSc.
 #if defined(PALACE_WITH_SLEPC)

palace/utils/timer.hpp

@@ -8,7 +8,6 @@
 #include <stack>
 #include <string>
 #include <vector>
-#include "drivers/basesolver.hpp"
 #include "utils/communication.hpp"
 
 namespace palace
@@ -58,15 +57,6 @@ class Timer
   TimePoint last_lap_time;
   std::vector<Duration> data;
   std::vector<int> counts;
-  std::vector<double> data_min, data_max, data_avg;
-
-  // Save a timing step by adding a duration, without lapping; optionally, count it.
-  Duration SaveTime(Index idx, Duration time, bool count_it)
-  {
-    data[idx] += time;
-    count_it &&counts[idx]++;
-    return data[idx];
-  }
 
 public:
   Timer()
@@ -88,91 +78,64 @@ class Timer
   // Return the time elapsed since timer creation.
   Duration TimeFromStart() const { return Now() - start_time; }
 
+  // Save a timing step by adding a duration, without lapping; optionally, count it.
+  Duration SaveTime(Index idx, Duration time, bool count_it = true)
+  {
+    data[idx] += time;
+    counts[idx] += count_it;
+    return data[idx];
+  }
+
   // Lap and record a timing step.
   Duration MarkTime(Index idx, bool count_it = true)
   {
     return SaveTime(idx, Lap(), count_it);
   }
 
   // Provide map-like read-only access to the timing data.
-  Duration operator[](Index idx) const { return data[idx]; }
-
-  // Provide access to the reduced timing data.
-  double GetMinTime(Index idx) const { return data_min[idx]; }
-  double GetMaxTime(Index idx) const { return data_max[idx]; }
-  double GetAvgTime(Index idx) const { return data_avg[idx]; }
+  auto Data(Index idx) const { return data[idx].count(); }
 
   // Return number of times timer.MarkTime(idx) or TimerBlock b(idx) was called.
-  int GetCounts(Index idx) const { return counts[idx]; }
+  auto Counts(Index idx) const { return counts[idx]; }
+};
+
+class BlockTimer
+{
+  using Index = Timer::Index;
+
+private:
+  inline static Timer timer;
+  inline static std::stack<Index> stack;
 
   // Reduce timing information across MPI ranks.
-  void Reduce(MPI_Comm comm)
+  static void Reduce(MPI_Comm comm, std::vector<double> &data_min,
+                     std::vector<double> &data_max, std::vector<double> &data_avg)
   {
-    const std::size_t ntimes = data.size();
-    SaveTime(TOTAL, TimeFromStart(), true);
-    data_min.resize(ntimes);
-    data_max.resize(ntimes);
-    data_avg.resize(ntimes);
-
-    int np = Mpi::Size(comm);
-    for (std::size_t i = 0; i < ntimes; i++)
+    data_min.resize(Timer::NUMTIMINGS);
+    data_max.resize(Timer::NUMTIMINGS);
+    data_avg.resize(Timer::NUMTIMINGS);
+    for (int i = Timer::INIT; i < Timer::NUMTIMINGS; i++)
     {
-      data_min[i] = data_max[i] = data_avg[i] = data[i].count();
+      data_min[i] = data_max[i] = data_avg[i] = timer.Data((Timer::Index)i);
     }
 
-    Mpi::GlobalMin(ntimes, data_min.data(), comm);
-    Mpi::GlobalMax(ntimes, data_max.data(), comm);
-    Mpi::GlobalSum(ntimes, data_avg.data(), comm);
+    Mpi::GlobalMin(Timer::NUMTIMINGS, data_min.data(), comm);
+    Mpi::GlobalMax(Timer::NUMTIMINGS, data_max.data(), comm);
+    Mpi::GlobalSum(Timer::NUMTIMINGS, data_avg.data(), comm);
 
-    for (std::size_t i = 0; i < ntimes; i++)
+    const int np = Mpi::Size(comm);
+    for (int i = Timer::INIT; i < Timer::NUMTIMINGS; i++)
     {
       data_avg[i] /= np;
     }
   }
 
-  // Prints timing information. We assume the data has already been reduced.
-  void Print(MPI_Comm comm) const
-  {
-    constexpr int p = 3;   // Floating point precision
-    constexpr int w = 12;  // Data column width
-    constexpr int h = 26;  // Left-hand side width
-    // clang-format off
-    Mpi::Print(comm, "\n{:<{}s}{:>{}s}{:>{}s}{:>{}s}\n",
-               "Elapsed Time Report (s)", h, "Min.", w, "Max.", w, "Avg.", w);
-    // clang-format on
-    Mpi::Print(comm, "{}\n", std::string(h + 3 * w, '='));
-    for (int i = INIT; i < NUMTIMINGS; i++)
-    {
-      if (counts[i] > 0)
-      {
-        if (i == TOTAL)
-        {
-          Mpi::Print(comm, "{}\n", std::string(h + 3 * w, '-'));
-        }
-        // clang-format off
-        Mpi::Print(comm, "{:<{}s}{:{}.{}f}{:{}.{}f}{:{}.{}f}\n",
-                   descriptions[i], h,
-                   data_min[i], w, p, data_max[i], w, p, data_avg[i], w, p);
-        // clang-format on
-      }
-    }
-  }
-};
-
-class BlockTimer
-{
-  using Index = Timer::Index;
-
-private:
-  inline static std::stack<Index> stack;
-  inline static Timer timer;
-
 public:
   BlockTimer(Index i)
   {
     // Start timing when entering the block, interrupting whatever we were timing before.
     // Take note of what we are now timing.
-    (stack.empty()) ? timer.Lap() : timer.MarkTime(stack.top(), false);
+    stack.empty() ? timer.Lap() : timer.MarkTime(stack.top(), false);
     stack.push(i);
   }
 
@@ -187,17 +150,47 @@ class BlockTimer
     }
   }
 
-  static void Finalize(MPI_Comm comm, BaseSolver &solver)
+  // Read-only access the static Timer object.
+  static const Timer &GlobalTimer() { return timer; }
+
+  // Print timing information after reducing the data across all processes.
+  static void Print(MPI_Comm comm)
   {
     while (!stack.empty())
     {
       timer.MarkTime(stack.top());
       stack.pop();
     }
-    timer.Reduce(comm);
-    timer.Print(comm);
-    solver.SaveMetadata(timer);
-    Mpi::Print(comm, "\n");
+    timer.SaveTime(Timer::TOTAL, timer.TimeFromStart());
+
+    // Reduce timing data.
+    std::vector<double> data_min, data_max, data_avg;
+    Reduce(comm, data_min, data_max, data_avg);
+
+    // Print a nice table of the timing data.
+    constexpr int p = 3;   // Floating point precision
+    constexpr int w = 12;  // Data column width
+    constexpr int h = 26;  // Left-hand side width
+    // clang-format off
+    Mpi::Print(comm, "\n{:<{}s}{:>{}s}{:>{}s}{:>{}s}\n",
+               "Elapsed Time Report (s)", h, "Min.", w, "Max.", w, "Avg.", w);
+    // clang-format on
+    Mpi::Print(comm, "{}\n", std::string(h + 3 * w, '='));
+    for (int i = Timer::INIT; i < Timer::NUMTIMINGS; i++)
+    {
+      if (timer.Counts((Timer::Index)i) > 0)
+      {
+        if (i == Timer::TOTAL)
+        {
+          Mpi::Print(comm, "{}\n", std::string(h + 3 * w, '-'));
+        }
+        // clang-format off
+        Mpi::Print(comm, "{:<{}s}{:{}.{}f}{:{}.{}f}{:{}.{}f}\n",
+                   timer.descriptions[i], h,
+                   data_min[i], w, p, data_max[i], w, p, data_avg[i], w, p);
+        // clang-format on
+      }
+    }
   }
 };