Recursion handling (#93)

src/c++/hashtable.cpp

@@ -8,6 +8,7 @@
 #include "hashvec_handler.h"
 
 #include <cassert>
+#include <cstring>
 #include <iterator>
 #include <cstring>
 #include <cstddef>
@@ -148,14 +149,42 @@ void meto::HashTable::update(record_index_t const record_index,
 
   auto& record = hashvec_[record_index];
 
-  // Increment the walltime for this hash entry.
-  record.total_walltime_ += time_delta;
+  // Increment the walltime for this hash entry. If this region has been called
+  // recursively, directly or indirectly, the time goes into a different bucket.
+  if (record.recursion_level_ > 0){
+    record.recursion_total_walltime_ += time_delta;
+  }
+  else{
+    record.total_walltime_ += time_delta;
+  }
 
   // Update the number of times this region has been called
   ++record.call_count_;
 
 }
 
+/**
+ * @brief  Increments by 1 the recursion level in a region record.
+ * @param [in] record_index  The index corresponding to the region record.
+ */
+
+void meto::HashTable::increment_recursion_level(record_index_t const record_index)
+{
+  auto& record = hashvec_[record_index];
+  ++record.recursion_level_;
+}
+
+/**
+ * @brief  Decrements by 1 the recursion level in a region record.  
+ * @param [in] record_index  The index corresponding to the region record.
+ */
+
+void meto::HashTable::decrement_recursion_level(record_index_t const record_index)
+{
+  auto& record = hashvec_[record_index];
+  --record.recursion_level_;
+}
+
 /**
  * @brief  Add in time spent calling child regions. Also retuns a pointer
  *         to the overhead time so that it can be incremented downstream,
@@ -216,14 +245,15 @@ void meto::HashTable::sort_records()
  * @details Times computed are: the region self time and the total time minus
  *          directly incurred profiling overhead costs.
  *
- * @param [in] record  The region record to compute.
+ * @param [inout] record  The region record to compute.
  */
 
 void meto::HashTable::prepare_computed_times(RegionRecord& record)
 {
 
   // Self time
   record.self_walltime_ = record.total_walltime_
+                        + record.recursion_total_walltime_
                         - record.child_walltime_
                         - record.overhead_walltime_;
 

src/c++/hashtable.h

@@ -111,6 +111,10 @@ class HashTable{
     std::string            get_decorated_region_name(size_t const hash) const;
     unsigned long long int get_call_count(size_t const hash) const;
     unsigned long long int get_prof_call_count() const;
+
+    void increment_recursion_level(record_index_t const);
+    void decrement_recursion_level(record_index_t const);
+
 };
 
 } // End meto namespace

src/c++/hashvec.cpp

@@ -18,12 +18,14 @@ meto::RegionRecord::RegionRecord(size_t const region_hash,
                                  int tid)
 : region_hash_(region_hash)
 , region_name_(region_name)
-, total_walltime_      (time_duration_t::zero())
-, total_raw_walltime_  (time_duration_t::zero())
-, self_walltime_       (time_duration_t::zero())
-, child_walltime_      (time_duration_t::zero())
-, overhead_walltime_   (time_duration_t::zero())
+, total_walltime_           (time_duration_t::zero())
+, recursion_total_walltime_ (time_duration_t::zero())
+, total_raw_walltime_       (time_duration_t::zero())
+, self_walltime_            (time_duration_t::zero())
+, child_walltime_           (time_duration_t::zero())
+, overhead_walltime_        (time_duration_t::zero())
 , call_count_(0)
+, recursion_level_(0)
 {
   decorated_region_name_ = region_name_;
   decorated_region_name_ += '@';

src/c++/hashvec.h

@@ -41,11 +41,13 @@ struct RegionRecord {
     std::string      region_name_;
     std::string      decorated_region_name_;
     time_duration_t  total_walltime_;
+    time_duration_t  recursion_total_walltime_;
     time_duration_t  total_raw_walltime_;
     time_duration_t  self_walltime_;
     time_duration_t  child_walltime_;
     time_duration_t  overhead_walltime_;
     unsigned long long int call_count_;
+    unsigned int     recursion_level_;
 
 };
 

src/c++/vernier.cpp

@@ -118,6 +118,7 @@ size_t meto::Vernier::start_part2(std::string_view const region_name)
   size_t hash;
   record_index_t record_index;
   thread_hashtables_[tid].query_insert(region_name, tid_int, hash, record_index);
+  thread_hashtables_[tid].increment_recursion_level(record_index);
 
   // Store the calliper and region start times.
   ++call_depth_;
@@ -163,9 +164,9 @@ void meto::Vernier::stop(size_t const hash)
     exit (101);
   }
 
- // Get reference to the traceback entry.
- auto call_depth_index = static_cast<traceback_index_t>(call_depth_);
- auto& traceback_entry = thread_traceback_[tid].at(call_depth_index);
+  // Get reference to the traceback entry.
+  auto call_depth_index = static_cast<traceback_index_t>(call_depth_);
+  auto& traceback_entry = thread_traceback_[tid].at(call_depth_index);
 
   // Check: which hash is last on the traceback list?
   size_t last_hash_on_list = traceback_entry.record_hash_;
@@ -178,6 +179,7 @@ void meto::Vernier::stop(size_t const hash)
   auto region_duration = region_stop_time - traceback_entry.region_start_time_;
 
   // Do the hashtable update for the child region.
+  thread_hashtables_[tid].decrement_recursion_level(traceback_entry.record_index_);
   thread_hashtables_[tid].update(traceback_entry.record_index_, region_duration);
 
   // Precompute times as far as possible. We just need the calliper stop time

tests/unit_tests/c++/CMakeLists.txt

@@ -25,3 +25,4 @@ add_unit_test(test_regionname test_regionname.cpp)
 add_unit_test(test_hashtable test_hashtable.cpp)
 add_unit_test(test_proftests test_proftests.cpp)
 add_unit_test(test_callcount test_callcount.cpp)
+add_unit_test(test_recursion test_recursion.cpp)

tests/unit_tests/c++/test_recursion.cpp

@@ -0,0 +1,189 @@
+/*----------------------------------------------------------------------------*\
+ (c) Crown copyright 2023 Met Office. All rights reserved.
+ The file LICENCE, distributed with this code, contains details of the terms
+ under which the code may be used.
+\*----------------------------------------------------------------------------*/
+
+#include <gtest/gtest.h>
+#include <omp.h>
+
+#include "vernier.h"
+
+int const max_depth = 3;
+int const sleep_seconds = 1;
+
+// The time tolerance can be reasonably loose. If the total times were incorrect
+// as a result of mis-handled recursion, they would be too large by multiples of
+// sleep_seconds.
+double const time_tolerance = 0.001;
+
+// ------------------------------------------------------------------------------
+//  Structs
+// ------------------------------------------------------------------------------
+
+// Structure To hold timings from the various recursive functions.
+struct Timings
+{
+  double zeroth_function_total_time_ = 0.0;
+  double first_function_total_time_  = 0.0;
+  double second_function_total_time_ = 0.0;
+};
+
+// ------------------------------------------------------------------------------
+//  Forward declarations
+// ------------------------------------------------------------------------------
+
+// Needed to escape circular dependence on function declarations.
+void second_function(Timings&);
+
+// ------------------------------------------------------------------------------
+//  Zeroth function - calls itself
+// ------------------------------------------------------------------------------
+
+void zeroth_function(Timings& timings)
+{
+
+  static int recursion_depth = 1;
+#pragma omp threadprivate(recursion_depth)
+
+  auto prof_handle = meto::vernier.start("first_function");
+
+  sleep(sleep_seconds);
+  ++recursion_depth;
+
+  if (recursion_depth <= max_depth)
+  {
+    zeroth_function(timings);
+  }
+
+  meto::vernier.stop(prof_handle);
+
+  // Update the total walltime so far spent in this function.
+  int const tid = omp_get_thread_num();
+  timings.zeroth_function_total_time_ = meto::vernier.get_total_walltime(prof_handle, tid);
+
+}
+
+// ------------------------------------------------------------------------------
+//  First function - calls the second function.
+// ------------------------------------------------------------------------------
+
+void first_function(Timings& timings)
+{
+
+  static int recursion_depth = 1;
+#pragma omp threadprivate(recursion_depth)
+
+  auto prof_handle = meto::vernier.start("first_function");
+
+  sleep(sleep_seconds);
+  ++recursion_depth;
+
+  if (recursion_depth <= max_depth)
+  {
+    second_function(timings);
+  }
+
+  meto::vernier.stop(prof_handle);
+
+  // Update the total walltime so far spent in this function. Do here while we
+  // have access to the prof_handle.
+  int const tid = omp_get_thread_num();
+  timings.first_function_total_time_ = meto::vernier.get_total_walltime(prof_handle, tid);
+
+}
+
+// ------------------------------------------------------------------------------
+//  Second function - calls the first function.
+// ------------------------------------------------------------------------------
+
+void second_function(Timings& timings)
+{
+  static int recursion_depth = 1;
+#pragma omp threadprivate(recursion_depth)
+
+  auto prof_handle = meto::vernier.start("second_function");
+
+  sleep(sleep_seconds);
+  ++recursion_depth;
+
+  if (recursion_depth <= max_depth)
+  {
+    first_function(timings);
+  }
+
+  meto::vernier.stop(prof_handle);
+
+  // Update the total walltime so far spent in this function. Do here while we
+  // have access to the prof_handle.
+  int const tid = omp_get_thread_num();
+  timings.second_function_total_time_ = meto::vernier.get_total_walltime(prof_handle, tid);
+}
+
+// -------------------------------------------------------------------------------
+//  Main tests
+// -------------------------------------------------------------------------------
+
+//
+// Direct recursion
+//
+
+TEST(RecursionTest,DirectRecursion)
+{
+  auto prof_handle = meto::vernier.start("test_recursion");
+
+  // Test independently on each thread.
+#pragma omp parallel
+  {
+    auto prof_handle_threaded = meto::vernier.start("test_recursion:threads");
+
+    Timings timings;
+    double t1 = omp_get_wtime();
+
+    // Function calls itself
+    zeroth_function(timings);
+
+    double t2 = omp_get_wtime();
+    double overall_time = t2-t1;
+
+    EXPECT_LE  (timings.zeroth_function_total_time_,  overall_time);
+    EXPECT_NEAR(timings.zeroth_function_total_time_,  overall_time, time_tolerance);
+
+    meto::vernier.stop(prof_handle_threaded);
+  }
+
+  meto::vernier.stop(prof_handle);
+}
+
+//
+// Indirect recursion
+//
+
+TEST(RecursionTest,IndirectRecursion)
+{
+  auto prof_handle = meto::vernier.start("test_recursion");
+
+  // Test independently on each thread.
+#pragma omp parallel
+  {
+    auto prof_handle_threaded = meto::vernier.start("test_recursion:threads");
+
+    Timings timings;
+    double t1 = omp_get_wtime();
+
+    // Function calls a second function
+    first_function(timings);
+
+    double t2 = omp_get_wtime();
+    double overall_time = t2-t1;
+
+    EXPECT_LE  (timings.first_function_total_time_,  overall_time);
+    EXPECT_NEAR(timings.first_function_total_time_,  overall_time, time_tolerance);
+    EXPECT_NEAR(timings.second_function_total_time_, timings.first_function_total_time_ - sleep_seconds, time_tolerance);
+
+    meto::vernier.stop(prof_handle_threaded);
+  }
+
+  meto::vernier.stop(prof_handle);
+}
+