Increase timer resolution (#487)

* Add exclusive time option for spot controller

* Use nsec resolution for timer

* Enable multiplexing in example flops spec

* Record time durations as integers

* Print verbose test output in Github actions

.github/workflows/cmake.yml

@@ -37,5 +37,5 @@ jobs:
       working-directory: ${{github.workspace}}/build
       # Execute tests defined by the CMake configuration.  
       # See https://cmake.org/cmake/help/latest/manual/ctest.1.html for more detail
-      run: ctest -C ${{env.BUILD_TYPE}}
+      run: ctest -C ${{env.BUILD_TYPE}} --rerun-failed --output-on-failure
 

examples/configs/flops.json

@@ -44,7 +44,8 @@
   "services": [ "papi" ],
   "config": 
   {
-      "CALI_PAPI_COUNTERS": "PAPI_DP_OPS,PAPI_SP_OPS"
+      "CALI_PAPI_COUNTERS": "PAPI_DP_OPS,PAPI_SP_OPS",
+      "CALI_PAPI_ENABLE_MULTIPLEXING": "true"
   },
   "query":
   [

python/cali2traceevent.py

@@ -25,9 +25,10 @@ def _get_timestamp(rec):
 
     timestamp_attributes = {
         "cupti.timestamp"      : 1e-3,
-        "gputrace.timestamp"   : 1e-3,
         "rocm.host.timestamp"  : 1e-3,
+        "time.offset.ns"       : 1e-3,
         "time.offset"          : 1.0,
+        "gputrace.timestamp"   : 1e-3,
         "cupti.activity.start" : 1e-3,
         "rocm.starttime"       : 1e-3
     }

src/caliper/RegionProfile.cpp

@@ -1,4 +1,4 @@
-// Copyright (c) 2015-2022, Lawrence Livermore National Security, LLC.  
+// Copyright (c) 2015-2022, Lawrence Livermore National Security, LLC.
 // See top-level LICENSE file for details.
 
 #include "caliper/RegionProfile.h"
@@ -42,38 +42,53 @@ RegionProfile::region_profile_t
 RegionProfile::exclusive_region_times(const std::string& region_type)
 {
     Caliper c;
-    FlatExclusiveRegionProfile rp(c, "sum#time.duration", region_type.c_str());
+    FlatExclusiveRegionProfile rp(c, "sum#time.duration.ns", region_type.c_str());
 
     if (channel())
         c.flush(channel(), SnapshotView(), rp);
     else
         Log(1).stream() << "RegionProfile::exclusive_region_times(): channel is not enabled"
                         << std::endl;
 
-    return rp.result();
+    auto res = rp.result();
+
+    // convert from nanosec to sec
+    std::get<1>(res) *= 1e-9;
+    std::get<2>(res) *= 1e-9;
+    for (auto &p : std::get<0>(res))
+        p.second *= 1e-9;
+
+    return res;
 }
 
 
 RegionProfile::region_profile_t
 RegionProfile::inclusive_region_times(const std::string& region_type)
 {
     Caliper c;
-    FlatInclusiveRegionProfile rp(c, "sum#time.duration", region_type.c_str());
+    FlatInclusiveRegionProfile rp(c, "sum#time.duration.ns", region_type.c_str());
 
     if (channel())
         c.flush(channel(), SnapshotView(), rp);
     else
         Log(1).stream() << "RegionProfile::inclusive_region_times(): channel is not enabled"
                         << std::endl;
 
-    return rp.result();
+    auto res = rp.result();
+
+    std::get<1>(res) *= 1e-9;
+    std::get<2>(res) *= 1e-9;
+    for (auto &p : std::get<0>(res))
+        p.second *= 1e-9;
+
+    return res;
 }
 
 void
 RegionProfile::clear()
 {
     Channel* chn = channel();
-    
+
     if (chn)
         Caliper::instance().clear(chn);
 }

src/caliper/controllers/HatchetRegionProfileController.cpp

@@ -61,6 +61,7 @@ class HatchetRegionProfileController : public cali::ChannelController
                 config()["CALI_MPIREPORT_WRITE_ON_FINALIZE"] = "false";
                 config()["CALI_MPIREPORT_CONFIG"  ] =
                     opts.build_query("local", {
+                            { "let",      "sum#time.duration=scale(sum#time.duration.ns,1e-9)" },
                             { "select",   "*,sum(sum#time.duration) as time unit sec" },
                             { "group by", "path,mpi.rank" },
                             { "format",   format }
@@ -70,6 +71,7 @@ class HatchetRegionProfileController : public cali::ChannelController
                 config()["CALI_REPORT_FILENAME"   ] = output;
                 config()["CALI_REPORT_CONFIG"     ] =
                     opts.build_query("local", {
+                            { "let",      "sum#time.duration=scale(sum#time.duration.ns,1e-9)" },
                             { "select",   "*,sum(sum#time.duration) as time unit sec" },
                             { "group by", "path" },
                             { "format",   format }

src/caliper/controllers/LoopReportController.cpp

@@ -83,13 +83,13 @@ class LoopReportController : public cali::internal::CustomOutputController
             " loop"
             ",count()"
             ",sum(loop.iterations)"
-            ",sum(time.duration)"
+            ",scale(time.duration.ns,1e-9)"
             ",min(iter_per_sec)"
             ",max(iter_per_sec)"
             ",avg(iter_per_sec)";
 
         std::string query = m_opts.build_query("local", {
-                { "let",      "iter_per_sec = ratio(loop.iterations,time.duration)" },
+                { "let",      "iter_per_sec = ratio(loop.iterations,time.duration.ns,1e9)" },
                 { "select",   select },
                 { "group by", "loop" },
                 { "where",    "loop" }
@@ -102,10 +102,10 @@ class LoopReportController : public cali::internal::CustomOutputController
         const char* select =
             " loop as Loop"
             ",max(sum#loop.iterations) as \"Iterations\""
-            ",max(sum#time.duration)   as \"Time (s)\""
+            ",max(scale#time.duration.ns) as \"Time (s)\""
             ",min(min#iter_per_sec) as \"Iter/s (min)\""
             ",max(max#iter_per_sec) as \"Iter/s (max)\""
-            ",ratio(sum#loop.iterations,sum#time.duration) as \"Iter/s (avg)\"";
+            ",ratio(sum#loop.iterations,scale#time.duration.ns) as \"Iter/s (avg)\"";
 
         std::string query = m_opts.build_query("cross", {
                 { "select",    select },
@@ -120,9 +120,9 @@ class LoopReportController : public cali::internal::CustomOutputController
     Aggregator timeseries_local_aggregation(Caliper& c, CaliperMetadataDB& db, const std::string& loopname, int blocksize) {
         const char* select =
             " Block"
-            ",sum(time.duration)"
+            ",scale(time.duration.ns,1e-9)"
             ",sum(loop.iterations)"
-            ",ratio(loop.iterations,time.duration)";
+            ",ratio(loop.iterations,time.duration.ns,1e9)";
 
         std::string block =
             std::string("Block = truncate(loop.start_iteration,") + std::to_string(blocksize) + ")";
@@ -141,8 +141,8 @@ class LoopReportController : public cali::internal::CustomOutputController
         const char* select =
             " Block"
             ",max(sum#loop.iterations) as \"Iterations\""
-            ",max(sum#time.duration) as \"Time (s)\""
-            ",avg(ratio#loop.iterations/time.duration) as \"Iter/s\"";
+            ",max(scale#time.duration.ns) as \"Time (s)\""
+            ",avg(ratio#loop.iterations/time.duration.ns) as \"Iter/s\"";
 
         std::string query = m_opts.build_query("cross", {
                 { "select",   select  },

src/caliper/controllers/OpenMPReportController.cpp

@@ -25,7 +25,8 @@ class OpenMPReportController : public cali::ChannelController
         : ChannelController(name, 0, initial_cfg)
         {
             const char* let =
-                " n.threads=first(omp.num.threads)"
+                " sum#time.duration=scale(sum#time.duration.ns,1e-9)"
+                ",n.threads=first(omp.num.threads)"
                 ",t.initial=first(sum#time.duration) if omp.thread.type=initial";
 
             // Config for first aggregation step in MPI mode (process-local aggregation)

src/caliper/controllers/ROCmActivityProfileController.cpp

@@ -63,7 +63,7 @@ class RocmActivityProfileController : public cali::ChannelController
                     opts.build_query("local", {
                             { "select",
                               "*,scale(sum#rocm.activity.duration,1e-9) as \"time (gpu)\" unit sec"
-                              " ,sum(sum#time.duration) as \"time\" unit sec"
+                              " ,scale(sum#time.duration.ns,1e-9) as \"time\" unit sec"
                             },
                             { "group by", "path,rocm.kernel.name,rocm.activity.kind,mpi.rank" },
                             { "format",   format }
@@ -75,7 +75,7 @@ class RocmActivityProfileController : public cali::ChannelController
                     opts.build_query("local", {
                             { "select",
                               "*,scale(sum#rocm.activity.duration,1e-9) as \"time (gpu)\" unit sec"
-                              " ,sum(sum#time.duration) as \"time\" unit sec" },
+                              " ,sale(sum#time.duration.ns,1e-9) as \"time\" unit sec" },
                             { "group by", "path,rocm.kernel.name,rocm.activity.kind" },
                             { "format",   format }
                         });

src/caliper/controllers/ROCmActivityReportController.cpp

@@ -28,18 +28,18 @@ class RocmActivityReportController : public cali::ChannelController
         {
             // Config for first aggregation step in MPI mode (process-local aggregation)
             std::string local_select =
-                " inclusive_sum(sum#time.duration)"
+                " inclusive_scale(sum#time.duration.ns,1e-9)"
                 ",inclusive_scale(sum#rocm.activity.duration,1e-9)";
             // Config for serial-mode aggregation
             std::string serial_select =
-                " inclusive_sum(sum#time.duration) as \"Host Time\""
+                " inclusive_scale(sum#time.duration.ns,1e-9) as \"Host Time\""
                 ",inclusive_scale(sum#rocm.activity.duration,1e-9) as \"GPU Time\""
                 ",inclusive_ratio(sum#rocm.activity.duration,sum#time.duration,1e-7) as \"GPU %\"";
 
             // Config for second aggregation step in MPI mode (cross-process aggregation)
             std::string cross_select =
-                " avg(inclusive#sum#time.duration) as \"Avg Host Time\""
-                ",max(inclusive#sum#time.duration) as \"Max Host Time\""
+                " avg(inclusive#scale#time.duration.ns) as \"Avg Host Time\""
+                ",max(inclusive#scale#time.duration.ns) as \"Max Host Time\""
                 ",avg(iscale#sum#rocm.activity.duration) as \"Avg GPU Time\""
                 ",max(iscale#sum#rocm.activity.duration) as \"Max GPU Time\""
                 ",ratio(iscale#sum#rocm.activity.duration,inclusive#sum#time.duration,100.0) as \"GPU %\"";

src/caliper/controllers/RuntimeReportController.cpp

@@ -26,6 +26,9 @@ class RuntimeReportController : public cali::ChannelController
     RuntimeReportController(bool use_mpi, const char* name, const config_map_t& initial_cfg, const ConfigManager::Options& opts)
         : ChannelController(name, 0, initial_cfg)
         {
+            std::string local_let =
+                "sum#time.duration=scale(sum#time.duration.ns,1e-9)";
+
             // Config for first aggregation step in MPI mode (process-local aggregation)
             std::string local_select =
                 " sum(sum#time.duration)";
@@ -60,6 +63,7 @@ class RuntimeReportController : public cali::ChannelController
                 config()["CALI_MPIREPORT_WRITE_ON_FINALIZE"] = "false";
                 config()["CALI_MPIREPORT_LOCAL_CONFIG"] =
                     opts.build_query("local", {
+                            { "let",       local_let },
                             { "select",    local_select  },
                             { "group by",  "path" }
                         });
@@ -74,6 +78,7 @@ class RuntimeReportController : public cali::ChannelController
                 config()["CALI_REPORT_FILENAME"   ] = opts.get("output", "stderr").to_string();
                 config()["CALI_REPORT_CONFIG"     ] =
                     opts.build_query("local", {
+                            { "let",       local_let },
                             { "select",    serial_select },
                             { "group by",  "path" },
                             { "format",    format }