From d25954725f9f61b870ca9886883d959035cc518d Mon Sep 17 00:00:00 2001 From: Wojtek Figat Date: Mon, 16 Oct 2023 10:58:07 +0200 Subject: [PATCH] Add excluding GPU swapchain present time from CPU draw time in profiling tool --- Source/Engine/Graphics/GPUDevice.cpp | 7 +++++ Source/Engine/Profiler/ProfilerGPU.cpp | 17 +++++++++--- Source/Engine/Profiler/ProfilerGPU.h | 33 ++++++++++------------- Source/Engine/Profiler/ProfilingTools.cpp | 4 ++- 4 files changed, 38 insertions(+), 23 deletions(-) diff --git a/Source/Engine/Graphics/GPUDevice.cpp b/Source/Engine/Graphics/GPUDevice.cpp index 019cfad5a..34d8e7661 100644 --- a/Source/Engine/Graphics/GPUDevice.cpp +++ b/Source/Engine/Graphics/GPUDevice.cpp @@ -503,6 +503,9 @@ void GPUDevice::DrawEnd() // Call present on all used tasks int32 presentCount = 0; bool anyVSync = false; +#if COMPILE_WITH_PROFILER + const double presentStart = Platform::GetTimeSeconds(); +#endif for (int32 i = 0; i < RenderTask::Tasks.Count(); i++) { const auto task = RenderTask::Tasks[i]; @@ -537,6 +540,10 @@ void GPUDevice::DrawEnd() #endif GetMainContext()->Flush(); } +#if COMPILE_WITH_PROFILER + const double presentEnd = Platform::GetTimeSeconds(); + ProfilerGPU::OnPresentTime((float)((presentEnd - presentStart) * 1000.0)); +#endif _wasVSyncUsed = anyVSync; _isRendering = false; diff --git a/Source/Engine/Profiler/ProfilerGPU.cpp b/Source/Engine/Profiler/ProfilerGPU.cpp index 3054abe67..6944441be 100644 --- a/Source/Engine/Profiler/ProfilerGPU.cpp +++ b/Source/Engine/Profiler/ProfilerGPU.cpp @@ -74,6 +74,7 @@ void ProfilerGPU::EventBuffer::Clear() _data.Clear(); _isResolved = false; FrameIndex = 0; + PresentTime = 0.0f; } GPUTimerQuery* ProfilerGPU::GetTimerQuery() @@ -133,7 +134,9 @@ void ProfilerGPU::BeginFrame() // Clear stats RenderStatsData::Counter = RenderStatsData(); _depth = 0; - Buffers[CurrentBuffer].FrameIndex = Engine::FrameCount; + auto& buffer = Buffers[CurrentBuffer]; + buffer.FrameIndex = Engine::FrameCount; + buffer.PresentTime = 0.0f; // Try to resolve previous frames for (int32 i = 0; i < PROFILER_GPU_EVENTS_FRAMES; i++) @@ -149,6 +152,12 @@ void ProfilerGPU::OnPresent() buffer.EndAll(); } +void ProfilerGPU::OnPresentTime(float time) +{ + auto& buffer = Buffers[CurrentBuffer]; + buffer.PresentTime += time; +} + void ProfilerGPU::EndFrame() { if (_depth) @@ -164,7 +173,7 @@ void ProfilerGPU::EndFrame() buffer.Clear(); } -bool ProfilerGPU::GetLastFrameData(float& drawTimeMs, RenderStatsData& statsData) +bool ProfilerGPU::GetLastFrameData(float& drawTimeMs, float& presentTimeMs, RenderStatsData& statsData) { uint64 maxFrame = 0; int32 maxFrameIndex = -1; @@ -177,17 +186,19 @@ bool ProfilerGPU::GetLastFrameData(float& drawTimeMs, RenderStatsData& statsData maxFrameIndex = i; } } - if (maxFrameIndex != -1) { auto& frame = frames[maxFrameIndex]; const auto root = frame.Get(0); drawTimeMs = root->Time; + presentTimeMs = frame.PresentTime; statsData = root->Stats; return true; } + // No data drawTimeMs = 0.0f; + presentTimeMs = 0.0f; Platform::MemoryClear(&statsData, sizeof(statsData)); return false; } diff --git a/Source/Engine/Profiler/ProfilerGPU.h b/Source/Engine/Profiler/ProfilerGPU.h index fa2c72ab0..94ed345b9 100644 --- a/Source/Engine/Profiler/ProfilerGPU.h +++ b/Source/Engine/Profiler/ProfilerGPU.h @@ -20,6 +20,8 @@ class GPUTimerQuery; API_CLASS(Static) class FLAXENGINE_API ProfilerGPU { DECLARE_SCRIPTING_TYPE_NO_SPAWN(ProfilerGPU); + friend class Engine; + friend class GPUDevice; public: /// /// Represents single CPU profiling event data. @@ -69,6 +71,11 @@ public: /// uint64 FrameIndex; + /// + /// Sum of all present events duration on CPU during this frame (in milliseconds). + /// + float PresentTime; + /// /// Determines whether this buffer has ready data (resolved and not empty). /// @@ -151,32 +158,20 @@ public: /// The event token index returned by the BeginEvent method. static void EndEvent(int32 index); - /// - /// Begins the new frame rendering. Called by the engine to sync profiling data. - /// - static void BeginFrame(); - - /// - /// Called when just before flushing current frame GPU commands (via Present or Flush). Call active timer queries should be ended now. - /// - static void OnPresent(); - - /// - /// Ends the frame rendering. Called by the engine to sync profiling data. - /// - static void EndFrame(); - /// /// Tries to get the rendering stats from the last frame drawing (that has been resolved and has valid data). /// /// The draw execution time on a GPU (in milliseconds). + /// The final frame present time on a CPU (in milliseconds). Time game waited for vsync or GPU to finish previous frame rendering. /// The rendering stats data. /// True if got the data, otherwise false. - static bool GetLastFrameData(float& drawTimeMs, RenderStatsData& statsData); + API_FUNCTION() static bool GetLastFrameData(float& drawTimeMs, float& presentTimeMs, RenderStatsData& statsData); - /// - /// Releases resources. Calls to the profiling API after Dispose are not valid - /// +private: + static void BeginFrame(); + static void OnPresent(); + static void OnPresentTime(float time); + static void EndFrame(); static void Dispose(); }; diff --git a/Source/Engine/Profiler/ProfilingTools.cpp b/Source/Engine/Profiler/ProfilingTools.cpp index 61c0e2c33..113a04ec8 100644 --- a/Source/Engine/Profiler/ProfilingTools.cpp +++ b/Source/Engine/Profiler/ProfilingTools.cpp @@ -48,7 +48,9 @@ void ProfilingToolsService::Update() stats.PhysicsTimeMs = static_cast(Time::Physics.LastLength * 1000.0); stats.DrawCPUTimeMs = static_cast(Time::Draw.LastLength * 1000.0); - ProfilerGPU::GetLastFrameData(stats.DrawGPUTimeMs, stats.DrawStats); + float presentTime; + ProfilerGPU::GetLastFrameData(stats.DrawGPUTimeMs, presentTime, stats.DrawStats); + stats.DrawCPUTimeMs = Math::Max(stats.DrawCPUTimeMs - presentTime, 0.0f); // Remove swapchain present wait time to exclude from drawing on CPU } // Extract CPU profiler events