Add kernel profiling time info to counter collection records (#1000)

* Add kernel profiling time info to counter collection records - lib/rocprofiler-sdk/kernel_dispatch - added profiling_time.{hpp,cpp} - restructured tracing.cpp - updated queue.cpp AsyncSignalHandler - gets kernel dispatch profiling time and passes to dispatch_complete and signal callbacks - structured some header includes to reduce cyclic include probability - originally, including kernel_dispatch/tracing.hpp in hsa/queue.hpp created a lot of cyclic includes * Fix kernel_dispatch.cpp includes * Fix kernel_dispatch.cpp - include <cstring> - replace use of ROCPROFILER_HSA_AMD_EXT_API_ID_NONE with ROCPROFILER_KERNEL_DISPATCH_LAST [ROCm/rocprofiler-sdk commit: b15e498945]
2024-08-19 20:05:04 -05:00
parent 11526c0f7c
commit 82a089ac0a
27 changed files with 395 additions and 182 deletions
@@ -1,6 +1,8 @@
 #
-set(ROCPROFILER_LIB_KERNEL_DISPATCH_SOURCES kernel_dispatch.cpp tracing.cpp)
-set(ROCPROFILER_LIB_KERNEL_DISPATCH_HEADERS kernel_dispatch.hpp tracing.hpp)
+set(ROCPROFILER_LIB_KERNEL_DISPATCH_SOURCES kernel_dispatch.cpp profiling_time.cpp
+                                            tracing.cpp)
+set(ROCPROFILER_LIB_KERNEL_DISPATCH_HEADERS kernel_dispatch.hpp profiling_time.hpp
+                                            tracing.hpp)

 target_sources(
    rocprofiler-object-library PRIVATE ${ROCPROFILER_LIB_KERNEL_DISPATCH_SOURCES}
@@ -22,7 +22,12 @@

 #include "lib/rocprofiler-sdk/kernel_dispatch/kernel_dispatch.hpp"

+#include <rocprofiler-sdk/fwd.h>
+
+#include <cstdint>
 #include <string_view>
+#include <utility>
+#include <vector>

 namespace rocprofiler
 {
@@ -65,7 +70,7 @@ id_by_name(const char* name, std::index_sequence<Idx, IdxTail...>)
    if constexpr(sizeof...(IdxTail) > 0)
        return id_by_name(name, std::index_sequence<IdxTail...>{});
    else
-        return ROCPROFILER_HSA_AMD_EXT_API_ID_NONE;
+        return ROCPROFILER_KERNEL_DISPATCH_LAST;
 }

 template <size_t... Idx>
@@ -73,7 +78,7 @@ void
 get_ids(std::vector<uint32_t>& _id_list, std::index_sequence<Idx...>)
 {
    auto _emplace = [](auto& _vec, uint32_t _v) {
-        if(_v < static_cast<uint32_t>(ROCPROFILER_HSA_AMD_EXT_API_ID_LAST)) _vec.emplace_back(_v);
+        if(_v < static_cast<uint32_t>(ROCPROFILER_KERNEL_DISPATCH_LAST)) _vec.emplace_back(_v);
    };

    (_emplace(_id_list, kernel_dispatch_info<Idx>::operation_idx), ...);
@@ -84,7 +89,7 @@ void
 get_names(std::vector<const char*>& _name_list, std::index_sequence<Idx...>)
 {
    auto _emplace = [](auto& _vec, const char* _v) {
-        if(_v != nullptr && strnlen(_v, 1) > 0) _vec.emplace_back(_v);
+        if(_v != nullptr && !std::string_view{_v}.empty()) _vec.emplace_back(_v);
    };

    (_emplace(_name_list, kernel_dispatch_info<Idx>::name), ...);
@@ -22,10 +22,6 @@

 #pragma once

-#include "lib/rocprofiler-sdk/hsa/queue_info_session.hpp"
-
-#include <rocprofiler-sdk/rocprofiler.h>
-
 #include <cstdint>
 #include <vector>

@@ -0,0 +1,140 @@
+// MIT License
+//
+// Copyright (c) 2023 Advanced Micro Devices, Inc. All rights reserved.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+#include "lib/rocprofiler-sdk/kernel_dispatch/profiling_time.hpp"
+#include "lib/common/logging.hpp"
+#include "lib/common/utility.hpp"
+#include "lib/rocprofiler-sdk/agent.hpp"
+#include "lib/rocprofiler-sdk/hsa/hsa.hpp"
+
+#include <rocprofiler-sdk/fwd.h>
+
+#include <hsa/hsa.h>
+
+#include <string_view>
+
+namespace rocprofiler
+{
+namespace kernel_dispatch
+{
+namespace
+{
+hsa_amd_profiling_dispatch_time_t&
+operator+=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t rhs)
+{
+    lhs.start += rhs;
+    lhs.end += rhs;
+    return lhs;
+}
+
+hsa_amd_profiling_dispatch_time_t&
+operator-=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t rhs)
+{
+    lhs.start -= rhs;
+    lhs.end -= rhs;
+    return lhs;
+}
+
+hsa_amd_profiling_dispatch_time_t&
+operator*=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t rhs)
+{
+    lhs.start *= rhs;
+    lhs.end *= rhs;
+    return lhs;
+}
+}  // namespace
+
+profiling_time&
+profiling_time::operator+=(uint64_t offset)
+{
+    start += offset;
+    end += offset;
+    return *this;
+}
+
+profiling_time&
+profiling_time::operator-=(uint64_t offset)
+{
+    start -= offset;
+    end -= offset;
+    return *this;
+}
+
+profiling_time&
+profiling_time::operator*=(uint64_t scale)
+{
+    start *= scale;
+    end *= scale;
+    return *this;
+}
+
+profiling_time
+get_dispatch_time(hsa_agent_t             _hsa_agent,
+                  hsa_signal_t            _signal,
+                  rocprofiler_kernel_id_t _kernel_id,
+                  std::optional<uint64_t> _baseline)
+{
+    static auto sysclock_period = hsa::get_hsa_timestamp_period();
+
+    auto ts                   = common::timestamp_ns();
+    auto dispatch_time        = hsa_amd_profiling_dispatch_time_t{};
+    auto dispatch_time_status = hsa::get_amd_ext_table()->hsa_amd_profiling_get_dispatch_time_fn(
+        _hsa_agent, _signal, &dispatch_time);
+
+    if(dispatch_time_status == HSA_STATUS_SUCCESS)
+    {
+        // if we encounter this in CI, it will cause test to fail
+        ROCP_CI_LOG_IF(ERROR, dispatch_time.end < dispatch_time.start)
+            << "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 dispatch times where the end time (" << dispatch_time.end
+            << ") was less than the start time (" << dispatch_time.start << ")";
+
+        // normalize
+        dispatch_time *= sysclock_period;
+
+        // below is a hack for clock skew issues:
+        // the timestamp of this handler for the kernel dispatch will always be after when the
+        // kernel completed
+        if(ts < dispatch_time.end) dispatch_time -= (dispatch_time.end - ts);
+
+        // below is a hack for clock skew issues:
+        // the timestamp of the packet rewriter for the kernel packet will always be before when the
+        // kernel started
+        if(_baseline && dispatch_time.start < *_baseline)
+            dispatch_time += (*_baseline - dispatch_time.start);
+    }
+    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);
+    }
+
+    return profiling_time{
+        .status = dispatch_time_status, .start = dispatch_time.start, .end = dispatch_time.end};
+}
+}  // namespace kernel_dispatch
+}  // namespace rocprofiler
@@ -0,0 +1,57 @@
+// MIT License
+//
+// Copyright (c) 2023 Advanced Micro Devices, Inc. All rights reserved.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+#pragma once
+
+#include <rocprofiler-sdk/fwd.h>
+#include <rocprofiler-sdk/hsa.h>
+
+#include <hsa/hsa.h>
+
+#include <cstdint>
+#include <optional>
+
+namespace rocprofiler
+{
+namespace kernel_dispatch
+{
+struct profiling_time
+{
+    hsa_status_t status = HSA_STATUS_ERROR_INVALID_SIGNAL;
+    uint64_t     start  = 0;
+    uint64_t     end    = 0;
+
+    profiling_time& operator+=(uint64_t offset);
+    profiling_time& operator-=(uint64_t offset);
+    profiling_time& operator*=(uint64_t scale);
+};
+
+// get the profiling time for a signal on an agent, if start time is less than baseline, correct to
+// start at baseline. If kernel_id is provided, it will be included in error log message if there is
+// an issue with
+profiling_time
+get_dispatch_time(hsa_agent_t             agent,
+                  hsa_signal_t            signal,
+                  rocprofiler_kernel_id_t kernel_id,
+                  std::optional<uint64_t> baseline = {});
+}  // namespace kernel_dispatch
+}  // namespace rocprofiler
@@ -27,6 +27,7 @@
 #include "lib/rocprofiler-sdk/context/context.hpp"
 #include "lib/rocprofiler-sdk/hsa/hsa.hpp"
 #include "lib/rocprofiler-sdk/hsa/queue.hpp"
