From 42b8236f93fc09336861c460b9cfa5d3e0830c86 Mon Sep 17 00:00:00 2001 From: Saleel Kudchadker Date: Fri, 30 Apr 2021 15:05:54 -0700 Subject: [PATCH] SWDEV-280773 - Additional logging for signals Cleanup new lines in debug log Change-Id: I6862c332eb9457b51e23cf4e9db9ba3f870d0c39 --- rocclr/device/rocm/rocblit.cpp | 10 +++++----- rocclr/device/rocm/rocvirtual.cpp | 12 ++++++------ rocclr/device/rocm/rocvirtual.hpp | 12 ++++++++++-- 3 files changed, 21 insertions(+), 13 deletions(-) diff --git a/rocclr/device/rocm/rocblit.cpp b/rocclr/device/rocm/rocblit.cpp index 54a048d13c..e4ff536840 100644 --- a/rocclr/device/rocm/rocblit.cpp +++ b/rocclr/device/rocm/rocblit.cpp @@ -457,7 +457,7 @@ bool DmaBlitManager::copyBufferRect(device::Memory& srcMemory, device::Memory& d // Copy memory line by line ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, - "[%zx]!\t HSA Asycn Copy Rect wait_event=0x%zx, completion_signal=0x%zx\n", + "[%zx]!\t HSA Asycn Copy Rect wait_event=0x%zx, completion_signal=0x%zx", std::this_thread::get_id(), (wait_event != nullptr) ? wait_event->handle : 0, active.handle); hsa_status_t status = hsa_amd_memory_async_copy_rect(&dstMem, &offset, @@ -479,7 +479,7 @@ bool DmaBlitManager::copyBufferRect(device::Memory& srcMemory, device::Memory& d // Copy memory line by line ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, - "[%zx]!\t HSA Asycn Copy wait_event=0x%zx, completion_signal=0x%zx\n", + "[%zx]!\t HSA Asycn Copy wait_event=0x%zx, completion_signal=0x%zx", std::this_thread::get_id(), (wait_event != nullptr) ? wait_event->handle : 0, active.handle); hsa_status_t status = hsa_amd_memory_async_copy( @@ -668,7 +668,7 @@ bool DmaBlitManager::hsaCopy(const Memory& srcMemory, const Memory& dstMemory, // Use SDMA to transfer the data ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, - "[%zx]!\t HSA Asycn Copy wait_event=0x%zx, completion_signal=0x%zx\n", + "[%zx]!\t HSA Asycn Copy wait_event=0x%zx, completion_signal=0x%zx", std::this_thread::get_id(), (wait_event != nullptr) ? wait_event->handle : 0, active.handle); @@ -726,7 +726,7 @@ bool DmaBlitManager::hsaCopyStaged(const_address hostSrc, address hostDst, size_ memcpy(hsaBuffer, hostSrc + offset, size); ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, - "[%zx]!\t HSA Async Copy completion_signal=0x%zx\n", + "[%zx]!\t HSA Async Copy completion_signal=0x%zx", std::this_thread::get_id(), active.handle); status = hsa_amd_memory_async_copy(hostDst + offset, dev().getBackendDevice(), hsaBuffer, srcAgent, size, 0, nullptr, active); @@ -756,7 +756,7 @@ bool DmaBlitManager::hsaCopyStaged(const_address hostSrc, address hostDst, size_ // Copy data from Device to Host ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, - "[%zx]!\t HSA Async Copy completion_signal=0x%zx\n", + "[%zx]!\t HSA Async Copy completion_signal=0x%zx", std::this_thread::get_id(), active.handle); status = hsa_amd_memory_async_copy(hsaBuffer, dstAgent, hostSrc + offset, dev().getBackendDevice(), size, 0, nullptr, active); diff --git a/rocclr/device/rocm/rocvirtual.cpp b/rocclr/device/rocm/rocvirtual.cpp index e5c08233f3..1c68a93022 100644 --- a/rocclr/device/rocm/rocvirtual.cpp +++ b/rocclr/device/rocm/rocvirtual.cpp @@ -153,7 +153,7 @@ bool HsaAmdSignalHandler(hsa_signal_value_t value, void* arg) { return false; } amd::ScopedLock sl(ts->gpu()->execution()); - ClPrint(amd::LOG_INFO, amd::LOG_SIG, "Handler: value(%d), timestamp(%p), handle(%lx)\n", + ClPrint(amd::LOG_INFO, amd::LOG_SIG, "Handler: value(%d), timestamp(%p), handle(0x%lx)", static_cast(value), arg, ts->HwProfiling() ? ts->Signals()[0]->signal_.handle : 0); // Update the batch, since signal is complete @@ -347,7 +347,7 @@ hsa_signal_t VirtualGPU::HwQueueTracker::ActiveSignal( if (HSA_STATUS_SUCCESS != result) { LogError("hsa_amd_signal_async_handler() failed to set the handler!"); } else { - ClPrint(amd::LOG_INFO, amd::LOG_SIG, "Set Handler: handle(%lx), timestamp(%p)\n", + ClPrint(amd::LOG_INFO, amd::LOG_SIG, "Set Handler: handle(0x%lx), timestamp(%p)", prof_signal->signal_.handle, prof_signal); } } @@ -417,7 +417,7 @@ bool VirtualGPU::HwQueueTracker::CpuWaitForSignal(ProfilingSignal* signal) { if (signal->ts_ != nullptr) { signal->ts_->checkGpuTime(); } else { - ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, "[%zx]!\t Host wait on completion_signal=0x%zx\n", + ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, "[%zx]!\t Host wait on completion_signal=0x%zx", std::this_thread::get_id(), signal->signal_.handle); if (!WaitForSignal(signal->signal_)) { LogPrintfError("Failed signal [0x%lx] wait", signal->signal_); @@ -572,7 +572,7 @@ bool VirtualGPU::processMemObjects(const amd::Kernel& kernel, const_address para const void* globalAddress = *reinterpret_cast(params + desc.offset_); ClPrint(amd::LOG_INFO, amd::LOG_KERN, - "!\targ%d: %s %s = ptr:%p obj:[%p-%p] threadId : %zx\n", + "!\targ%d: %s %s = ptr:%p obj:[%p-%p] threadId : %zx", index, desc.typeName_.c_str(), desc.name_.c_str(), globalAddress, gpuMem->getDeviceMemory(), reinterpret_cast
(gpuMem->getDeviceMemory()) + mem->getSize(), @@ -2178,7 +2178,7 @@ void VirtualGPU::submitStreamOperation(amd::StreamOperationCommand& cmd) { // Use GPU Blit to write bool result = blitMgr().fillBuffer(*memory, &value, sizeBytes, origin, size, entire, true); - ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, "Writting value: 0x%lx \n", value); + ClPrint(amd::LOG_DEBUG, amd::LOG_COPY, "Writting value: 0x%lx", value); if (!result) { LogError("submitStreamOperation: Write failed!"); @@ -2526,7 +2526,7 @@ bool VirtualGPU::submitKernelInternal(const amd::NDRangeContainer& sizes, const return false; } - ClPrint(amd::LOG_INFO, amd::LOG_KERN, "[%zx]!\tShaderName : %s\n", + ClPrint(amd::LOG_INFO, amd::LOG_KERN, "[%zx]!\tShaderName : %s", std::this_thread::get_id(), gpuKernel.name().c_str()); // Check if runtime has to setup hidden arguments diff --git a/rocclr/device/rocm/rocvirtual.hpp b/rocclr/device/rocm/rocvirtual.hpp index d3263b7c46..739e1a20fa 100644 --- a/rocclr/device/rocm/rocvirtual.hpp +++ b/rocclr/device/rocm/rocvirtual.hpp @@ -187,7 +187,12 @@ class VirtualGPU : public device::VirtualDevice { Timestamp* ts = nullptr, uint32_t queue_size = 0); //! Wait for the curent active signal. Can idle the queue - bool WaitCurrent() { return CpuWaitForSignal(signal_list_[current_id_]); } + bool WaitCurrent() { + ProfilingSignal* signal = signal_list_[current_id_]; + ClPrint(amd::LOG_DEBUG, amd::LOG_MISC, "[%zx]!\t WaitCurret completion_signal=0x%zx", + std::this_thread::get_id(), signal->signal_.handle); + return CpuWaitForSignal(signal); + } //! Update current active engine void SetActiveEngine(HwQueueEngine engine = HwQueueEngine::Compute) { engine_ = engine; } @@ -211,7 +216,10 @@ class VirtualGPU : public device::VirtualDevice { //! Wait for the next active signal void WaitNext() { size_t next = (current_id_ + 1) % signal_list_.size(); - CpuWaitForSignal(signal_list_[next]); + ProfilingSignal* signal = signal_list_[next]; + ClPrint(amd::LOG_DEBUG, amd::LOG_MISC, "[%zx]!\t WaitNext completion_signal=0x%zx", + std::this_thread::get_id(), signal->signal_.handle); + CpuWaitForSignal(signal); } //! Wait for the provided signal