Allow access to logged timer data

cpp/dolfinx/common/TimeLogger.cpp

@@ -13,13 +13,12 @@ using namespace dolfinx;
 using namespace dolfinx::common;
 
 //-----------------------------------------------------------------------------
-void TimeLogger::register_timing(std::string task, double time)
+void TimeLogger::register_timing(
+    std::string task, std::chrono::duration<double, std::ratio<1>> time)
 {
-  assert(time >= 0.0);
-
   // Print a message
   std::string line
-      = "Elapsed time: " + std::to_string(time) + " (" + task + ")";
+      = "Elapsed time: " + std::to_string(time.count()) + " (" + task + ")";
   spdlog::debug(line.c_str());
 
   // Store values for summary
@@ -35,7 +34,7 @@ void TimeLogger::register_timing(std::string task, double time)
 void TimeLogger::list_timings(MPI_Comm comm, Table::Reduction reduction) const
 {
   // Format and reduce to rank 0
-  Table timings = this->timings();
+  Table timings = this->timing_table();
   timings = timings.reduce(comm, reduction);
   const std::string str = "\n" + timings.str();
 
@@ -44,23 +43,24 @@ void TimeLogger::list_timings(MPI_Comm comm, Table::Reduction reduction) const
     std::cout << str << std::endl;
 }
 //-----------------------------------------------------------------------------
-Table TimeLogger::timings() const
+Table TimeLogger::timing_table() const
 {
   // Generate log::timing table
-  Table table("Summary of timings");
+  Table table("Summary of timings (s)");
   for (auto& it : _timings)
   {
     std::string task = it.first;
     auto [num_timings, time] = it.second;
     table.set(task, "reps", num_timings);
-    table.set(task, "avg", time / static_cast<double>(num_timings));
-    table.set(task, "tot", time);
+    table.set(task, "avg", time.count() / static_cast<double>(num_timings));
+    table.set(task, "tot", time.count());
   }
 
   return table;
 }
 //-----------------------------------------------------------------------------
-std::pair<int, double> TimeLogger::timing(std::string task) const
+std::pair<int, std::chrono::duration<double, std::ratio<1>>>
+TimeLogger::timing(std::string task) const
 {
   // Find timing
   auto it = _timings.find(task);
@@ -73,3 +73,10 @@ std::pair<int, double> TimeLogger::timing(std::string task) const
   return it->second;
 }
 //-----------------------------------------------------------------------------
+std::map<std::string,
+         std::pair<int, std::chrono::duration<double, std::ratio<1>>>>
+TimeLogger::timings() const
+{
+  return _timings;
+}
+//-----------------------------------------------------------------------------

cpp/dolfinx/common/TimeLogger.h

@@ -8,14 +8,14 @@
 
 #include "Table.h"
 #include "timing.h"
+#include <chrono>
 #include <map>
 #include <mpi.h>
 #include <string>
 #include <utility>
 
 namespace dolfinx::common
 {
-
 /// Timer logging
 class TimeLogger
 {
@@ -33,10 +33,11 @@ class TimeLogger
   ~TimeLogger() = default;
 
   /// Register timing (for later summary)
-  void register_timing(std::string task, double wall);
+  void register_timing(std::string task,
+                       std::chrono::duration<double, std::ratio<1>> wall);
 
   /// Return a summary of timings and tasks in a Table
-  Table timings() const;
+  Table timing_table() const;
 
   /// List a summary of timings and tasks. Reduction type is
   /// printed.
@@ -46,13 +47,21 @@ class TimeLogger
 
   /// @brief Return timing.
   /// @param[in] task The task name to retrieve the timing for
-  /// @returns Values (count, total wall time, total user time, total
-  /// system time) for given task.
-  std::pair<int, double> timing(std::string task) const;
+  /// @return Values (count, total wall time) for given task.
+  std::pair<int, std::chrono::duration<double, std::ratio<1>>>
+  timing(std::string task) const;
+
+  /// @brief Logged elapsed times.
+  /// @return Elapsed [task id: (count, total wall time)].
+  std::map<std::string,
+           std::pair<int, std::chrono::duration<double, std::ratio<1>>>>
+  timings() const;
 
 private:
   // List of timings for tasks, map from string to (num_timings,
   // total_wall_time)
-  std::map<std::string, std::pair<int, double>> _timings;
+  std::map<std::string,
+           std::pair<int, std::chrono::duration<double, std::ratio<1>>>>
+      _timings;
 };
 } // namespace dolfinx::common

cpp/dolfinx/common/Timer.h

@@ -22,25 +22,27 @@ namespace dolfinx::common
 /// Timer timer("Assembling over cells");
 /// \endcode
 /// The timer is started at construction and timing ends when the timer
-/// is destroyed (goes out of scope). The timer can be started (reset)
+/// is destroyed (goes out-of-scope). The timer can be started (reset)
 /// and stopped explicitly by
 /// \code{.cpp}
 ///   timer.start();
 ///    /* .... */
 ///   timer.stop();
 /// \endcode
-/// A summary of registered elapsed times can be printed by calling
+/// A summary of registered elapsed times can be printed by calling:
 /// \code{.cpp}
 ///   list_timings();
 /// \endcode
+/// Registered elapsed times are logged when (1) the timer goes
+/// out-of-scope or (2) Timer::flush() is called.
 template <typename T = std::chrono::high_resolution_clock>
 class Timer
 {
 public:
   /// @brief Create and start timer.
   ///
-  /// Elapsed is optionally registered in the logger (in seconds) when
-  /// the Timer destructor is called.
+  /// Elapsed time is optionally registered in the logger when the Timer
+  /// destructor is called.
   ///
   /// @param[in] task Name used to registered the elapsed time in the
   /// logger. If no name is set, the elapsed time is not registered in
@@ -54,9 +56,7 @@ class Timer
     if (_start_time.has_value() and _task.has_value())
     {
       _acc += T::now() - *_start_time;
-      using X = std::chrono::duration<double, std::ratio<1>>;
-      TimeLogManager::logger().register_timing(
-          *_task, std::chrono::duration_cast<X>(_acc).count());
+      TimeLogManager::logger().register_timing(*_task, _acc);
     }
   }
 
@@ -109,7 +109,9 @@ class Timer
 
   /// @brief Flush timer duration to the logger.
   ///
-  /// Timer can be flushed only once.
+  /// An instance of a timer can be flushed to the logger only once.
+  /// Subsequent calls will have no effect and will not trigger any
+  /// logging.
   ///
   /// @pre Timer must have been stopped before flushing.
   void flush()
@@ -119,9 +121,7 @@ class Timer
 
     if (_task.has_value())
     {
-      using X = std::chrono::duration<double, std::ratio<1>>;
-      TimeLogManager::logger().register_timing(
-          *_task, std::chrono::duration_cast<X>(_acc).count());
+      TimeLogManager::logger().register_timing(*_task, _acc);
       _task = std::nullopt;
     }
   }