+#include "lib/rocprofiler-sdk/kernel_dispatch/profiling_time.hpp"
 #include "lib/rocprofiler-sdk/tracing/tracing.hpp"

 #include <rocprofiler-sdk/callback_tracing.h>
@@ -36,16 +37,6 @@

 #include <string_view>

-#define ROCP_HSA_TABLE_CALL(SEVERITY, EXPR)                                                        \
-    auto ROCPROFILER_VARIABLE(rocp_hsa_table_call_, __LINE__) = (EXPR);                            \
-    ROCP_##SEVERITY##_IF(ROCPROFILER_VARIABLE(rocp_hsa_table_call_, __LINE__) !=                   \
-                         HSA_STATUS_SUCCESS)                                                       \
-        << #EXPR << " returned non-zero status code "                                              \
-        << ROCPROFILER_VARIABLE(rocp_hsa_table_call_, __LINE__) << " :: "                          \
-        << ::rocprofiler::hsa::get_hsa_status_string(                                              \
-               ROCPROFILER_VARIABLE(rocp_hsa_table_call_, __LINE__))                               \
-        << " "
-
 namespace rocprofiler
 {
 namespace kernel_dispatch
@@ -54,46 +45,24 @@ namespace
 {
 using queue_info_session_t     = hsa::queue_info_session;
 using kernel_dispatch_record_t = rocprofiler_buffer_tracing_kernel_dispatch_record_t;
-
-hsa_amd_profiling_dispatch_time_t&
-operator+=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t rhs)
-{
-    lhs.start += rhs;
-    lhs.end += rhs;
-    return lhs;
-}
-
-hsa_amd_profiling_dispatch_time_t&
-operator-=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t rhs)
-{
-    lhs.start -= rhs;
-    lhs.end -= rhs;
-    return lhs;
-}
-
-hsa_amd_profiling_dispatch_time_t&
-operator*=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t rhs)
-{
-    lhs.start *= rhs;
-    lhs.end *= rhs;
-    return lhs;
-}
 }  // namespace

