birkeh/o3de
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

[ATOM-15862] Fixing CPU profiler to save multiple regions within the same thread (#1636)

Browse Source 
Signed-off-by: Jacob Hilliard <jhlliar@amazon.com>
This commit is contained in:
Jacob Hilliard
2021-06-30 08:51:32 -07:00
committed by GitHub
parent 03c8110d02
commit ed9232563d
6 changed files with 111 additions and 52 deletions
Download Patch File Download Diff File Expand all files Collapse all files
Gems/Atom/Feature/Common/Code/Source/AuxGeom/AuxGeomDrawQueue.cpp
-1
View File
@@ -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
Gems/Atom/Feature/Common/Code/Source/ProfilingCaptureSystemComponent.cpp
+9 -7
View File
@@ -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<CpuProfilingStatisticsSerializerEntry> 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,
Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfiler.h
+3 -3
View File
@@ -60,7 +60,7 @@ namespace AZ
class CpuProfiler
{
public:
using ThreadTimeRegionMap = AZStd::unordered_map<AZStd::string, CachedTimeRegion>;
using ThreadTimeRegionMap = AZStd::unordered_map<AZStd::string, AZStd::vector<CachedTimeRegion>>;
using TimeRegionMap = AZStd::unordered_map<AZStd::thread_id, ThreadTimeRegionMap>;
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;
Gems/Atom/RHI/Code/Include/Atom/RHI/CpuProfilerImpl.h
+11 -3
View File
@@ -10,10 +10,13 @@
#include <Atom/RHI.Reflect/Base.h>
#include <AzCore/Memory/OSAllocator.h>
#include <AzCore/std/containers/map.h>
#include <AzCore/std/parallel/mutex.h>
#include <AzCore/std/parallel/shared_mutex.h>
#include <AzCore/std/smart_ptr/intrusive_refcount.h>
#include <Atom/RHI/FrameEventBus.h>
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<AZStd::string, bool> 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
Gems/Atom/RHI/Code/Source/RHI/CpuProfilerImpl.cpp
+44 -20
View File
@@ -11,6 +11,7 @@
#include <AzCore/std/smart_ptr/shared_ptr.h>
#include <AzCore/Debug/Timer.h>
#include <Atom/RHI/RHIUtils.h>
namespace AZ
{
@@ -78,6 +79,8 @@ namespace AZ
{
Interface<CpuProfiler>::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<AZStd::mutex> 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<CpuTimingLocalStorage>& 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<AZStd::mutex> 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<CpuTimingLocalStorage>& 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<CachedTimeRegion>& 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();
}
Gems/Atom/Utils/Code/Include/Atom/Utils/ImGuiCpuProfiler.inl
+44 -18
View File
@@ -9,6 +9,7 @@
#include <Atom/RPI.Public/RPISystemInterface.h>
#include <AzCore/IO/Path/Path_fwd.h>
#include <AzCore/std/time.h>
#include <AzCore/std/containers/set.h>
namespace AZ
{
@@ -30,6 +31,13 @@ namespace AZ
const AZStd::string threadIdText = AZStd::string::format("Thread: %zu", static_cast<size_t>(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<float>((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<float>((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<uint32_t>(regions.size()));
AZStd::sys_time_t totalTime = 0;
AZStd::set<AZStd::thread_id> 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<uint32_t>(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<uint32_t>(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<ThreadRegionEntry>& 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 });
}
}
}
}