cpp/dolfinx/common/timing.cpp

@@ -11,18 +11,26 @@
 #include "Timer.h"
 
 //-----------------------------------------------------------------------
-dolfinx::Table dolfinx::timings()
+dolfinx::Table dolfinx::timing_table()
 {
-  return dolfinx::common::TimeLogManager::logger().timings();
+  return dolfinx::common::TimeLogManager::logger().timing_table();
 }
 //-----------------------------------------------------------------------------
 void dolfinx::list_timings(MPI_Comm comm, Table::Reduction reduction)
 {
   dolfinx::common::TimeLogManager::logger().list_timings(comm, reduction);
 }
 //-----------------------------------------------------------------------------
-std::pair<std::size_t, double> dolfinx::timing(std::string task)
+std::pair<int, std::chrono::duration<double, std::ratio<1>>>
+dolfinx::timing(std::string task)
 {
   return dolfinx::common::TimeLogManager::logger().timing(task);
 }
 //-----------------------------------------------------------------------------
+std::map<std::string,
+         std::pair<int, std::chrono::duration<double, std::ratio<1>>>>
+dolfinx::timings()
+{
+  return dolfinx::common::TimeLogManager::logger().timings();
+}
+//-----------------------------------------------------------------------------

cpp/dolfinx/common/timing.h

@@ -7,16 +7,17 @@
 #pragma once
 
 #include "Table.h"
+#include <chrono>
+#include <map>
 #include <mpi.h>
 #include <string>
 #include <utility>
 
 namespace dolfinx
 {
-
 /// @brief Return a summary of timings and tasks in a Table.
 /// @return Table with timings.
-Table timings();
+Table timing_table();
 
 /// @brief List a summary of timings and tasks.
 ///
@@ -27,10 +28,16 @@ Table timings();
 void list_timings(MPI_Comm comm,
                   Table::Reduction reduction = Table::Reduction::max);
 
-/// @brief Return timing (count, total wall time, total user time, total
-/// system time) for given task.
+/// @brief Return timing (count, total wall time) for given task.
 /// @param[in] task Name of a task
 /// @return The (count, total wall time) for the task.
-std::pair<std::size_t, double> timing(std::string task);
+std::pair<int, std::chrono::duration<double, std::ratio<1>>>
+timing(std::string task);
+
+/// @brief Logged elapsed times.
+/// @return Elapsed [task id: (count, total wall time)].
+std::map<std::string,
+         std::pair<int, std::chrono::duration<double, std::ratio<1>>>>
+timings();
 
 } // namespace dolfinx

