CI: Relax timestamp checking (#1189)

* Relax timestamp checking

- Prevent recurring CI failures that have no remedy until HSA/driver issues are resolved

* Replace "cc" abbreviation in tests with "counter-collection"

* Update CODEOWNERS to explicitly include jrmadsen for source/include

* Extra logging in rocprofiler tool library

* Tweak aborted-app test

- remove counter collection as part of the test

source/lib/rocprofiler-sdk-tool/tool.cpp

@@ -922,9 +922,8 @@ get_device_counting_service(rocprofiler_agent_id_t agent_id)
                     name_v        = itr.substr(0, pos);
                     auto dev_id_s = itr.substr(pos + device_qualifier.length());
 
-                    LOG_IF(FATAL,
-                           dev_id_s.empty() ||
-                               dev_id_s.find_first_not_of("0123456789") != std::string::npos)
+                    ROCP_FATAL_IF(dev_id_s.empty() ||
+                                  dev_id_s.find_first_not_of("0123456789") != std::string::npos)
                         << "invalid device qualifier format (':device=N) where N is the GPU id: "
                         << itr;
 
@@ -1203,6 +1202,7 @@ void
 initialize_rocprofv3()
 {
     ROCP_INFO << "initializing rocprofv3...";
+
     if(int status = 0;
        rocprofiler_is_initialized(&status) == ROCPROFILER_STATUS_SUCCESS && status == 0)
     {
@@ -1210,21 +1210,26 @@ initialize_rocprofv3()
                          "force configuration");
     }
 
-    LOG_IF(FATAL, !client_identifier) << "nullptr to client identifier!";
-    LOG_IF(FATAL, !client_finalizer && !tool::get_config().list_metrics)
+    ROCP_FATAL_IF(!client_identifier) << "nullptr to client identifier!";
+    ROCP_FATAL_IF(!client_finalizer && !tool::get_config().list_metrics)
         << "nullptr to client finalizer!";  // exception for listing metrics
 }
 
 void
-finalize_rocprofv3()
+finalize_rocprofv3(std::string_view context)
 {
-    ROCP_INFO << "finalizing rocprofv3...";
+    ROCP_INFO << "invoked: finalize_rocprofv3";
     if(client_finalizer && client_identifier)
     {
+        ROCP_INFO << "finalizing rocprofv3: caller='" << context << "'...";
         client_finalizer(*client_identifier);
         client_finalizer  = nullptr;
         client_identifier = nullptr;
     }
+    else
+    {
+        ROCP_INFO << "finalize_rocprofv3('" << context << "') ignored: already finalized";
+    }
 }
 
 timestamps_t*
