From 9b747eb63c83847fd99bf2d2544852e705ccad42 Mon Sep 17 00:00:00 2001 From: "Jonathan R. Madsen" Date: Thu, 25 Apr 2024 14:36:11 -0500 Subject: [PATCH] Correct timestamp skew adjustments for kernel and async copy tracing (#827) [ROCm/rocprofiler-sdk commit: e2bce49655749d96f051839b0d791d7fee23b1ad] --- .../lib/rocprofiler-sdk/hsa/async_copy.cpp | 16 ++++++++++++---- .../kernel_dispatch/tracing.cpp | 18 +++++++++++++----- 2 files changed, 25 insertions(+), 9 deletions(-) diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/async_copy.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/async_copy.cpp index 6c876f35da..dff29c68dd 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/async_copy.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/hsa/async_copy.cpp @@ -340,6 +340,14 @@ operator+=(hsa_amd_profiling_async_copy_time_t& lhs, uint64_t rhs) return lhs; } +hsa_amd_profiling_async_copy_time_t& +operator-=(hsa_amd_profiling_async_copy_time_t& lhs, uint64_t rhs) +{ + lhs.start -= rhs; + lhs.end -= rhs; + return lhs; +} + hsa_amd_profiling_async_copy_time_t& operator*=(hsa_amd_profiling_async_copy_time_t& lhs, uint64_t rhs) { @@ -377,15 +385,15 @@ async_copy_handler(hsa_signal_value_t signal_value, void* arg) // normalize copy_time *= sysclock_period; + // below is a hack for clock skew issues: + // the timestamp of this handler for the copy will always be after when the copy ended + if(ts < copy_time.end) copy_time -= (copy_time.end - ts); + // below is a hack for clock skew issues: // the timestamp of the function call triggering the copy will always be before when the copy // started if(copy_time.start < _data->start_ts) copy_time += (_data->start_ts - copy_time.start); - // below is a hack for clock skew issues: - // the timestamp of this handler for the copy will always be after when the copy ended - if(copy_time.end < ts) copy_time += (ts - copy_time.end); - // if we encounter this in CI, it will cause test to fail ROCP_CI_LOG_IF(ERROR, copy_time_status == HSA_STATUS_SUCCESS && copy_time.end < copy_time.start) << "hsa_amd_profiling_get_async_copy_time for returned async times where the end time (" diff --git a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/kernel_dispatch/tracing.cpp b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/kernel_dispatch/tracing.cpp index 07e8db562f..32d1e6a29e 100644 --- a/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/kernel_dispatch/tracing.cpp +++ b/projects/rocprofiler-sdk/source/lib/rocprofiler-sdk/kernel_dispatch/tracing.cpp @@ -69,6 +69,14 @@ operator+=(hsa_amd_profiling_dispatch_time_t& lhs, uint64_t 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) { @@ -119,17 +127,17 @@ dispatch_complete(queue_info_session_t& session) // 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); - // 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(dispatch_time.end < ts) dispatch_time += (ts - dispatch_time.end); - callback_record.start_timestamp = dispatch_time.start; callback_record.end_timestamp = dispatch_time.end; }