python/dolfinx/common.py

@@ -45,46 +45,72 @@
 Reduction = _cpp.common.Reduction
 
 
-def timing(task: str):
+def timing(task: str) -> tuple[int, datetime.timedelta]:
+    """Return the logged elapsed time.
+
+    Timing data is for the calling process.
+
+    Arguments:
+        task: The task name using when logging the time.
+
+    Returns:
+        (number of times logged, total wall time)
+    """
     return _cpp.common.timing(task)
 
 
 def list_timings(comm, reduction=Reduction.max):
-    """Print out a summary of all Timer measurements. When used in parallel, a
-    reduction is applied across all processes. By default, the maximum
-    time is shown."""
+    """Print out a summary of all Timer measurements.
+
+    When used in parallel, a reduction is applied across all processes.
+    By default, the maximum time is shown.
+    """
     _cpp.common.list_timings(comm, reduction)
 
 
 class Timer:
-    """A timer can be used for timing tasks. The basic usage is::
+    """A timer for timing section of code.
+
+    The recommended usage is with a context manager.
 
-        with Timer(\"Some costly operation\"):
-            costly_call_1()
-            costly_call_2()
+    Example:
+        With a context manager, the timer is started when entering
+        and stopped at exit. With a named ``Timer``::
 
-    or::
+            with Timer(\"Some costly operation\"):
+                costly_call_1()
+                costly_call_2()
 
-        with Timer() as t:
-            costly_call_1()
-            costly_call_2()
-            print(\"Elapsed time so far: %s\" % t.elapsed()[0])
+            delta = timing(\"Some costly operation\")
+            print(delta)
 
-    The timer is started when entering context manager and timing
-    ends when exiting it. It is also possible to start and stop a
-    timer explicitly by::
+        or with an un-named ``Timer``::
 
-        t = Timer(\"Some costly operation\")
-        costly_call()
-        delta = t.stop()
+            with Timer() as t:
+                costly_call_1()
+                costly_call_2()
+                print(f\"Elapsed time: {t.elapsed()}\")
 
-    and retrieve timing data using::
+    Example:
+        It is possible to start and stop a timer explicitly::
 
-        delta = t.elapsed()
+            t = Timer(\"Some costly operation\")
+            costly_call()
+            delta = t.stop()
 
-    Timings are stored globally (if task name is given) and
-    may be printed using functions ``timing``, ``timings``,
-    ``list_timings``, ``dump_timings_to_xml``, e.g.::
+        and retrieve timing data using::
+
+            delta = t.elapsed()
+
+        To flush the timing data for a named ``Timer`` to the logger, the
+        timer should be stopped and flushed::
+
+            t.stop()
+            t.flush()
+
+    Timings are stored globally (if task name is given) and once flushed
+    (if used without a context manager) may be printed using functions
+    ``timing`` and ``list_timings``, e.g.::
 
         list_timings(comm)
     """
@@ -135,9 +161,10 @@ def flush(self) -> None:
         """Flush timer duration to the logger.
 
         Note:
-            Timer can be flushed only once.
-
             Timer must have been stopped before flushing.
+
+            Timer can be flushed only once. Subsequent calls will have
+            no effect.
         """
         self._cpp_object.flush()
 

python/dolfinx/wrappers/common.cpp

@@ -21,6 +21,7 @@
 #include <nanobind/ndarray.h>
 #include <nanobind/stl/array.h>
 #include <nanobind/stl/chrono.h>
+#include <nanobind/stl/map.h>
 #include <nanobind/stl/optional.h>
 #include <nanobind/stl/pair.h>
 #include <nanobind/stl/string.h>
@@ -183,8 +184,8 @@ void common(nb::module_& m)
            &dolfinx::common::Timer<std::chrono::high_resolution_clock>::flush,
            "Flush timer");
 
-  // dolfinx::common::Timer enum
   m.def("timing", &dolfinx::timing);
+  m.def("timings", &dolfinx::timings);
 
   m.def(
       "list_timings",