@@ -1820,7 +1825,9 @@ rocprofv3_set_main(main_func_t main_func) ROCPROFV3_INTERNAL_API;
 void
 rocprofv3_error_signal_handler(int signo)
 {
-    finalize_rocprofv3();
+    ROCP_WARNING << __FUNCTION__ << " caught signal " << signo << "...";
+
+    finalize_rocprofv3(__FUNCTION__);
     // below is for testing purposes. re-raising the signal causes CTest to ignore WILL_FAIL ON
     if(signal_handler_exit) ::exit(signo);
     ::raise(signo);
@@ -1863,7 +1870,7 @@ rocprofiler_configure(uint32_t                 version,
     add_destructor(stats_timestamp);
 
     // in case main wrapper is not used
-    ::atexit(finalize_rocprofv3);
+    ::atexit([]() { finalize_rocprofv3("atexit"); });
 
     if(tool::get_config().list_metrics)
     {
@@ -1927,9 +1934,13 @@ rocprofv3_main(int argc, char** argv, char** envp)
         }
     }
 
+    ROCP_INFO << "rocprofv3: main function wrapper will be invoked...";
+
     auto ret = CHECK_NOTNULL(get_main_function())(argc, argv, envp);
 
-    finalize_rocprofv3();
+    ROCP_INFO << "rocprofv3: main function has returned with exit code: " << ret;
+
+    finalize_rocprofv3(__FUNCTION__);
 
     ROCP_INFO << "rocprofv3 finished. exit code: " << ret;
     return ret;

source/lib/rocprofiler-sdk/hsa/async_copy.cpp

@@ -342,14 +342,20 @@ async_copy_handler(hsa_signal_value_t signal_value, void* arg)
     {
         _profile_time = tracing::adjust_profiling_time(
             "memcpy",
+            "hsa_amd_profiling_get_async_copy_time",
             _profile_time,
             tracing::profiling_time{HSA_STATUS_SUCCESS, _data->start_ts, ts});
-
-        // if we encounter this in CI, it will cause test to fail
-        ROCP_CI_LOG_IF(ERROR, _profile_time.end < _profile_time.start)
-            << "hsa_amd_profiling_get_async_copy_time for returned async times where the end time ("
-            << _profile_time.end << ") was less than the start time (" << _profile_time.start
-            << ")";
+    }
+    else
+    {
+        ROCP_CI_LOG(ERROR) << fmt::format(
+            "hsa_amd_profiling_get_async_copy_time for the {} copy operation from agent-{} to "
+            "agent-{} returned status={} :: {}",
+            std::string_view{hsa::async_copy::name_by_id(_data->direction)},
+            CHECK_NOTNULL(agent::get_agent(_data->src_agent))->node_id,
+            CHECK_NOTNULL(agent::get_agent(_data->dst_agent))->node_id,
+            static_cast<int>(copy_time_status),
+            hsa::get_hsa_status_string(copy_time_status));
     }
 
     // get the contexts that were active when the signal was created

source/lib/rocprofiler-sdk/kernel_dispatch/profiling_time.cpp

@@ -55,27 +55,22 @@ get_dispatch_time(hsa_agent_t             _hsa_agent,
 
     if(_profile_time.status == HSA_STATUS_SUCCESS)
     {
-        // if we encounter this in CI, it will cause test to fail
-        ROCP_CI_LOG_IF(ERROR, _profile_time.end < _profile_time.start)
-            << "hsa_amd_profiling_get_dispatch_time for kernel_id=" << _kernel_id
-            << " on rocprofiler_agent="
-            << CHECK_NOTNULL(agent::get_rocprofiler_agent(_hsa_agent))->node_id
-            << " returned dispatch times where the end time (" << _profile_time.end
-            << ") was less than the start time (" << _profile_time.start << ")";
-
         _profile_time = tracing::adjust_profiling_time(
             "dispatch",
+            "hsa_amd_profiling_get_dispatch_time",
             _profile_time,
             tracing::profiling_time{
                 HSA_STATUS_SUCCESS, _baseline.value_or(dispatch_time.start), ts});
     }
     else
     {
-        ROCP_CI_LOG(ERROR) << "hsa_amd_profiling_get_dispatch_time for kernel id=" << _kernel_id
-                           << " on rocprofiler_agent="
-                           << CHECK_NOTNULL(agent::get_rocprofiler_agent(_hsa_agent))->id.handle
-                           << " returned status=" << dispatch_time_status
-                           << " :: " << hsa::get_hsa_status_string(dispatch_time_status);
+        ROCP_CI_LOG(ERROR) << fmt::format(
+            "hsa_amd_profiling_get_dispatch_time for kernel id={} on agent-{} returned status={} "
+            ":: {}",
+            _kernel_id,
+            CHECK_NOTNULL(agent::get_rocprofiler_agent(_hsa_agent))->node_id,
+            static_cast<int>(dispatch_time_status),
+            hsa::get_hsa_status_string(dispatch_time_status));
     }
 
     return _profile_time;

source/lib/rocprofiler-sdk/tracing/profiling_time.hpp

@@ -72,7 +72,10 @@ struct profiling_time
 };
 
 inline profiling_time
-adjust_profiling_time(std::string_view _label, profiling_time _value, profiling_time&& _bounds)
+adjust_profiling_time(std::string_view _label,
+                      std::string_view _responsible,
+                      profiling_time   _value,
+                      profiling_time&& _bounds)
 {
     static auto sysclock_period = hsa::get_hsa_timestamp_period();
     static auto normalize_env   = common::get_env("ROCPROFILER_CI_FREQ_SCALE_TIMESTAMPS", false);
@@ -84,19 +87,21 @@ adjust_profiling_time(std::string_view _label, profiling_time _value, profiling_
 
     if(strict_ts_env)
     {
-        ROCP_FATAL_IF(ROCPROFILER_UNLIKELY(_value.end < _value.start))
-            << fmt::format("Invalid {} time value: {} end time ({}) is less than the {} start time "
-                           "({}) :: difference={}",
+        ROCP_FATAL_IF(ROCPROFILER_UNLIKELY(_value.start > _value.end))
+            << fmt::format("{} returned invalid {} time value: {} start time is greater than the "
+                           "{} end time ({} > {}) :: difference={}",
+                           _responsible,
                            _label,
                            _label,
-                           _value.end,
                            _label,
                            _value.start,
-                           (_value.end - _value.start));
+                           _value.end,
+                           (_value.start - _value.end));
 
         ROCP_FATAL_IF(ROCPROFILER_UNLIKELY(_value.start < _bounds.start))
-            << fmt::format("Invalid {} time value: {} start time ({}) is less than the enqueue "
-                           "time on the CPU ({}) :: difference={}",
+            << fmt::format("{} returned invalid {} time value: {} start time is before the API "
+                           "call enqueuing the operation on the CPU ({} < {}) :: difference={}",
+                           _responsible,
                            _label,
                            _label,
                            _value.start,
@@ -105,8 +110,9 @@ adjust_profiling_time(std::string_view _label, profiling_time _value, profiling_
                            (_bounds.start - _value.start));
 
         ROCP_FATAL_IF(ROCPROFILER_UNLIKELY(_value.end > _bounds.end))
-            << fmt::format("Invalid {} time value: {} end time ({}) is greater than the current "
-                           "time on the CPU ({}) :: difference={}",
+            << fmt::format("{} returned invalid {} time value: {} end time is greater than the "
+                           "current time on the CPU ({} > {}) :: difference={}",
+                           _responsible,
                            _label,
                            _label,
                            _value.end,
@@ -115,6 +121,21 @@ adjust_profiling_time(std::string_view _label, profiling_time _value, profiling_
                            (_value.end - _bounds.end));
     }
 
+    if(_value.start > _value.end)
+    {
+        ROCP_ERROR << fmt::format(
+            "{} returned {} times where the start time is after end time ({} > {}) :: "
+            "difference={}. Swapping the values. Set the environment variable "
+            "ROCPROFILER_CI_STRICT_TIMESTAMPS=1 to cause a failure instead",
+            _responsible,
+            _label,
+            _value.start,
+            _value.end,
+            (_value.start - _value.end));
+
+        std::swap(_value.start, _value.end);
+    }
+
     // below are hacks for clock skew issues:
     //
     // the timestamp of this handler will always be after when the profiling time ended