From ed9232563d711320b4a41c5b81072e5244dd0a9a Mon Sep 17 00:00:00 2001 From: Jacob Hilliard <64656371+jcbhl@users.noreply.github.com> Date: Wed, 30 Jun 2021 08:51:32 -0700 Subject: [PATCH] [ATOM-15862] Fixing CPU profiler to save multiple regions within the same thread (#1636) Signed-off-by: Jacob Hilliard --- .../Code/Source/AuxGeom/AuxGeomDrawQueue.cpp | 1 - .../ProfilingCaptureSystemComponent.cpp | 16 +++-- .../RHI/Code/Include/Atom/RHI/CpuProfiler.h | 6 +- .../Code/Include/Atom/RHI/CpuProfilerImpl.h | 14 +++- .../RHI/Code/Source/RHI/CpuProfilerImpl.cpp | 64 +++++++++++++------ .../Include/Atom/Utils/ImGuiCpuProfiler.inl | 62 ++++++++++++------ 6 files changed, 111 insertions(+), 52 deletions(-) diff --git a/Gems/Atom/Feature/Common/Code/Source/AuxGeom/AuxGeomDrawQueue.cpp b/Gems/Atom/Feature/Common/Code/Source/AuxGeom/AuxGeomDrawQueue.cpp index 2be6b562fc..0a1d6f5235 100644 --- a/Gems/Atom/Feature/Common/Code/Source/AuxGeom/AuxGeomDrawQueue.cpp +++ b/Gems/Atom/Feature/Common/Code/Source/AuxGeom/AuxGeomDrawQueue.cpp @@ -649,7 +649,6 @@ namespace AZ int32_t viewProjOverrideIndex) { AZ_PROFILE_FUNCTION(AZ::Debug::ProfileCategory::AzRender); - AZ_ATOM_PROFILE_FUNCTION("AuxGeom", "AuxGeomDrawQueue: DrawPrimitiveCommon"); // grab a mutex lock for the rest of this function so that a commit cannot happen during it and // other threads can't add geometry during it diff --git a/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp b/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp index 113e28db3b..874d385df6 100644 --- a/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp +++ b/Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp @@ -134,7 +134,7 @@ namespace AZ static void Reflect(AZ::ReflectContext* context); CpuProfilingStatisticsSerializer() = default; - CpuProfilingStatisticsSerializer(RHI::CpuProfiler::TimeRegionMap& timeRegionMap); + CpuProfilingStatisticsSerializer(const RHI::CpuProfiler::TimeRegionMap& timeRegionMap); AZStd::vector m_cpuProfilingStatisticsSerializerEntries; }; @@ -251,14 +251,17 @@ namespace AZ // --- CpuProfilingStatisticsSerializer --- - CpuProfilingStatisticsSerializer::CpuProfilingStatisticsSerializer(RHI::CpuProfiler::TimeRegionMap& timeRegionMap) + CpuProfilingStatisticsSerializer::CpuProfilingStatisticsSerializer(const RHI::CpuProfiler::TimeRegionMap& timeRegionMap) { // Create serializable entries - for (auto& treadEntry : timeRegionMap) + for (auto& threadEntry : timeRegionMap) { - for (auto& cachedRegionEntry : treadEntry.second) + for (auto& cachedRegionEntry : threadEntry.second) { - m_cpuProfilingStatisticsSerializerEntries.emplace_back(cachedRegionEntry.second); + m_cpuProfilingStatisticsSerializerEntries.insert( + m_cpuProfilingStatisticsSerializerEntries.end(), + cachedRegionEntry.second.begin(), + cachedRegionEntry.second.end()); } } } @@ -465,8 +468,7 @@ namespace AZ serializationSettings.m_keepDefaults = true; // Get time Cpu profiled time regions - RHI::CpuProfiler::TimeRegionMap timeRegionMap; - RHI::CpuProfiler::Get()->FlushTimeRegionMap(timeRegionMap); + const RHI::CpuProfiler::TimeRegionMap& timeRegionMap = RHI::CpuProfiler::Get()->GetTimeRegionMap(); CpuProfilingStatisticsSerializer serializer(timeRegionMap); const auto saveResult = JsonSerializationUtils::SaveObjectToFile(&serializer, diff --git a/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfiler.h b/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfiler.h index e103116a8a..a9c8107e57 100644 --- a/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfiler.h +++ b/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfiler.h @@ -60,7 +60,7 @@ namespace AZ class CpuProfiler { public: - using ThreadTimeRegionMap = AZStd::unordered_map; + using ThreadTimeRegionMap = AZStd::unordered_map>; using TimeRegionMap = AZStd::unordered_map; AZ_RTTI(CpuProfiler, "{127C1D0B-BE05-4E18-A8F6-24F3EED2ECA6}"); @@ -78,8 +78,8 @@ namespace AZ //! Ends a time region virtual void EndTimeRegion() = 0; - //! Flush cached regions from all threads to the passed parameter - virtual void FlushTimeRegionMap(TimeRegionMap& timeRegionMap) = 0; + //! Get the last frame's TimeRegionMap + virtual const TimeRegionMap& GetTimeRegionMap() const = 0; //! Enable/Disable the CpuProfiler virtual void SetProfilerEnabled(bool enabled) = 0; diff --git a/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfilerImpl.h b/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfilerImpl.h index f6e7467949..56de2a0395 100644 --- a/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfilerImpl.h +++ b/Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfilerImpl.h @@ -10,10 +10,13 @@ #include #include +#include #include #include #include +#include + namespace AZ { namespace RHI @@ -70,6 +73,9 @@ namespace AZ // When the thread is terminated, it will flag itself for deletion AZStd::atomic_bool m_deleteFlag = false; + + // Keep track of the regions that have hit the size limit so we don't have to lock to check + AZStd::map m_hitSizeLimitMap; }; //! CpuProfiler will keep track of the registered threads, and @@ -77,6 +83,7 @@ namespace AZ //! cached regions, which are stored on a per thread frequency. class CpuProfilerImpl final : public CpuProfiler + , public FrameEventBus::Handler { friend class CpuTimingLocalStorage; @@ -92,10 +99,12 @@ namespace AZ //! Unregisters the CpuProfilerImpl instance from the interface void Shutdown(); + void OnFrameBegin(); + //! CpuProfiler overrides... void BeginTimeRegion(TimeRegion& timeRegion) final; void EndTimeRegion() final; - void FlushTimeRegionMap(TimeRegionMap& timeRegionMap) final; + const TimeRegionMap& GetTimeRegionMap() const final; void SetProfilerEnabled(bool enabled) final; bool IsProfilerEnabled() const final; @@ -104,8 +113,7 @@ namespace AZ void RegisterThreadStorage(); // ThreadId -> ThreadTimeRegionMap - // When the user requests the cached time regions from the system, it will use this map as an intermediate - // storage point to flush each thread's cached regions into this map. + // On the start of each frame, this map will be updated with the last frame's profiling data. TimeRegionMap m_timeRegionMap; // Set of registered threads when created diff --git a/Gems/Atom/RHI/Code/Source/RHI/CpuProfilerImpl.cpp b/Gems/Atom/RHI/Code/Source/RHI/CpuProfilerImpl.cpp index 12690b3ba9..d494d6735a 100644 --- a/Gems/Atom/RHI/Code/Source/RHI/CpuProfilerImpl.cpp +++ b/Gems/Atom/RHI/Code/Source/RHI/CpuProfilerImpl.cpp @@ -11,6 +11,7 @@ #include #include +#include namespace AZ { @@ -78,6 +79,8 @@ namespace AZ { Interface::Register(this); m_initialized = true; + Device* rhiDevice = GetRHIDevice().get(); + FrameEventBus::Handler::BusConnect(rhiDevice); } void CpuProfilerImpl::Shutdown() @@ -98,6 +101,7 @@ namespace AZ m_registeredThreads.clear(); m_timeRegionMap.clear(); m_initialized = false; + FrameEventBus::Handler::BusDisconnect(); } void CpuProfilerImpl::BeginTimeRegion(TimeRegion& timeRegion) @@ -132,26 +136,9 @@ namespace AZ } } - void CpuProfilerImpl::FlushTimeRegionMap(TimeRegionMap& timeRegionMap) + const CpuProfiler::TimeRegionMap& CpuProfilerImpl::GetTimeRegionMap() const { - AZStd::unique_lock lock(m_threadRegisterMutex); - - // Iterate through all the threads, and collect the thread's cached time regions - for (auto& threadLocal : m_registeredThreads) - { - CpuProfiler::ThreadTimeRegionMap& threadMapEntry = m_timeRegionMap[threadLocal->m_executingThreadId]; - threadLocal->TryFlushCachedMap(threadMapEntry); - } - - // Clear all TLS that flagged themselves to be deleted, meaning that the thread is already terminated - AZStd::remove_if(m_registeredThreads.begin(), m_registeredThreads.end(), [](const RHI::Ptr& thread) - { - return thread->m_deleteFlag.load(); - }); - - // Flush all the cached time regions to the provided map - timeRegionMap = AZStd::move(m_timeRegionMap); - m_timeRegionMap.clear(); + return m_timeRegionMap; } void CpuProfilerImpl::SetProfilerEnabled(bool enabled) @@ -186,6 +173,32 @@ namespace AZ return m_enabled; } + void CpuProfilerImpl::OnFrameBegin() + { + if (!m_enabled) + { + return; + } + AZStd::unique_lock lock(m_threadRegisterMutex); + + // Iterate through all the threads, and collect the thread's cached time regions + TimeRegionMap newMap; + for (auto& threadLocal : m_registeredThreads) + { + ThreadTimeRegionMap& threadMapEntry = newMap[threadLocal->m_executingThreadId]; + threadLocal->TryFlushCachedMap(threadMapEntry); + } + + // Clear all TLS that flagged themselves to be deleted, meaning that the thread is already terminated + AZStd::remove_if(m_registeredThreads.begin(), m_registeredThreads.end(), [](const RHI::Ptr& thread) + { + return thread->m_deleteFlag.load(); + }); + + // Update our saved time regions to the last frame's collected data + m_timeRegionMap = AZStd::move(newMap); + } + void CpuProfilerImpl::RegisterThreadStorage() { @@ -261,6 +274,10 @@ namespace AZ // Gets called when region ends and all data is set void CpuTimingLocalStorage::AddCachedRegion(CachedTimeRegion&& timeRegionCached) { + if (m_hitSizeLimitMap[timeRegionCached.m_groupRegionName->m_regionName]) + { + return; + } // Add an entry to the cached region m_cachedTimeRegions.push_back(timeRegionCached); @@ -276,7 +293,13 @@ namespace AZ // Add the cached regions to the map for (auto& cachedTimeRegion : m_cachedTimeRegions) { - m_cachedTimeRegionMap[cachedTimeRegion.m_groupRegionName->m_regionName] = cachedTimeRegion; + const AZStd::string regionName = cachedTimeRegion.m_groupRegionName->m_regionName; + AZStd::vector& regionVec = m_cachedTimeRegionMap[regionName]; + regionVec.push_back(cachedTimeRegion); + if (regionVec.size() >= TimeRegionStackSize) + { + m_hitSizeLimitMap[cachedTimeRegion.m_groupRegionName->m_regionName] = true; + } } // Clear the cached regions @@ -295,6 +318,7 @@ namespace AZ { cachedTimeRegionMap = AZStd::move(m_cachedTimeRegionMap); m_cachedTimeRegionMap.clear(); + m_hitSizeLimitMap.clear(); } m_cachedTimeRegionMutex.unlock(); } diff --git a/Gems/Atom/Utils/Code/Include/Atom/Utils/ImGuiCpuProfiler.inl b/Gems/Atom/Utils/Code/Include/Atom/Utils/ImGuiCpuProfiler.inl index eb62a6f092..9b16ae81cf 100644 --- a/Gems/Atom/Utils/Code/Include/Atom/Utils/ImGuiCpuProfiler.inl +++ b/Gems/Atom/Utils/Code/Include/Atom/Utils/ImGuiCpuProfiler.inl @@ -9,6 +9,7 @@ #include #include #include +#include namespace AZ { @@ -30,6 +31,13 @@ namespace AZ const AZStd::string threadIdText = AZStd::string::format("Thread: %zu", static_cast(threadId)); ImGui::Text(threadIdText.c_str()); } + inline float TicksToMs(AZStd::sys_time_t ticks) + { + // Note: converting to microseconds integer before converting to milliseconds float + const AZStd::sys_time_t ticksPerSecond = AZStd::GetTimeTicksPerSecond(); + AZ_Assert(ticksPerSecond >= 1000, "Error in converting ticks to ms, expected ticksPerSecond >= 1000"); + return static_cast((ticks * 1000) / (ticksPerSecond / 1000)) / 1000.0f; + } } inline void ImGuiCpuProfiler::Draw(bool& keepDrawing, const AZ::RHI::CpuTimingStatistics& currentCpuTimingStatistics) @@ -73,9 +81,7 @@ namespace AZ const auto ShowTimeInMs = [ticksPerSecond](AZStd::sys_time_t duration) { - // Note: converting to microseconds integer before converting to milliseconds float - const float timeInMs = static_cast((duration * 1000) / (ticksPerSecond / 1000)) / 1000.0f; - ImGui::Text("%.2f ms", timeInMs); + ImGui::Text("%.2f ms", CpuProfilerImGuiHelper::TicksToMs(duration)); }; const auto ShowRow = [ticksPerSecond, &ShowTimeInMs](const char* regionLabel, AZStd::sys_time_t duration) @@ -117,19 +123,36 @@ namespace AZ ImGui::NextColumn(); // Draw the thread count label - const AZStd::string threadLabel = AZStd::string::format("Threads: %u", static_cast(regions.size())); + AZStd::sys_time_t totalTime = 0; + AZStd::set threads; + for (ThreadRegionEntry& entry : regions) // Find the thread count and total execution time for all threads + { + threads.insert(entry.m_threadId); + totalTime += entry.m_endTick - entry.m_startTick; + } + const AZStd::string threadLabel = AZStd::string::format("Threads: %u", static_cast(threads.size())); ImGui::Text(threadLabel.c_str()); DrawRegionHoverMarker(regions); ImGui::NextColumn(); - // Draw the region time label - ShowTimeInMs(duration); + // Draw the overall invocation count + const AZStd::string invocationLabel = AZStd::string::format("Total calls: %u", static_cast(regions.size())); + ImGui::Text(invocationLabel.c_str()); + DrawRegionHoverMarker(regions); + ImGui::NextColumn(); + + // Draw the time labels (max and then total) + const AZStd::string timeLabel = + AZStd::string::format("%.2f ms max, %.2f ms total", + CpuProfilerImGuiHelper::TicksToMs(duration), + CpuProfilerImGuiHelper::TicksToMs(totalTime)); + ImGui::Text(timeLabel.c_str()); ImGui::NextColumn(); }; // Set column settings. ImGui::Columns(2, "view", false); - ImGui::SetColumnWidth(0, 540.0f); + ImGui::SetColumnWidth(0, 660.0f); ImGui::SetColumnWidth(1, 100.0f); ShowRow("Frame to Frame Time", cpuTimingStatistics.m_frameToFrameTime); @@ -152,14 +175,15 @@ namespace AZ // Draw the regions if (ImGui::TreeNodeEx(timeRegionMapEntry.first.c_str(), ImGuiTreeNodeFlags_DefaultOpen)) { - ImGui::Columns(3, "view", false); + ImGui::Columns(4, "view", false); ImGui::SetColumnWidth(0, 400.0f); ImGui::SetColumnWidth(1, 100.0f); - ImGui::SetColumnWidth(2, 80.0f); + ImGui::SetColumnWidth(2, 150.0f); + ImGui::SetColumnWidth(3, 240.0f); for (auto& reigon : timeRegionMapEntry.second) { - // Calculate the thread with the longest execution time + // Calculate the region with the longest execution time AZStd::sys_time_t threadExecutionElapsed = 0; for (ThreadRegionEntry& entry : reigon.second) { @@ -209,19 +233,21 @@ namespace AZ m_groupRegionMap.clear(); // Get the latest TimeRegionMap - RHI::CpuProfiler::TimeRegionMap timeRegionMap; - RHI::CpuProfiler::Get()->FlushTimeRegionMap(timeRegionMap); + const RHI::CpuProfiler::TimeRegionMap& timeRegionMap = RHI::CpuProfiler::Get()->GetTimeRegionMap(); // Iterate through all the cached regions from all threads, and add the entries to this map - for (auto& treadEntry : timeRegionMap) + for (auto& threadEntry : timeRegionMap) { - for (auto& cachedRegionEntry : treadEntry.second) + for (auto& cachedRegionEntry : threadEntry.second) { - RegionEntryMap& groupRegionEntry = m_groupRegionMap[cachedRegionEntry.second.m_groupRegionName->m_groupName]; - AZStd::vector& regionArray = groupRegionEntry[cachedRegionEntry.second.m_groupRegionName->m_regionName]; - RHI::CachedTimeRegion& cachedRegion = cachedRegionEntry.second; + const AZStd::string& regionName = cachedRegionEntry.first; + for (auto& cachedRegion : cachedRegionEntry.second) + { + const AZStd::string& groupName = cachedRegion.m_groupRegionName->m_groupName; - regionArray.push_back({ treadEntry.first, cachedRegion.m_startTick, cachedRegion.m_endTick }); + m_groupRegionMap[groupName][regionName].push_back( + { threadEntry.first, cachedRegion.m_startTick, cachedRegion.m_endTick }); + } } } }