From 6e2a056e1bfe402191fea4ae9039418787457a04 Mon Sep 17 00:00:00 2001 From: Sean Keely Date: Thu, 18 Apr 2019 18:27:27 -0500 Subject: [PATCH] Correlate errors for time stamps which predate process start. Small times may be given to time conversion if GPU clocks are used to accumulate elapsed time. Because HSA APIs deal in absolute time this leads to large conversion offsets of order system uptime. Variation in relative clock ratio estimation may be amplified in this case, destroying elapsed time measurements. This patch fixes the relative clock ratio used for times which predate the call to hsa_init. This correlates errors in such times allowing the elapsed time to be correctly computed. The effective maximum system uptime before elapsed time conversion becomes inaccurate is ~3.5 months. GPU event timestamps are good for process uptime of ~3.5 months. These are limited by double's mantissa precision. Change-Id: I48752ff354920439d91016d6f2b0c8ddfa60b445 --- runtime/hsa-runtime/core/inc/amd_gpu_agent.h | 2 + .../core/runtime/amd_gpu_agent.cpp | 62 ++++++++++++------- runtime/hsa-runtime/core/runtime/runtime.cpp | 14 ++--- 3 files changed, 46 insertions(+), 32 deletions(-) diff --git a/runtime/hsa-runtime/core/inc/amd_gpu_agent.h b/runtime/hsa-runtime/core/inc/amd_gpu_agent.h index dc3dfe694d..db299842cd 100644 --- a/runtime/hsa-runtime/core/inc/amd_gpu_agent.h +++ b/runtime/hsa-runtime/core/inc/amd_gpu_agent.h @@ -433,6 +433,8 @@ class GpuAgent : public GpuAgentInt { HsaClockCounters t1_; + double historical_clock_ratio_; + // @brief Array of GPU cache property. std::vector cache_props_; diff --git a/runtime/hsa-runtime/core/runtime/amd_gpu_agent.cpp b/runtime/hsa-runtime/core/runtime/amd_gpu_agent.cpp index 90fcd13d47..83bdd71341 100644 --- a/runtime/hsa-runtime/core/runtime/amd_gpu_agent.cpp +++ b/runtime/hsa-runtime/core/runtime/amd_gpu_agent.cpp @@ -94,6 +94,7 @@ GpuAgent::GpuAgent(HSAuint32 node, const HsaNodeProperties& node_props) HSAKMT_STATUS err = hsaKmtGetClockCounters(node_id(), &t0_); t1_ = t0_; + historical_clock_ratio_ = 0.0; assert(err == HSAKMT_STATUS_SUCCESS && "hsaGetClockCounters error"); // Set instruction set architecture via node property, only on GPU device. @@ -1067,39 +1068,54 @@ void GpuAgent::ReleaseQueueScratch(ScratchInfo& scratch) { void GpuAgent::TranslateTime(core::Signal* signal, hsa_amd_profiling_dispatch_time_t& time) { - // Ensure interpolation - ScopedAcquire lock(&t1_lock_); - if (t1_.GPUClockCounter < signal->signal_.end_ts) { - SyncClocks(); - } + // Order is important, we want to translate the end time first to ensure that packet duration is + // not impacted by clock measurement latency jitter. + time.end = TranslateTime(signal->signal_.end_ts); + time.start = TranslateTime(signal->signal_.start_ts); if ((signal->signal_.start_ts == 0) || (signal->signal_.end_ts == 0) || (signal->signal_.start_ts > t1_.GPUClockCounter) || - (signal->signal_.end_ts > t1_.GPUClockCounter)) + (signal->signal_.end_ts > t1_.GPUClockCounter) || + (signal->signal_.start_ts < t0_.GPUClockCounter) || + (signal->signal_.end_ts < t0_.GPUClockCounter)) debug_print("Signal %p time stamps may be invalid.", &signal->signal_); - - time.start = uint64_t( - (double(int64_t(t0_.SystemClockCounter - t1_.SystemClockCounter)) / - double(int64_t(t0_.GPUClockCounter - t1_.GPUClockCounter))) * - double(int64_t(signal->signal_.start_ts - t1_.GPUClockCounter)) + - double(t1_.SystemClockCounter)); - time.end = uint64_t( - (double(int64_t(t0_.SystemClockCounter - t1_.SystemClockCounter)) / - double(int64_t(t0_.GPUClockCounter - t1_.GPUClockCounter))) * - double(int64_t(signal->signal_.end_ts - t1_.GPUClockCounter)) + - double(t1_.SystemClockCounter)); } +/* +Times during program execution are interpolated to adjust for relative clock drift. +Interval timing may appear as ticks well before process start, leading to large errors due to +frequency adjustment (ie the profiling with NTP problem). This is fixed by using a fixed frequency +for early times. +Intervals larger than t0_ will be frequency adjusted. This admits a numerical error of not more +than twice the frequency stability (~10^-5). +*/ uint64_t GpuAgent::TranslateTime(uint64_t tick) { + // Ensure interpolation for times during program execution. ScopedAcquire lock(&t1_lock_); - SyncClocks(); + if ((t1_.GPUClockCounter < tick) || (t1_.GPUClockCounter == t0_.GPUClockCounter)) SyncClocks(); + // Good for ~300 yrs + // uint64_t sysdelta = t1_.CPUClockCounter - t0_.CPUClockCounter; + // uint64_t gpudelta = t1_.GPUClockCounter - t0_.GPUClockCounter; + // int64_t offtick = int64_t(tick - t1_.GPUClockCounter); + //__int128 num = __int128(sysdelta)*__int128(offtick) + + //__int128(gpudelta)*__int128(t1_.CPUClockCounter); + //__int128 sysLarge = num / __int128(gpudelta); + // return sysLarge; + + // Good for ~3.5 months. uint64_t system_tick = 0; - system_tick = uint64_t( - (double(int64_t(t0_.SystemClockCounter - t1_.SystemClockCounter)) / - double(int64_t(t0_.GPUClockCounter - t1_.GPUClockCounter))) * - double(int64_t(tick - t1_.GPUClockCounter)) + - double(t1_.SystemClockCounter)); + double ratio = double(t1_.CPUClockCounter - t0_.CPUClockCounter) / + double(t1_.GPUClockCounter - t0_.GPUClockCounter); + system_tick = uint64_t(ratio * double(int64_t(tick - t1_.GPUClockCounter))) + t1_.CPUClockCounter; + + // tick predates HSA startup - extrapolate with fixed clock ratio + if (tick < t0_.GPUClockCounter) { + if (historical_clock_ratio_ == 0.0) historical_clock_ratio_ = ratio; + system_tick = uint64_t(historical_clock_ratio_ * double(int64_t(tick - t0_.GPUClockCounter))) + + t0_.CPUClockCounter; + } + return system_tick; } diff --git a/runtime/hsa-runtime/core/runtime/runtime.cpp b/runtime/hsa-runtime/core/runtime/runtime.cpp index d1d4a5f9f3..0448a28439 100644 --- a/runtime/hsa-runtime/core/runtime/runtime.cpp +++ b/runtime/hsa-runtime/core/runtime/runtime.cpp @@ -419,19 +419,15 @@ hsa_status_t Runtime::CopyMemory(void* dst, core::Agent& dst_agent, } if (profiling_enabled) { - HsaClockCounters clocks = {0}; - core::Runtime::runtime_singleton_->GetSystemInfo( - HSA_SYSTEM_INFO_TIMESTAMP, reinterpret_cast(&clocks)); - completion_signal->signal_.start_ts = clocks.SystemClockCounter; + core::Runtime::runtime_singleton_->GetSystemInfo(HSA_SYSTEM_INFO_TIMESTAMP, + &completion_signal->signal_.start_ts); } memcpy(dst, src, size); if (profiling_enabled) { - HsaClockCounters clocks = {0}; - core::Runtime::runtime_singleton_->GetSystemInfo( - HSA_SYSTEM_INFO_TIMESTAMP, reinterpret_cast(&clocks)); - completion_signal->signal_.end_ts = clocks.SystemClockCounter; + core::Runtime::runtime_singleton_->GetSystemInfo(HSA_SYSTEM_INFO_TIMESTAMP, + &completion_signal->signal_.end_ts); } completion_signal->SubRelease(1); @@ -513,7 +509,7 @@ hsa_status_t Runtime::GetSystemInfo(hsa_system_info_t attribute, void* value) { case HSA_SYSTEM_INFO_TIMESTAMP: { HsaClockCounters clocks; hsaKmtGetClockCounters(0, &clocks); - *((uint64_t*)value) = clocks.SystemClockCounter; + *((uint64_t*)value) = clocks.CPUClockCounter; break; } case HSA_SYSTEM_INFO_TIMESTAMP_FREQUENCY: {