-void
-dispatch_complete(queue_info_session_t& session)
+profiling_time
+get_dispatch_time(const hsa::queue_info_session& session)
 {
-    auto ts = common::timestamp_ns();
+    const auto& callback_record = session.callback_record;
+    const auto* _rocp_agent     = agent::get_agent(callback_record.dispatch_info.agent_id);
+    auto        _hsa_agent      = agent::get_hsa_agent(_rocp_agent);
+    auto        _signal         = session.kernel_pkt.kernel_dispatch.completion_signal;
+    auto        _kern_id        = callback_record.dispatch_info.kernel_id;

-    static auto sysclock_period = []() -> uint64_t {
-        constexpr auto nanosec     = 1000000000UL;
-        uint64_t       sysclock_hz = 0;
-        ROCP_HSA_TABLE_CALL(ERROR,
-                            hsa::get_core_table()->hsa_system_get_info_fn(
-                                HSA_SYSTEM_INFO_TIMESTAMP_FREQUENCY, &sysclock_hz));
-        return (nanosec / sysclock_hz);
-    }();
+    return (_hsa_agent) ? get_dispatch_time(*_hsa_agent, _signal, _kern_id, session.enqueue_ts)
+                        : profiling_time{.status = HSA_STATUS_ERROR_INVALID_AGENT};
+}

