Re-jig get_walltime function; swap to unordered_map; sort entries in … (#32)

* Re-jig get_walltime function; swap to unordered_map; sort entries in output.

* Manual timing callipers just inside profiler callipers.

* Minor tweaks to comments: afterwards -> before.

* Change to get_thread0_walltime; find t2 before final prof calliper; other cosmetic changes.

* 32 - First set of changes in response to review.

* 32 - Further change in response to review. (Comment block tweaks.)

* PR #32: Update changelog for merge to main

Co-authored-by: TeranIvy <[email protected]>

Author: mo-mglover

CHANGELOG.md

@@ -14,8 +14,8 @@
 20/12/2021 PR #19 for #12: Use standard CMake project version variables for versioning. \
 21/12/2021 PR #18: Add GitHub runner for building and deploying Doxygen documentation. \
 21/12/2021 PR #22 for #13: Move install functionality in main CMakeLists.txt to cmake/Installation.cmake \
-21/01/2022 PR #23: Fix version number passed to Doxygen \
-15/03/2022 PR #5: Initial code import \
-08/07/2022 PR #27: Working Fortran (and C) interfaces \
-15/07/2022 PR #29: Unit testing for fortran interface
- 
+21/01/2022 PR #23: Fix version number passed to Doxygen. \
+15/03/2022 PR #5 towards #2: Initial code import. \
+08/07/2022 PR #27: Working Fortran (and C) interfaces. \
+15/07/2022 PR #30 for #29: Unit testing for Fortran interface. \
+04/08/2022 PR #32 for #31: Functionality improvements (walltime, swap to unordered_map, sort entries in output.

src/c++/hashtable.cpp

@@ -10,6 +10,7 @@
 #include <cassert>
 #include <iostream>
 #include <string>
+#include <algorithm>
 
 /**
  * @brief  Constructs a new entry in the hash table. 
@@ -83,7 +84,7 @@ void HashTable::add_child_time(size_t hash, double time_delta)
 }
 
 /**
- * @brief  Writes all entries in the hashtable.
+ * @brief  Writes all entries in the hashtable, sorted according to self times.
  *
  */
 
@@ -107,9 +108,17 @@ void HashTable::write()
     << std::setw(15) << "-" << " "
     << std::setw(15) << "-" << "\n";
   std::cout << std::setfill(' ');
+
+  // Create a vector from the hashtable and sort the entries according to self
+  // walltime.  If optimisation of this is needed, it ought to be possible to
+  // acquire a vector of hash-selftime pairs in the correct order, then use the
+  // hashes to look up other information directly from the hashtable.
+  auto hashvec = std::vector<std::pair<size_t, HashEntry>>(begin(table_), end(table_));
+  std::sort(begin(hashvec), end(hashvec), 
+      [](auto a, auto b) { return a.second.self_walltime_ > b.second.self_walltime_;});
 
   // Data entries
-  for (auto& [hash, entry] : table_) {
+  for (auto& [hash, entry] : hashvec) {
     std::cout 
       << std::setw(40) << std::left  << entry.region_name_    << " "
       << std::setw(15) << std::right << entry.self_walltime_  << " "
@@ -145,15 +154,13 @@ std::vector<size_t> HashTable::list_keys()
 }
 
 /**
- * @brief  Get the total wallclock time, which is the total walltime of the
- *         first entry in the table corresponding to the top-level timing
- *         callipers.
- *
+ * @brief  Get the total (inclusive) time corresponding to the input hash.
+ * 
  */
 
-double HashTable::get_total_wallclock_time()
+double HashTable::get_total_walltime(size_t const hash)
 {
-    return table_.begin()->second.total_walltime_;
+    return table_.at(hash).total_walltime_;
 }
 
 

src/c++/hashtable.h

@@ -24,7 +24,7 @@
 #ifndef PROFILER_HASHTABLE_H
 #define PROFILER_HASHTABLE_H
 
-#include <map>
+#include <unordered_map>
 #include <vector>
 #include <string>
 #include <string_view>
@@ -65,7 +65,7 @@ class HashTable{
 
     // Members
     int tid_;
-    std::map<size_t,HashEntry> table_;
+    std::unordered_map<size_t,HashEntry> table_;
     std::hash<std::string_view> hash_function_;
 
   public:
@@ -80,13 +80,10 @@ class HashTable{
     void write();
 
     // Member functions
-    double get_walltime(size_t const hash) const {return table_.at(hash).total_walltime_;}
-
     std::vector<size_t> list_keys();
-
     void add_child_time(size_t, double);
     void compute_self_times();
-    double get_total_wallclock_time();
+    double get_total_walltime(size_t const);
 
 };
 #endif

src/c++/profiler.cpp

@@ -124,13 +124,21 @@ void Profiler::write()
 }
 
 /**
- * @brief  Get the top-level elapsed time.
+ * @brief  Get the total (inclusive) time of everything below the specified hash.
+ *
+ * @param[in] hash  The hash corresponding to the region of interest. 
+ *
+ * @note   This function is normally expected to be used to return the total
+ *         wallclock time for whole run. Since this value is required only from
+ *         thread 0, the function does not take a thread ID argument and returns
+ *         the value for thread 0 only. Taking the hash argument avoids the need
+ *         to store the top-level hash inside the profiler itself.
  *
  */
 
-double Profiler::get_total_wallclock_time()
+double Profiler::get_thread0_walltime(size_t const hash)
 {
   auto tid = static_cast<hashtable_iterator_t_>(0);
-  return thread_hashtables_[tid].get_total_wallclock_time();
+  return thread_hashtables_[tid].get_total_walltime(hash);
 }
 

src/c++/profiler.h

@@ -55,7 +55,7 @@ class Profiler
     size_t start(std::string_view);
     void   stop (size_t const);
     void   write();
-    double get_total_wallclock_time();
+    double get_thread0_walltime(size_t const);
 };
 
 // Declare global profiler

src/c/profiler_c.cpp

@@ -22,10 +22,10 @@
 #include <cstring>
 
 extern "C" {
-	void c_profiler_start(long int&, char const*);
-	void c_profiler_stop (long int const&);
-	void c_profiler_write();
-    double c_get_total_wallclock_time();
+  void   c_profiler_start(long int&, char const*);
+  void   c_profiler_stop (long int const&);
+  void   c_profiler_write();
+  double c_get_thread0_walltime(long int const&);
 }
 
 /**
@@ -47,13 +47,13 @@ void c_profiler_start(long int& hash_out, char const* name)
 
 void c_profiler_stop(long int const& hash_in)
 {
-    size_t hash;
+  size_t hash;
 
-    // Ensure that the source and destination have the same size.
-    static_assert(sizeof(hash) == sizeof(hash_in), "Hash/In size mismatch.");
-    std::memcpy(&hash, &hash_in, sizeof(hash));
+  // Ensure that the source and destination have the same size.
+  static_assert(sizeof(hash) == sizeof(hash_in), "Hash/In size mismatch.");
+  std::memcpy(&hash, &hash_in, sizeof(hash));
 
-    prof.stop( hash );
+  prof.stop( hash );
 }
 
 /**
@@ -62,14 +62,21 @@ void c_profiler_stop(long int const& hash_in)
 
 void c_profiler_write()
 {
-    prof.write();
+  prof.write();
 }
 
 /**
- * Get the total wallclock time
+ * Get the total wallclock time for the specified region on thread 0.
  */
- double c_get_total_wallclock_time()
- {
-     return prof.get_total_wallclock_time();
- }
+
+ double c_get_thread0_walltime(long int const& hash_in)
+{
+  size_t hash;
+
+  // Ensure that the source and destination have the same size.
+  static_assert(sizeof(hash) == sizeof(hash_in), "Hash/In size mismatch.");
+  std::memcpy(&hash, &hash_in, sizeof(hash));
+
+  return prof.get_thread0_walltime( hash );
+}
 

src/f/profiler_mod.F90

@@ -24,29 +24,31 @@ module profiler_mod
   public :: profiler_start
   public :: profiler_stop
   public :: profiler_write
-  public :: profiler_get_total_wallclock_time
+  public :: profiler_get_thread0_walltime
 
   interface
 
     subroutine profiler_start(hash_out, name)  bind(C, name='c_profiler_start')
-          import :: c_char, c_long
-          character(kind=c_char, len=1), intent(in)  :: name
-          integer(kind=c_long),          intent(out) :: hash_out
+      import :: c_char, c_long
+      character(kind=c_char, len=1), intent(in)  :: name
+      integer(kind=c_long),          intent(out) :: hash_out
     end subroutine profiler_start
 
     subroutine profiler_stop(hash_in) bind(C, name='c_profiler_stop')
-        import :: c_long
-        integer(kind=c_long), intent(in) :: hash_in
+      import :: c_long
+      integer(kind=c_long), intent(in) :: hash_in
     end subroutine profiler_stop
 
     subroutine profiler_write() bind(C, name='c_profiler_write')
         !No arguments to handle
     end subroutine profiler_write
 
-    real(kind=c_double) function profiler_get_total_wallclock_time() &
-        bind(C, name='c_get_total_wallclock_time')
-        import :: c_double
-    end function profiler_get_total_wallclock_time
+    function profiler_get_thread0_walltime(hash_in) result(walltime)   &
+             bind(C, name='c_get_thread0_walltime')
+      import :: c_double, c_long
+      integer(kind=c_long), intent(in) :: hash_in
+      real(kind=c_double)              :: walltime
+    end function profiler_get_thread0_walltime
 
   end interface
 

tests/unit_tests/c++/test_profiler.cpp

@@ -16,8 +16,8 @@ TEST(SystemTests, TimingTest)
 {
 
   // Start timing: noddy way, and using Profiler.
-  double t1 = omp_get_wtime();
   auto prof_main = prof.start("MAIN");
+  double t1 = omp_get_wtime();
 
   // Time a region
   {
@@ -44,9 +44,9 @@ TEST(SystemTests, TimingTest)
   // Give the main regions some substantial execution time.
   sleep(2);
 
-  // End of profiling; record t2 immediately afterwards.
-  prof.stop(prof_main);
+  // End of profiling; record t2 immediately before.
   double t2 = omp_get_wtime();
+  prof.stop(prof_main);
 
   // Write the profile
   prof.write();
@@ -57,7 +57,7 @@ TEST(SystemTests, TimingTest)
   double const time_tolerance = 0.0001;
 
   double actual_time = t2 - t1;
-  double prof_time   = prof.get_total_wallclock_time();
+  double prof_time  = prof.get_thread0_walltime(prof_main);
   EXPECT_NEAR(prof_time, actual_time, time_tolerance);
 
   std::cout << "\n" << "Actual timing: "   << actual_time << "\n";

tests/unit_tests/f/test_profiler_mod.pf

@@ -8,7 +8,7 @@ module test_profiler_mod
   @suite(name='test_profiler_mod_suite')
 
   use profiler_mod
-  use OMP_LIB
+  use omp_lib
 
 contains
 
@@ -21,15 +21,15 @@ contains
 
     integer, parameter :: dp = 8
 
-    !Timer declarations
+    ! Timer declarations
     real(kind=dp) :: t1, t2, actual_time
 
     real(kind=prk) :: profiler_wallclock_time
 
-    !Handle declarations
+    ! Handle declarations
     integer(kind=pik) :: prof_main
 
-    !Start timing: noddy way, and using Profiler.
+    ! Start timing: noddy way, and using Profiler.
     call profiler_start(prof_main, 'FULL')
     t1 = omp_get_wtime()
 
@@ -59,21 +59,21 @@ contains
     end block
     !$OMP END PARALLEL
 
-    !Give the main regions some substantial execution time.
+    ! Give the main regions some substantial execution time.
     call sleep(2);
 
-    ! End of profiling; record t2 immediately afterwards.
-    call profiler_stop(prof_main)
+    ! End of profiling; record t2 immediately before.
     t2 = omp_get_wtime();
+    call profiler_stop(prof_main)
 
-    !Write the profile
+    ! Write the profile
     call profiler_write()
 
     actual_time = t2 - t1
-    profiler_wallclock_time = profiler_get_total_wallclock_time()
+    profiler_wallclock_time = profiler_get_thread0_walltime(prof_main)
 
-    @assertEqual(actual_time, profiler_wallclock_time, tolerance=1e-4)
+    @assertEqual(actual_time, profiler_wallclock_time, tolerance=1.0e-4_dp)
 
   end subroutine test_profiler
 
-end module test_profiler_mod
+end module test_profiler_mod