Add loop.stats option (#602)

* Add loop.stats option

* Update loop.stats test

src/caliper/controllers/controllers.cpp

@@ -374,6 +374,39 @@ const char* builtin_option_specs = R"json(
        }
      ]
     },
+    {
+     "name"        : "loop.stats",
+     "description" : "Loop iteration count and time statistics",
+     "type"        : "bool",
+     "category"    : "metric",
+     "services"    : [ "loop_statistics" ],
+     "query"  :
+     [
+       { "level"   : "local",
+         "let"     :
+         [
+          "ls.min=scale(min#iter.duration.ns,1e-9)",
+          "ls.avg=scale(avg#iter.duration.ns,1e-9)",
+          "ls.max=scale(max#iter.duration.ns,1e-9)"
+         ],
+         "select"  :
+         [
+          "max(max#iter.count) as \"Iterations\" unit count",
+          "min(ls.min) as \"Time/iter (min)\" unit sec",
+          "avg(ls.avg) as \"Time/iter (avg)\" unit sec",
+          "max(ls.max) as \"Time/iter (max)\" unit sec"
+         ]
+       },
+       { "level"   : "cross", "select":
+         [
+          "max(max#max#iter.count) as \"Iterations\" unit count",
+          "min(min#ls.min) as \"Time/iter (min)\" unit sec",
+          "avg(avg#ls.avg) as \"Time/iter (avg)\" unit sec",
+          "max(max#ls.max) as \"Time/iter (max)\" unit sec"
+         ]
+       }
+     ]
+    },
     {
      "name"        : "node.order",
      "description" : "Report order in which regions first appeared",

src/services/CMakeLists.txt

@@ -127,6 +127,11 @@ if (CALIPER_HAVE_MPI)
   endif()
 endif()
 
+list(APPEND CALIPER_SERVICES_SOURCES
+  LoopStatistics.cpp)
+list(APPEND CALIPER_SERVICE_NAMES
+  "loop_statistics")
+
 if (CALIPER_BUILD_TESTING)
   add_subdirectory(templates)
 endif()

src/services/LoopStatistics.cpp

@@ -0,0 +1,118 @@
+// Copyright (c) 2015-2022, Lawrence Livermore National Security, LLC.
+// See top-level LICENSE file for details.
+
+#include "caliper/CaliperService.h"
+
+#include "Services.h"
+
+#include "caliper/Caliper.h"
+#include "caliper/SnapshotRecord.h"
+
+#include "caliper/common/Log.h"
+#include "caliper/common/RuntimeConfig.h"
+
+#include <chrono>
+#include <vector>
+
+using namespace cali;
+
+namespace cali
+{
+
+extern Attribute class_iteration_attr;
+extern Attribute loop_attr;
+
+}
+
+namespace
+{
+
+class LoopStatisticsService
+{
+    using clock = std::chrono::steady_clock;
+
+    struct LoopInfo {
+        clock::time_point iter_start_time;
+        uint64_t num_iterations;
+    };
+
+    std::vector<LoopInfo> m_loop_info;
+
+    Attribute m_iter_duration_attr;
+    Attribute m_iter_count_attr;
+
+    void begin_cb(Caliper* c, Channel* channel, const Attribute& attr, const Variant& data) {
+        if (attr == loop_attr) {
+            m_loop_info.emplace_back(LoopInfo { clock::now(), 0 });
+        } else if (attr.get(class_iteration_attr).to_bool() && !m_loop_info.empty()) {
+            m_loop_info.back().iter_start_time = clock::now();
+            m_loop_info.back().num_iterations++;
+        }
+    }
+
+    void end_cb(Caliper* c, Channel* channel, const Attribute& attr, const Variant& data) {
+        if (m_loop_info.empty())
+            return;
+        if (attr == loop_attr) {
+            Entry e { m_iter_count_attr, Variant(m_loop_info.back().num_iterations) };
+            c->push_snapshot(channel, SnapshotView(e));
+            m_loop_info.pop_back();
+        } else if (attr.get(class_iteration_attr).to_bool()) {
+            uint64_t t = std::chrono::duration_cast<std::chrono::nanoseconds>(
+                clock::now() - m_loop_info.back().iter_start_time).count();
+            Entry e { m_iter_duration_attr, Variant(t) };
+            c->push_snapshot(channel, SnapshotView(e));
+        }
+    }
+
+    LoopStatisticsService(Caliper* c, Channel* channel)
+    {
+        m_iter_duration_attr =
+            c->create_attribute("iter.duration.ns", CALI_TYPE_UINT,
+                CALI_ATTR_ASVALUE | CALI_ATTR_AGGREGATABLE | CALI_ATTR_SKIP_EVENTS);
+        m_iter_count_attr =
+            c->create_attribute("iter.count", CALI_TYPE_UINT,
+                CALI_ATTR_ASVALUE | CALI_ATTR_AGGREGATABLE | CALI_ATTR_SKIP_EVENTS);
+
+        m_loop_info.reserve(4);
+    }
+
+public:
+
+    static const char* s_spec;
+
+    static void create(Caliper* c, Channel* channel) {
+        LoopStatisticsService* instance = new LoopStatisticsService(c, channel);
+
+        channel->events().pre_begin_evt.connect(
+            [instance](Caliper* c, Channel* channel, const Attribute& attr, const Variant& data){
+                    instance->begin_cb(c, channel, attr, data);
+                });
+        channel->events().pre_end_evt.connect(
+            [instance](Caliper* c, Channel* channel, const Attribute& attr, const Variant& data){
+                    instance->end_cb(c, channel, attr, data);
+                });
+        channel->events().finish_evt.connect(
+            [instance](Caliper* c, Channel* channel){
+                    delete instance;
+                });
+
+        Log(1).stream() << channel->name() << ": registered loop_statistics service\n";
+    }
+};
+
+const char* LoopStatisticsService::s_spec = R"json(
+{
+ "name": "loop_statistics",
+ "description": "Record loop iteration statistics"
+}
+)json";
+
+} // namespace [anonymous]
+
+namespace cali
+{
+
+CaliperService loop_statistics_service { ::LoopStatisticsService::s_spec, ::LoopStatisticsService::create };
+
+}

test/ci_app_tests/test_loopreport.py

@@ -112,5 +112,27 @@ def test_loopreport_target_loop_selection(self):
             else:
                 self.fail('%s not found in log' % target)
 
+    """ Loop statistics option """
+    def test_loop_stats(self):
+        target_cmd = [ './ci_test_macros', '10', 'spot,loop.stats,output=stdout' ]
+        query_cmd  = [ '../../src/tools/cali-query/cali-query', '-q', 'let r=leaf() select * where r=main\ loop format json' ]
+
+        obj = json.loads( cat.run_test_with_query(target_cmd, query_cmd, None) )
+
+        self.assertEqual(len(obj), 1)
+
+        rec = obj[0]
+
+        self.assertTrue("max#max#max#iter.count" in rec)
+        self.assertTrue("avg#avg#ls.avg" in rec)
+        self.assertTrue("min#min#ls.min" in rec)
+        self.assertTrue("max#max#ls.max" in rec)
+
+        self.assertEqual(int(rec["max#max#max#iter.count"]), 4)
+        self.assertGreaterEqual(float(rec["min#min#ls.min"]), 0.000009)
+        self.assertGreaterEqual(float(rec["avg#avg#ls.avg"]), float(rec["min#min#ls.min"]))
+        self.assertGreaterEqual(float(rec["max#max#ls.max"]), float(rec["avg#avg#ls.avg"]))
+
+
 if __name__ == "__main__":
     unittest.main()