Add excluding GPU swapchain present time from CPU draw time in profiling tool

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;

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;
 }

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:
     /// <summary>
     /// Represents single CPU profiling event data.
@@ -69,6 +71,11 @@ public:
         /// </summary>
         uint64 FrameIndex;
 
+        /// <summary>
+        /// Sum of all present events duration on CPU during this frame (in milliseconds).
+        /// </summary>
+        float PresentTime;
+
         /// <summary>
         /// Determines whether this buffer has ready data (resolved and not empty).
         /// </summary>
@@ -151,32 +158,20 @@ public:
     /// <param name="index">The event token index returned by the BeginEvent method.</param>
     static void EndEvent(int32 index);
 
-    /// <summary>
-    /// Begins the new frame rendering. Called by the engine to sync profiling data.
-    /// </summary>
-    static void BeginFrame();
-
-    /// <summary>
-    /// Called when just before flushing current frame GPU commands (via Present or Flush). Call active timer queries should be ended now.
-    /// </summary>
-    static void OnPresent();
-
-    /// <summary>
-    /// Ends the frame rendering. Called by the engine to sync profiling data.
-    /// </summary>
-    static void EndFrame();
-
     /// <summary>
     /// Tries to get the rendering stats from the last frame drawing (that has been resolved and has valid data).
     /// </summary>
     /// <param name="drawTimeMs">The draw execution time on a GPU (in milliseconds).</param>
+    /// <param name="presentTimeMs">The final frame present time on a CPU (in milliseconds). Time game waited for vsync or GPU to finish previous frame rendering.</param>
     /// <param name="statsData">The rendering stats data.</param>
     /// <returns>True if got the data, otherwise false.</returns>
-    static bool GetLastFrameData(float& drawTimeMs, RenderStatsData& statsData);
+    API_FUNCTION() static bool GetLastFrameData(float& drawTimeMs, float& presentTimeMs, RenderStatsData& statsData);
 
-    /// <summary>
+private:
-    /// Releases resources. Calls to the profiling API after Dispose are not valid
+    static void BeginFrame();
-    /// </summary>
+    static void OnPresent();
+    static void OnPresentTime(float time);
+    static void EndFrame();
     static void Dispose();
 };
 

Source/Engine/Profiler/ProfilingTools.cpp

@@ -48,7 +48,9 @@ void ProfilingToolsService::Update()
         stats.PhysicsTimeMs = static_cast<float>(Time::Physics.LastLength * 1000.0);
         stats.DrawCPUTimeMs = static_cast<float>(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