From 6ec98753ca1e863e7fd208a153f77f16a73d42c5 Mon Sep 17 00:00:00 2001 From: Giovanni Baraldi Date: Wed, 12 Aug 2026 15:44:56 +0200 Subject: [PATCH] fix(rocprofiler-sdk): Add timestamps to thread trace shader data --- .../experimental/thread-trace/core.h | 18 +++ .../source/lib/aqlprofile/aql_profile_v2.h | 20 ++++ .../lib/aqlprofile/core/threadtrace.cpp | 31 +++++ .../source/lib/aqlprofile/pm4/cmd_builder.h | 7 +- .../lib/aqlprofile/pm4/gfx10_cmd_builder.h | 17 +++ .../lib/aqlprofile/pm4/gfx11_cmd_builder.h | 17 +++ .../lib/aqlprofile/pm4/gfx12_cmd_builder.h | 17 +++ .../lib/aqlprofile/pm4/gfx9_cmd_builder.h | 12 +- .../source/lib/aqlprofile/pm4/sqtt_builder.h | 62 ++++++---- .../att_no_intercept_quick_scan.cpp | 2 + .../lib/rocprofiler-sdk/hsa/aql_packet.cpp | 15 +++ .../lib/rocprofiler-sdk/hsa/aql_packet.hpp | 4 + .../lib/rocprofiler-sdk/thread_trace/core.cpp | 10 +- .../lib/rocprofiler-sdk/thread_trace/dl.cpp | 5 + .../lib/rocprofiler-sdk/thread_trace/dl.hpp | 2 + .../thread_trace/tests/producer_consumer.cpp | 112 ++++++++++++++++-- .../thread_trace/threading.cpp | 88 +++++++++++--- .../thread_trace/threading.hpp | 6 + .../tests/tools/thread-trace-callbacks.cpp | 3 + 19 files changed, 397 insertions(+), 51 deletions(-) diff --git a/projects/rocprofiler-sdk/source/include/rocprofiler-sdk/experimental/thread-trace/core.h b/projects/rocprofiler-sdk/source/include/rocprofiler-sdk/experimental/thread-trace/core.h index 6fa690d3c438..acd6dae46633 100644 --- a/projects/rocprofiler-sdk/source/include/rocprofiler-sdk/experimental/thread-trace/core.h +++ b/projects/rocprofiler-sdk/source/include/rocprofiler-sdk/experimental/thread-trace/core.h @@ -143,6 +143,19 @@ typedef enum rocprofiler_thread_trace_resource_mode_t /// @brief Initializes resources at first kernel dispatch per GPU. } rocprofiler_thread_trace_resource_mode_t; +/** + * @brief GPU and system clock values for a thread trace buffer record. + * + * @p gpu_clock is the timestamp in the GPU clock domain. + * @p system_clock is the same timestamp in the system clock domain. + * Approximate. Both values are zero when the data has no GPU-defined boundary. + */ +typedef struct rocprofiler_thread_trace_timestamp_t +{ + uint64_t gpu_clock; + rocprofiler_timestamp_t system_clock; +} rocprofiler_thread_trace_timestamp_t; + /** * @brief Bundle of shader data delivered to * rocprofiler_thread_trace_shader_data_callback_t. @@ -158,6 +171,11 @@ typedef struct rocprofiler_thread_trace_shader_data_t rocprofiler_agent_id_t agent; ///< Identifier for the target agent. rocprofiler_thread_trace_shader_data_flags_t flags; ///< Flags for this data chunk. + + /// Timestamp at which collection into this data chunk began. + rocprofiler_thread_trace_timestamp_t start_timestamp; + /// Timestamp at which collection into this data chunk ended. + rocprofiler_thread_trace_timestamp_t end_timestamp; } rocprofiler_thread_trace_shader_data_t; /** diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/aql_profile_v2.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/aql_profile_v2.h index ab767af74ca2..454f3ee8d380 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/aql_profile_v2.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/aql_profile_v2.h @@ -457,6 +457,12 @@ typedef hsa_status_t (*aqlprofile_pmc_data_callback_t)(aqlprofile_pmc_event_t ev uint64_t counter_value, void* userdata); +typedef struct aqlprofile_att_gpu_clock_t +{ + uint64_t start; ///< Most recent start-packet clock. + uint64_t latest; ///< Most recent swap- or stop-packet clock. +} aqlprofile_att_gpu_clock_t; + /** * @brief Data callback for thread trace. This will be called at least once per shader engine * @param[in] shader Shader Engine ID @@ -628,6 +634,20 @@ typedef struct aqlprofile_att_buffer_status_t uint64_t read_offset; } aqlprofile_att_buffer_status_t; +/** + * @brief Read GPU clocks written by the ATT start/stop/swap packets. + * + * This query only reads the trace control buffer and does not update buffer status. + * + * @param[out] out Latest GPU clock values. + * @param[in] handle Handle returned by aqlprofile_att_create_packets(). + * @param[in] shader_engine_id Shader engine (SE) ID. + */ +hsa_status_t +aqlprofile_att_get_gpu_clock(aqlprofile_att_gpu_clock_t* out, + aqlprofile_handle_t handle, + int shader_engine_id); + /** * @brief Fn to retrieve buffer status. * Must be called at least once with has_buffer_swapped=true for every swap packet inserted. diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/core/threadtrace.cpp b/projects/rocprofiler-sdk/source/lib/aqlprofile/core/threadtrace.cpp index c7ac8e3ab47c..8ebd398cbb64 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/core/threadtrace.cpp +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/core/threadtrace.cpp @@ -301,6 +301,12 @@ _internal_aqlprofile_att_create_packets(aqlprofile_handle_t* ha } auto* control_ptr = memorymgr->GetTraceControlBuf(); + // The allocation callback returns uninitialized storage; initialize clocks before GPU writes. + for(size_t i = 0; i < se_number_total; ++i) + { + control_ptr[i].gpu_clock_start = 0; + control_ptr[i].gpu_clock_latest = 0; + } trace_config.control_buffer_ptr = control_ptr; trace_config.control_buffer_size = control_size; @@ -455,6 +461,31 @@ aqlprofile_att_update_buffer_status(aqlprofile_att_buffer_status_t* out, return HSA_STATUS_SUCCESS; } +PUBLIC_API hsa_status_t +aqlprofile_att_get_gpu_clock(aqlprofile_att_gpu_clock_t* out, + aqlprofile_handle_t handle, + int shader_engine_id) +{ + if(out == nullptr || shader_engine_id < 0) return HSA_STATUS_ERROR_INVALID_ARGUMENT; + + auto generic_manager = MemoryManager::GetManager(handle.handle); + auto* manager = dynamic_cast(generic_manager.get()); + if(manager == nullptr) return HSA_STATUS_ERROR; + + auto* factory = aql_profile::Pm4Factory::Create(manager->AgentHandle()); + if(static_cast(shader_engine_id) >= factory->GetShaderEnginesNumber()) + return HSA_STATUS_ERROR_INVALID_ARGUMENT; + + const auto se_per_xcc = + factory->GetShaderEnginesNumber() / std::max(1u, factory->GetXccNumber()); + volatile auto& control = manager->GetTraceControlBuf< + pm4_builder::TraceControl>()[static_cast(shader_engine_id) / se_per_xcc]; + + out->start = control.gpu_clock_start; + out->latest = control.gpu_clock_latest; + return HSA_STATUS_SUCCESS; +} + PUBLIC_API hsa_status_t aqlprofile_att_get_buffer_packets(uint64_t* header, hsa_ext_amd_aql_pm4_packet_t* query_status, diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/cmd_builder.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/cmd_builder.h index f2566463531a..540d8ac4bc78 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/cmd_builder.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/cmd_builder.h @@ -305,7 +305,7 @@ class CmdBuilder /// @param cmdBuf command buffer to be appended with launch command virtual void BuildPrimeL2(CmdBuffer* cmdBuf, uint64_t addr) = 0; - /// @brief Generates RT packets into thread trace buffer (gfx9 only) + /// @brief Generates an RT timestamp marker in the thread trace buffer (GFX9 only). /// @param cmdBuf command buffer to be appended with launch command /// @param dst where gpu clock data is r/w. Must persist during packet dispatch /// @param reg userdata register address @@ -315,6 +315,11 @@ class CmdBuilder const Register& reg, uint32_t header){}; + /// @brief Copies the GPU clock to memory without writing SQ thread-trace userdata registers. + /// @param cmdBuf command buffer to be appended with the copy command + /// @param dst destination for the GPU clock; must persist during packet dispatch + virtual void BuildReadGPUClockPacket(CmdBuffer* cmdBuf, uint64_t* dst){}; + /// @brief Release resources used by CmdBuilder virtual ~CmdBuilder(){}; diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx10_cmd_builder.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx10_cmd_builder.h index 71434997f6c8..d646ee7ee6fc 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx10_cmd_builder.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx10_cmd_builder.h @@ -482,6 +482,23 @@ class Gfx10CmdBuilder : public CmdBuilder { BuildCopyRegDataPacket(cmd, get_addr(reg), dst_addr, size, wait); } + + void BuildReadGPUClockPacket(CmdBuffer* cmd_buffer, uint64_t* dst) override + { + uint32_t header = MakePacket3Header(PACKET3_COPY_DATA, 6 * sizeof(uint32_t)); + uint32_t control = + PACKET3_COPY_DATA__SRC_SEL(PACKET3_COPY_DATA__SRC_SEL__GPU_CLOCK_COUNT) | + PACKET3_COPY_DATA__SRC_CACHE_POLICY(PACKET3_COPY_DATA__SRC_CACHE_POLICY__LRU) | + PACKET3_COPY_DATA__DST_SEL(PACKET3_COPY_DATA__DST_SEL__TC_L2) | + PACKET3_COPY_DATA__DST_CACHE_POLICY(PACKET3_COPY_DATA__DST_CACHE_POLICY__LRU) | + PACKET3_COPY_DATA__WR_CONFIRM(PACKET3_COPY_DATA__WR_CONFIRM__WAIT_FOR_CONFIRMATION) | + PACKET3_COPY_DATA__COUNT_SEL(PACKET3_COPY_DATA__COUNT_SEL__64_BITS_OF_DATA); + uint32_t dst_lo = PACKET3_COPY_DATA__DST_64B_ADDR_LO(PtrLow32(dst) >> 3); + uint32_t dst_hi = PACKET3_COPY_DATA__DST_ADDR_HI(PtrHigh32(dst)); + + uint32_t packet[6] = {header, control, 0, 0, dst_lo, dst_hi}; + APPEND_COMMAND_WRAPPER(cmd_buffer, packet); + } }; } // namespace pm4_builder diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx11_cmd_builder.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx11_cmd_builder.h index 1d921bf0f76a..6150609af2a8 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx11_cmd_builder.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx11_cmd_builder.h @@ -504,6 +504,23 @@ class Gfx11CmdBuilder : public CmdBuilder { BuildCopyRegDataPacket(cmd, get_addr(reg), dst_addr, size, wait); } + + void BuildReadGPUClockPacket(CmdBuffer* cmd_buffer, uint64_t* dst) override + { + uint32_t header = MakePacket3Header(PACKET3_COPY_DATA, 6 * sizeof(uint32_t)); + uint32_t control = + PACKET3_COPY_DATA__SRC_SEL(PACKET3_COPY_DATA__SRC_SEL__GPU_CLOCK_COUNT) | + PACKET3_COPY_DATA__SRC_CACHE_POLICY(PACKET3_COPY_DATA__SRC_CACHE_POLICY__LRU) | + PACKET3_COPY_DATA__DST_SEL(PACKET3_COPY_DATA__DST_SEL__TC_L2) | + PACKET3_COPY_DATA__DST_CACHE_POLICY(PACKET3_COPY_DATA__DST_CACHE_POLICY__LRU) | + PACKET3_COPY_DATA__WR_CONFIRM(PACKET3_COPY_DATA__WR_CONFIRM__WAIT_FOR_CONFIRMATION) | + PACKET3_COPY_DATA__COUNT_SEL(PACKET3_COPY_DATA__COUNT_SEL__64_BITS_OF_DATA); + uint32_t dst_lo = PACKET3_COPY_DATA__DST_64B_ADDR_LO(PtrLow32(dst) >> 3); + uint32_t dst_hi = PACKET3_COPY_DATA__DST_ADDR_HI(PtrHigh32(dst)); + + uint32_t packet[6] = {header, control, 0, 0, dst_lo, dst_hi}; + APPEND_COMMAND_WRAPPER(cmd_buffer, packet); + } }; } // namespace pm4_builder diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx12_cmd_builder.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx12_cmd_builder.h index c37155f4a935..4e0e8cd19ee0 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx12_cmd_builder.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx12_cmd_builder.h @@ -800,6 +800,23 @@ class Gfx12CmdBuilder : public CmdBuilder { BuildCopyRegDataPacket(cmd, get_addr(reg), dst_addr, size, wait); } + + void BuildReadGPUClockPacket(CmdBuffer* cmd_buffer, uint64_t* dst) override + { + uint32_t header = MakePacket3Header(PACKET3_COPY_DATA, 6 * sizeof(uint32_t)); + uint32_t control = + PACKET3_COPY_DATA__SRC_SEL(PACKET3_COPY_DATA__SRC_SEL__GPU_CLOCK_COUNT) | + PACKET3_COPY_DATA__SRC_TEMPORAL(PACKET3_COPY_DATA__SRC_TEMPORAL__LU) | + PACKET3_COPY_DATA__DST_SEL(PACKET3_COPY_DATA__DST_SEL__TC_L2) | + PACKET3_COPY_DATA__DST_TEMPORAL(PACKET3_COPY_DATA__DST_TEMPORAL__LU) | + PACKET3_COPY_DATA__WR_CONFIRM(PACKET3_COPY_DATA__WR_CONFIRM__WAIT_FOR_CONFIRMATION) | + PACKET3_COPY_DATA__COUNT_SEL(PACKET3_COPY_DATA__COUNT_SEL__64_BITS_OF_DATA); + uint32_t dst_lo = PACKET3_COPY_DATA__DST_64B_ADDR_LO(PtrLow32(dst) >> 3); + uint32_t dst_hi = PACKET3_COPY_DATA__DST_ADDR_HI(PtrHigh32(dst)); + + uint32_t packet[6] = {header, control, 0, 0, dst_lo, dst_hi}; + APPEND_COMMAND_WRAPPER(cmd_buffer, packet); + } }; } // namespace pm4_builder diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx9_cmd_builder.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx9_cmd_builder.h index e6756f693810..b899403f7a5c 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx9_cmd_builder.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/gfx9_cmd_builder.h @@ -548,8 +548,6 @@ class Gfx9CmdBuilder : public CmdBuilder std::array ClockRetrievePacket(uint64_t* dst) { - auto addr = reinterpret_cast(dst); - uint32_t header = MakePacket3Header(PACKET3_COPY_DATA, 6 * sizeof(uint32_t)); uint32_t dword2 = @@ -560,8 +558,8 @@ class Gfx9CmdBuilder : public CmdBuilder PACKET3_COPY_DATA__WR_CONFIRM(PACKET3_COPY_DATA__WR_CONFIRM__WAIT_FOR_CONFIRMATION) | PACKET3_COPY_DATA__COUNT_SEL(PACKET3_COPY_DATA__COUNT_SEL__64_BITS_OF_DATA); - uint32_t dword5 = PACKET3_COPY_DATA__DST_64B_ADDR_LO(addr >> 3); - uint32_t dword6 = PACKET3_COPY_DATA__DST_ADDR_HI(High32(addr)); + uint32_t dword5 = PACKET3_COPY_DATA__DST_64B_ADDR_LO(PtrLow32(dst) >> 3); + uint32_t dword6 = PACKET3_COPY_DATA__DST_ADDR_HI(PtrHigh32(dst)); return {header, dword2, 0, 0, dword5, dword6}; } @@ -627,6 +625,12 @@ class Gfx9CmdBuilder : public CmdBuilder APPEND_COMMAND_WRAPPER(cmdBuf, copy_data); } } + + void BuildReadGPUClockPacket(CmdBuffer* cmdBuf, uint64_t* dst) override + { + auto copy_data = ClockRetrievePacket(dst); + APPEND_COMMAND_WRAPPER(cmdBuf, copy_data); + } }; } // namespace pm4_builder diff --git a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/sqtt_builder.h b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/sqtt_builder.h index b8d34ce4d6e6..2b3de1e7a29c 100644 --- a/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/sqtt_builder.h +++ b/projects/rocprofiler-sdk/source/lib/aqlprofile/pm4/sqtt_builder.h @@ -95,8 +95,8 @@ struct TraceControl uint32_t cntr{0}; uint32_t wptr{0}; uint32_t status2{0}; - uint64_t gpu_clock_cnt_start{0}; - uint64_t gpu_clock_cnt_end{0}; + uint64_t gpu_clock_start{0}; + uint64_t gpu_clock_latest{0}; uint32_t status_double_buffer{0}; uint32_t wptr_doublebuffer{0}; }; @@ -524,7 +524,6 @@ class GpuSqttBuilder (1 + cu_per_se) * ((config->perfcounters.size() + 3) & ~3) * config->perfPeriod; builder.BuildWriteUConfigRegPacket(cmd_buffer, userdata_channel, packet.u32All); } - if(Primitives::GFXIP_LEVEL == 9 && config->enable_rt_timestamp) { for(size_t xcc = 0; xcc < GetXCCNumber(); xcc++) { @@ -532,8 +531,10 @@ class GpuSqttBuilder XCC_Packet_Lock lock(builder, cmd_buffer, GetXCCNumber(), xcc); auto& control = reinterpret_cast(config->control_buffer_ptr)[xcc]; - InsertTimestampMarker(cmd_buffer, &control.gpu_clock_cnt_start); + CaptureClock(cmd_buffer, &control.gpu_clock_start, config->enable_rt_timestamp); } + builder.BuildCacheFlushPacket( + cmd_buffer, size_t(config->control_buffer_ptr), config->control_buffer_size); } } @@ -542,21 +543,19 @@ class GpuSqttBuilder SetGRBMToBroadcast(cmd_buffer); const uint32_t se_number_xcc = se_number_total / std::max(1u, GetXCCNumber()); - if(Primitives::GFXIP_LEVEL == 9) { - if(config->enable_rt_timestamp) + for(size_t xcc = 0; xcc < GetXCCNumber(); xcc++) { - for(size_t xcc = 0; xcc < GetXCCNumber(); xcc++) - { - if(!isXccEnabled(xcc, se_number_xcc, config)) continue; + if(!isXccEnabled(xcc, se_number_xcc, config)) continue; - XCC_Packet_Lock lock(builder, cmd_buffer, GetXCCNumber(), xcc); - auto& control = - reinterpret_cast(config->control_buffer_ptr)[xcc]; - InsertTimestampMarker(cmd_buffer, &control.gpu_clock_cnt_end); - } + XCC_Packet_Lock lock(builder, cmd_buffer, GetXCCNumber(), xcc); + auto& control = reinterpret_cast(config->control_buffer_ptr)[xcc]; + CaptureClock(cmd_buffer, &control.gpu_clock_latest, config->enable_rt_timestamp); } + } + if(Primitives::GFXIP_LEVEL == 9) + { // Program the thread trace mode register to disable thread trace builder.BuildWriteUConfigRegPacket(cmd_buffer, Primitives::SQ_THREAD_TRACE_MODE_ADDR, @@ -717,14 +716,30 @@ class GpuSqttBuilder virtual void InsertTimestampMarker(CmdBuffer* cmd_buffer, uint64_t* addr) override { - rocprof_trace_decoder_packet_header_t header{}; - header.opcode = ROCPROF_TRACE_DECODER_PACKET_OPCODE_RT_TIMESTAMP; - header.type = 0; - header.data20 = 0; + if constexpr(Primitives::GFXIP_LEVEL == 9) + { + rocprof_trace_decoder_packet_header_t header{}; + header.opcode = ROCPROF_TRACE_DECODER_PACKET_OPCODE_RT_TIMESTAMP; + header.type = 0; + header.data20 = 0; - SetGRBMToBroadcast(cmd_buffer); - builder.BuildGPUClockPacket( - cmd_buffer, addr, Primitives::SQ_THREAD_TRACE_USERDATA_3, header.u32All); + SetGRBMToBroadcast(cmd_buffer); + builder.BuildGPUClockPacket( + cmd_buffer, addr, Primitives::SQ_THREAD_TRACE_USERDATA_3, header.u32All); + } + } + + void CaptureClock(CmdBuffer* cmd_buffer, uint64_t* addr, bool emit_marker) + { + if constexpr(Primitives::GFXIP_LEVEL == 9) + { + if(emit_marker) + { + InsertTimestampMarker(cmd_buffer, addr); + return; + } + } + builder.BuildReadGPUClockPacket(cmd_buffer, addr); } template @@ -803,7 +818,12 @@ class GpuSqttBuilder WriteConfigPacket(cmd_buffer, reg_lo, buff1_lo); WriteConfigPacket(cmd_buffer, reg_hi, buff1_hi); } + auto& control = + reinterpret_cast(config->control_buffer_ptr)[se_id / se_per_xcc]; + builder.BuildReadGPUClockPacket(cmd_buffer, &control.gpu_clock_latest); builder.BuildCacheFlushPacket(cmd_buffer, size_t(prev), config->data_buffer_size); + builder.BuildCacheFlushPacket( + cmd_buffer, size_t(config->control_buffer_ptr), config->control_buffer_size); SetGRBMToBroadcast(cmd_buffer); } diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk-tool/att_no_intercept_quick_scan.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk-tool/att_no_intercept_quick_scan.cpp index aa06b356871b..573bf3875de2 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk-tool/att_no_intercept_quick_scan.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk-tool/att_no_intercept_quick_scan.cpp @@ -294,6 +294,8 @@ forward_cut(agent_state_t& state, shader_data.read_offset = 0; shader_data.agent = state.id; shader_data.flags = ROCPROFILER_THREAD_TRACE_SHADER_DATA_FLAGS_NONE; + shader_data.start_timestamp = original.start_timestamp; + shader_data.end_timestamp = original.end_timestamp; auto userdata = rocprofiler_user_data_t{}; userdata.value = capture_id.fetch_add(1); diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.cpp index adaea3be84e7..7bc33d412d57 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.cpp @@ -301,6 +301,21 @@ SQTTBufferingPackets::query_buffer_status() return query; } +aqlprofile_att_gpu_clock_t +get_gpu_clock(aqlprofile_handle_t handle, int shader_engine_id) +{ + auto clock = aqlprofile_att_gpu_clock_t{}; + auto* dl = rocprofiler::thread_trace::get_aqlprofile_dl(); + if(dl && dl->get_gpu_clock_fn) dl->get_gpu_clock_fn(&clock, handle, shader_engine_id); + return clock; +} + +aqlprofile_att_gpu_clock_t +SQTTBufferingPackets::get_gpu_clock() const +{ + return hsa::get_gpu_clock(handle, shader_engine_id); +} + CodeobjMarkerAQLPacket::CodeobjMarkerAQLPacket(const TraceMemoryPool& _tracepool, uint64_t id, uint64_t addr, diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.hpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.hpp index 1d3276ef3f9a..705746447fad 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.hpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/aql_packet.hpp @@ -284,6 +284,9 @@ struct sqtt_buffer_status_t bool gpu_full{}; }; +aqlprofile_att_gpu_clock_t +get_gpu_clock(aqlprofile_handle_t handle, int shader_engine_id); + // Virtual members for mocking in tests class SQTTBufferingPackets { @@ -293,6 +296,7 @@ class SQTTBufferingPackets hsa_ext_amd_aql_pm4_packet_t query_status{}; virtual std::optional query_buffer_status(); + virtual aqlprofile_att_gpu_clock_t get_gpu_clock() const; virtual hsa_status_t iterate_data(aqlprofile_att_data_callback_t callback, void* data) { return aqlprofile_att_iterate_data(handle, callback, data); diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/core.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/core.cpp index e623d2f21600..57c8d6bb48cf 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/core.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/core.cpp @@ -78,6 +78,8 @@ struct cbdata_t rocprofiler_thread_trace_shader_data_callback_t cb_fn = nullptr; const rocprofiler_user_data_t* userdata = nullptr; uint64_t next_chunk = 0; + + aqlprofile_handle_t handle{}; }; // Keeps track of a single client registering for serialized thread trace @@ -98,6 +100,9 @@ thread_trace_callback(uint32_t shader, void* buffer, uint64_t size, void* callba { auto& cb_data = *static_cast(callback_data); + // Clock storage is per XCC; select it using this callback's shader engine. + auto clock = hsa::get_gpu_clock(cb_data.handle, shader); + auto shader_data = rocprofiler_thread_trace_shader_data_t{}; shader_data.size = sizeof(shader_data); shader_data.data = buffer; @@ -107,6 +112,8 @@ thread_trace_callback(uint32_t shader, void* buffer, uint64_t size, void* callba shader_data.read_offset = 0; shader_data.agent = cb_data.agent; shader_data.flags = ROCPROFILER_THREAD_TRACE_SHADER_DATA_FLAGS_END; + shader_data.start_timestamp = convert_timestamp(cb_data.agent, clock.start); + shader_data.end_timestamp = convert_timestamp(cb_data.agent, clock.latest); cb_data.cb_fn(shader_data, *cb_data.userdata); // The iterator guarantees the last chunk is tagged with END; here we just @@ -251,7 +258,8 @@ ThreadTracerAgent::iterate_data(aqlprofile_handle_t handle, rocprofiler_user_dat cbdata_t cb_dt{}; - cb_dt.agent = agent_id; + cb_dt.agent = agent_id; + cb_dt.handle = handle; // Walk each buffer produced by the ATT runtime and forward it to the // registered shader callback. cb_dt.cb_fn = params.shader_cb_fn; diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.cpp index 9a4e2cd2566d..f89b1332c5b0 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.cpp @@ -125,12 +125,15 @@ AQLProfileDL::AQLProfileDL() // and would not see handles registered by the vendored aqlprofile_att_create_packets. get_buffer_packets_fn = &aqlprofile_att_get_buffer_packets; update_buffer_status_fn = &aqlprofile_att_update_buffer_status; + get_gpu_clock_fn = &aqlprofile_att_get_gpu_clock; #else // External aqlprofile: load symbols from libhsa-amd-aqlprofile64.so get_buffer_packets_fn = reinterpret_cast( dlsym(RTLD_DEFAULT, "aqlprofile_att_get_buffer_packets")); update_buffer_status_fn = reinterpret_cast( dlsym(RTLD_DEFAULT, "aqlprofile_att_update_buffer_status")); + get_gpu_clock_fn = + reinterpret_cast(dlsym(RTLD_DEFAULT, "aqlprofile_att_get_gpu_clock")); if(valid()) return; @@ -155,6 +158,8 @@ AQLProfileDL::AQLProfileDL() reinterpret_cast(dlsym(handle, "aqlprofile_att_get_buffer_packets")); update_buffer_status_fn = reinterpret_cast( dlsym(handle, "aqlprofile_att_update_buffer_status")); + get_gpu_clock_fn = + reinterpret_cast(dlsym(handle, "aqlprofile_att_get_gpu_clock")); #endif } diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.hpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.hpp index 64b5bf094abb..1fe8b40e5f49 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.hpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/dl.hpp @@ -57,6 +57,7 @@ class AQLProfileDL { using GetBufferPacketsFn = decltype(aqlprofile_att_get_buffer_packets); using UpdateBufferStatusFn = decltype(aqlprofile_att_update_buffer_status); + using GetGPUClockFn = decltype(aqlprofile_att_get_gpu_clock); public: AQLProfileDL(); @@ -69,6 +70,7 @@ class AQLProfileDL GetBufferPacketsFn* get_buffer_packets_fn = nullptr; UpdateBufferStatusFn* update_buffer_status_fn = nullptr; + GetGPUClockFn* get_gpu_clock_fn = nullptr; void* handle = nullptr; }; diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/tests/producer_consumer.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/tests/producer_consumer.cpp index 303c189d7632..d95482abde4a 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/tests/producer_consumer.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/tests/producer_consumer.cpp @@ -95,19 +95,26 @@ make_mock_queue(rocprofiler_agent_id_t agent_id) } using query_status_t = std::function(void)>; +using query_clock_t = std::function; using drain_t = std::function; class MockPackets : public hsa::SQTTBufferingPackets { public: - MockPackets(aqlprofile_handle_t _handle, query_status_t _query) + MockPackets(aqlprofile_handle_t _handle, query_status_t _query, query_clock_t _clock) : hsa::SQTTBufferingPackets(_handle, 0) - , query_fn(std::move(_query)){}; + , query_fn(std::move(_query)) + , clock_fn(std::move(_clock)){}; std::optional query_buffer_status() override { return query_fn(); }; - query_status_t query_fn; - drain_t drain_fn{}; - hsa_status_t iterate_data(aqlprofile_att_data_callback_t callback, void* data) override + aqlprofile_att_gpu_clock_t get_gpu_clock() const override + { + return clock_fn ? clock_fn() : aqlprofile_att_gpu_clock_t{}; + } + query_status_t query_fn; + query_clock_t clock_fn; + drain_t drain_fn{}; + hsa_status_t iterate_data(aqlprofile_att_data_callback_t callback, void* data) override { return drain_fn ? drain_fn(callback, data) : SQTTBufferingPackets::iterate_data(callback, data); @@ -134,7 +141,8 @@ start_threads(rocprofiler_thread_trace_shader_data_callback_t cb_fn, const query_status_t& query_fn, rocprofiler_user_data_t userdata, decltype(att_queue_t::submit_fn) submit_fn = mock_submit, - drain_t drain_fn = {}) + drain_t drain_fn = {}, + query_clock_t clock = {}) { // Build a synthetic queue + packet stack that mimics the runtime so we can // exercise the producer/consumer pairing without a real GPU. @@ -173,7 +181,8 @@ start_threads(rocprofiler_thread_trace_shader_data_callback_t cb_fn, // them here or the producer aborts with small_vector::at out_of_range. control_packet->populate_before(); control_packet->populate_after(); - auto buffer_packet = std::make_unique(control_packet->GetHandle(), query_fn); + auto buffer_packet = + std::make_unique(control_packet->GetHandle(), query_fn, clock); buffer_packet->header = 1; buffer_packet->drain_fn = std::move(drain_fn); @@ -318,6 +327,95 @@ TEST(thread_trace, final_drain_preserves_data_and_end) } } +TEST(thread_trace, timestamps_follow_buffer_boundaries) +{ + using timestamp_t = rocprofiler_thread_trace_timestamp_t; + struct state_t + { + std::atomic data_callbacks{0}; + std::mutex mut; + std::map> timestamps; + } state; + + rocprofiler::thread_trace::test_init(); + + auto* ext_table = rocprofiler::hsa::get_amd_ext_table(); + auto original_convert_fn = ext_table->hsa_amd_profiling_convert_tick_to_system_domain_fn; + ext_table->hsa_amd_profiling_convert_tick_to_system_domain_fn = + [](hsa_agent_t, uint64_t gpu_clock, uint64_t* system_clock) { + *system_clock = gpu_clock * 10; + return HSA_STATUS_SUCCESS; + }; + + auto fetch_cb = [](rocprofiler_thread_trace_shader_data_t shader_data, + rocprofiler_user_data_t userdata) { + auto* callback_state = static_cast(userdata.ptr); + { + auto lock = std::lock_guard{callback_state->mut}; + callback_state->timestamps.emplace( + shader_data.chunk_index, + std::make_pair(shader_data.start_timestamp, shader_data.end_timestamp)); + } + callback_state->data_callbacks.fetch_add(1); + }; + + auto input_buffer = + std::vector(rocprofiler::thread_trace::MOCK_BUFFER_SIZE / sizeof(size_t)); + auto status_calls = std::atomic{0}; + auto query_status = [&]() -> std::optional { + auto called = status_calls.load(); + if(called >= 2 || called > state.data_callbacks.load()) return std::nullopt; + status_calls.fetch_add(1); + auto status = rocprofiler::hsa::sqtt_buffer_status_t{}; + status.data = input_buffer.data(); + status.size = rocprofiler::thread_trace::MOCK_BUFFER_SIZE; + return status; + }; + + auto clock_calls = std::atomic{0}; + auto query_clock = [&]() { + auto call = clock_calls.fetch_add(1); + return aqlprofile_att_gpu_clock_t{100, 100 * (call + 1)}; + }; + auto userdata = rocprofiler_user_data_t{.ptr = &state}; + auto threads = rocprofiler::thread_trace::start_threads( + fetch_cb, query_status, userdata, rocprofiler::thread_trace::mock_submit, {}, query_clock); + + while(state.data_callbacks.load() < 3) + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + threads.flag->store(rocprofiler::thread_trace::WORKER_FLAG_STOP); + threads.join_all(); + ext_table->hsa_amd_profiling_convert_tick_to_system_domain_fn = original_convert_fn; + + auto lock = std::lock_guard{state.mut}; + ASSERT_GE(state.timestamps.size(), 4u); + const auto& header = state.timestamps.at(0); + const auto& first = state.timestamps.at(1); + const auto& second = state.timestamps.at(2); + const auto& final = state.timestamps.at(3); + + EXPECT_EQ(header.first.gpu_clock, 0u); + EXPECT_EQ(header.first.system_clock, 0u); + EXPECT_EQ(header.second.gpu_clock, 0u); + EXPECT_EQ(header.second.system_clock, 0u); + + EXPECT_EQ(first.first.gpu_clock, 100u); + EXPECT_EQ(first.second.gpu_clock, 200u); + EXPECT_EQ(second.first.gpu_clock, first.second.gpu_clock); + EXPECT_EQ(second.second.gpu_clock, 300u); + EXPECT_EQ(final.first.gpu_clock, second.second.gpu_clock); + EXPECT_EQ(final.second.gpu_clock, 400u); + + for(const auto& [chunk, timestamps] : state.timestamps) + { + if(chunk == 0) continue; + EXPECT_LT(timestamps.first.gpu_clock, timestamps.second.gpu_clock); + EXPECT_LT(timestamps.first.system_clock, timestamps.second.system_clock); + EXPECT_EQ(timestamps.first.system_clock, timestamps.first.gpu_clock * 10); + EXPECT_EQ(timestamps.second.system_clock, timestamps.second.gpu_clock * 10); + } +} + TEST(thread_trace, multiple_calls) { rocprofiler::thread_trace::test_init(); diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.cpp index 96022ca6604a..2fbb820f8f2a 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.cpp @@ -26,6 +26,7 @@ #include "lib/common/environment.hpp" #include "lib/common/scope_destructor.hpp" #include "lib/common/utility.hpp" +#include "lib/rocprofiler-sdk/agent.hpp" #include "lib/rocprofiler-sdk/thread_trace/core.hpp" #include @@ -40,6 +41,32 @@ namespace thread_trace { constexpr double SQTT_BANDWIDTH_DEFAULT = 60E9; // 60GB/s, for wiggle room +rocprofiler_thread_trace_timestamp_t +convert_timestamp(rocprofiler_agent_id_t agent_id, uint64_t gpu_clock) +{ + auto result = rocprofiler_thread_trace_timestamp_t{}; + result.gpu_clock = gpu_clock; + if(gpu_clock == 0) return result; + + // KFD queues do not carry an HSA agent; resolve it from the SDK agent ID. + auto hsa_agent = agent::get_hsa_agent(agent_id); + if(!hsa_agent) return result; + + auto* ext_table = hsa::get_amd_ext_table(); + if(ext_table == nullptr || + ext_table->hsa_amd_profiling_convert_tick_to_system_domain_fn == nullptr) + return result; + + auto status = ext_table->hsa_amd_profiling_convert_tick_to_system_domain_fn( + *hsa_agent, gpu_clock, &result.system_clock); + if(status != HSA_STATUS_SUCCESS) + { + result.system_clock = 0; + ROCP_CI_LOG(ERROR) << "Failed to convert thread trace GPU clock: " << status; + } + return result; +} + namespace { struct trace_callback_data_t @@ -104,6 +131,9 @@ consumer_loop( shader_data.agent = agent_id; shader_data.flags = static_cast(slot.flags); + shader_data.start_timestamp = slot.start_timestamp; + shader_data.end_timestamp = slot.end_timestamp; + callback_fn(shader_data, userdata); // Hand the slot back to the producer. @@ -146,6 +176,8 @@ producer_loop( bool do_sleep{false}; uint64_t next_chunk_index = 0; + auto current_ts = rocprofiler_thread_trace_timestamp_t{}; + auto sleep_fn = [&]() { sched_yield(); std::this_thread::sleep_for(std::chrono::microseconds(interval_microseconds)); @@ -168,20 +200,24 @@ producer_loop( } }; - auto send_to_consumer = [&](void* src, - size_t size, - int flags, - size_t slot_idx, - bool isHeader = false, - uint64_t read_offset = 0) { + auto send_to_consumer = [&](void* src, + size_t size, + int flags, + size_t slot_idx, + bool isHeader = false, + uint64_t read_offset = 0, + rocprofiler_thread_trace_timestamp_t start_ts = {}, + rocprofiler_thread_trace_timestamp_t end_ts = {}) { auto t0 = std::chrono::system_clock::now(); - auto& buffer = buffers[slot_idx]; - buffer.flags = flags; - buffer.size = size; - buffer.se_id = buffer_packet.shader_engine_id; - buffer.chunk_index = next_chunk_index++; - buffer.read_offset = read_offset; + auto& buffer = buffers[slot_idx]; + buffer.flags = flags; + buffer.size = size; + buffer.se_id = buffer_packet.shader_engine_id; + buffer.chunk_index = next_chunk_index++; + buffer.read_offset = read_offset; + buffer.start_timestamp = start_ts; + buffer.end_timestamp = end_ts; if(!isHeader) parameters.copy_data_fn(queue, buffer.memory, src, size); @@ -215,8 +251,11 @@ producer_loop( // Drain remaining ATT data after a stop; waits for a free slot to land it in. auto iterate_trace = [&]() { - size_t idx = wait_for_free_slot(); - auto wptr = iterate_data(buffer_packet); + size_t idx = wait_for_free_slot(); + auto wptr = iterate_data(buffer_packet); + auto clock = buffer_packet.get_gpu_clock(); + if(current_ts.gpu_clock == 0) current_ts = convert_timestamp(queue.agent_id, clock.start); + auto end_ts = convert_timestamp(queue.agent_id, clock.latest); buffer_packet.reset_current_buffer(); int flags = ROCPROFILER_THREAD_TRACE_SHADER_DATA_FLAGS_END; if(wptr.status == HSA_STATUS_ERROR_OUT_OF_RESOURCES) @@ -232,7 +271,7 @@ producer_loop( wptr.size = 0; } ROCP_INFO << "Iterate data with size: " << wptr.size; - send_to_consumer(wptr.data, wptr.size, flags, idx); + send_to_consumer(wptr.data, wptr.size, flags, idx, false, 0, current_ts, end_ts); }; std::array header_plus_zeros{}; // Used for warmup the decoder path @@ -274,6 +313,10 @@ producer_loop( if(!att_queue_submit(queue, &buffer_packet.query_status, &submit_signal)) return; signal_wait(submit_signal); + // The completed query also orders the initial start packet before reading its clock. + if(current_ts.gpu_clock == 0) + current_ts = convert_timestamp(queue.agent_id, buffer_packet.get_gpu_clock().start); + if(auto status = buffer_packet.query_buffer_status()) { if(status->gpu_full) @@ -299,6 +342,7 @@ producer_loop( // the swap has executed. if(!att_queue_submit(queue, &status->packet, &submit_signal)) return; signal_wait(submit_signal); + auto swap_ts = convert_timestamp(queue.agent_id, buffer_packet.get_gpu_clock().latest); ROCP_FATAL_IF(status->size != buffer_size) << "GPU buffer overflow: " << status->size << " vs " << buffer_size; @@ -316,8 +360,15 @@ producer_loop( slot_idx = wait_for_free_slot(); } - send_to_consumer( - status->data, buffer_size, flags, slot_idx, false, status->read_offset); + send_to_consumer(status->data, + buffer_size, + flags, + slot_idx, + false, + status->read_offset, + current_ts, + swap_ts); + current_ts = swap_ts; if(cpu_full) { @@ -325,6 +376,9 @@ producer_loop( send_header(); if(!parameters.restart_trace(parameters.control_packet)) return; + // Restart submission is asynchronous. Read its clock after the next completed + // query (or the final stop), just as for the initial start packet. + current_ts = {}; } // The status_query test verifies we immediately poll again after consuming a // buffer, so skip the backoff when a flip just occurred. diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.hpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.hpp index 2e14b65feca8..63b237446de3 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.hpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/thread_trace/threading.hpp @@ -37,6 +37,9 @@ namespace rocprofiler { namespace thread_trace { +rocprofiler_thread_trace_timestamp_t +convert_timestamp(rocprofiler_agent_id_t agent_id, uint64_t gpu_clock); + /// Shared state coordinating the single producer and N worker threads. /// /// Each slot is owned by exactly one consumer thread; the producer hands @@ -66,6 +69,9 @@ struct triple_buffer_shared_data_t uint64_t chunk_index{0}; uint64_t read_offset{0}; + rocprofiler_thread_trace_timestamp_t start_timestamp{}; + rocprofiler_thread_trace_timestamp_t end_timestamp{}; + /// Producer sets true after writing slot fields; consumer stores /// false after running the callback. std::atomic filled{false}; diff --git a/projects/rocprofiler-sdk/tests/tools/thread-trace-callbacks.cpp b/projects/rocprofiler-sdk/tests/tools/thread-trace-callbacks.cpp index 50b25d72b336..ef408120e52b 100644 --- a/projects/rocprofiler-sdk/tests/tools/thread-trace-callbacks.cpp +++ b/projects/rocprofiler-sdk/tests/tools/thread-trace-callbacks.cpp @@ -73,6 +73,9 @@ void shader_data_callback(rocprofiler_thread_trace_shader_data_t shader_data, rocprofiler_user_data_t /* userdata */) { + assert(shader_data.start_timestamp.gpu_clock <= shader_data.end_timestamp.gpu_clock); + assert(shader_data.start_timestamp.system_clock <= shader_data.end_timestamp.system_clock); + auto parse = [](rocprofiler_thread_trace_decoder_record_type_t record_type_id, void* trace_events, uint64_t trace_size,