+void
+dispatch_complete(queue_info_session_t& session, profiling_time dispatch_time)
+{
    // get the contexts that were active when the signal was created
    auto& tracing_data_v = session.tracing_data;
    if(tracing_data_v.callback_contexts.empty() && tracing_data_v.buffered_contexts.empty()) return;
@@ -102,57 +71,16 @@ dispatch_complete(queue_info_session_t& session)
    auto* _corr_id = session.correlation_id;

    // only do the following work if there are contexts that require this info
-    auto&       callback_record  = session.callback_record;
-    const auto& _extern_corr_ids = session.tracing_data.external_correlation_ids;
-    const auto* _rocp_agent      = agent::get_agent(callback_record.dispatch_info.agent_id);
-    auto        _hsa_agent       = agent::get_hsa_agent(_rocp_agent);
-    auto        _kern_id         = callback_record.dispatch_info.kernel_id;
-    auto        _signal          = session.kernel_pkt.kernel_dispatch.completion_signal;
-    auto        _tid             = session.tid;
+    auto&       callback_record   = session.callback_record;
+    const auto& _extern_corr_ids  = session.tracing_data.external_correlation_ids;
+    auto        _tid              = session.tid;
+    auto        _internal_corr_id = (_corr_id) ? _corr_id->internal : 0;

-    auto dispatch_time = hsa_amd_profiling_dispatch_time_t{};
-    auto dispatch_time_status =
-        (_hsa_agent) ? hsa::get_amd_ext_table()->hsa_amd_profiling_get_dispatch_time_fn(
-                           *_hsa_agent, _signal, &dispatch_time)
-                     : HSA_STATUS_ERROR;
-
-    if(dispatch_time_status == HSA_STATUS_SUCCESS)
+    if(dispatch_time.status == HSA_STATUS_SUCCESS)
    {
-        // normalize
-        dispatch_time *= sysclock_period;
-
-        // below is a hack for clock skew issues:
-        // the timestamp of this handler for the kernel dispatch will always be after when the
-        // kernel completed
-        if(ts < dispatch_time.end) dispatch_time -= (dispatch_time.end - ts);
-
-        // below is a hack for clock skew issues:
-        // the timestamp of the packet rewriter for the kernel packet will always be before when the
-        // kernel started
-        if(dispatch_time.start < session.enqueue_ts)
-            dispatch_time += (session.enqueue_ts - dispatch_time.start);
-
        callback_record.start_timestamp = dispatch_time.start;
        callback_record.end_timestamp   = dispatch_time.end;
-    }

-    // if we encounter this in CI, it will cause test to fail
-    ROCP_CI_LOG_IF(
-        ERROR,
-        dispatch_time_status == HSA_STATUS_SUCCESS && dispatch_time.end < dispatch_time.start)
-        << "hsa_amd_profiling_get_dispatch_time for kernel_id=" << _kern_id
-        << " on rocprofiler_agent=" << _rocp_agent->id.handle
-        << " returned dispatch times where the end time (" << dispatch_time.end
-        << ") was less than the start time (" << dispatch_time.start << ")";
-
-    ROCP_CI_LOG_IF(ERROR, dispatch_time_status != HSA_STATUS_SUCCESS)
-        << "hsa_amd_profiling_get_dispatch_time for kernel id=" << _kern_id << " returned "
-        << dispatch_time_status << " :: " << hsa::get_hsa_status_string(dispatch_time_status);
-
-    auto _internal_corr_id = (_corr_id) ? _corr_id->internal : 0;
-
-    if(dispatch_time_status == HSA_STATUS_SUCCESS)
-    {
        if(!tracing_data_v.callback_contexts.empty())
        {
            auto tracer_data = callback_record;
@@ -22,18 +22,35 @@

 #pragma once

-#include "lib/rocprofiler-sdk/context/context.hpp"
 #include "lib/rocprofiler-sdk/hsa/queue_info_session.hpp"
+// #include "lib/rocprofiler-sdk/kernel_dispatch/profiling_time.hpp"
+
+#include <rocprofiler-sdk/fwd.h>
+#include <rocprofiler-sdk/hsa.h>
+
+#include <hsa/hsa.h>
+
+#include <cstdint>

 namespace rocprofiler
 {
+namespace context
+{
+struct context;
+}
+
 namespace kernel_dispatch
 {
 using context_t              = context::context;
 using user_data_map_t        = std::unordered_map<const context_t*, rocprofiler_user_data_t>;
 using external_corr_id_map_t = user_data_map_t;

+struct profiling_time;
+
+profiling_time
+get_dispatch_time(const hsa::queue_info_session& session);
+
 void
-dispatch_complete(hsa::queue_info_session&);
+dispatch_complete(hsa::queue_info_session&, profiling_time);
 }  // namespace kernel_dispatch
 }  // namespace rocprofiler