measure timing

Author: mbaetgen-wup

src/libprojectM/ProjectM.cpp

@@ -102,7 +102,13 @@ void ProjectM::LoadPresetFile(const std::string& presetFilename, bool smoothTran
     }
 
     // Asynchronous path — offload file I/O to the background thread.
-    m_textureManager->PurgeTextures();
+    {
+        auto tPurge = std::chrono::steady_clock::now();
+        m_textureManager->PurgeTextures();
+        auto usPurge = std::chrono::duration_cast<std::chrono::microseconds>(
+            std::chrono::steady_clock::now() - tPurge).count();
+        LOG_INFO("[PresetSwitch] PurgeTextures=" + std::to_string(usPurge / 1000.0f) + "ms");
+    }
 
     auto ctx = std::make_shared<PresetSwitchContext>();
     ctx->path = presetFilename;
@@ -170,12 +176,16 @@ void ProjectM::RenderFrame(uint32_t targetFramebufferObject /*= 0*/)
         return;
     }
 
+    auto tFrameStart = std::chrono::steady_clock::now();
+
     // Drive the asynchronous preset switch state machine.
     if (m_activeSwitch)
     {
         ProcessPresetSwitch();
     }
 
+    auto tAfterSwitch = std::chrono::steady_clock::now();
+
     // Update FPS and other timer values.
     m_timeKeeper->UpdateTimers();
 
@@ -230,9 +240,14 @@ void ProjectM::RenderFrame(uint32_t targetFramebufferObject /*= 0*/)
     {
         if (m_transition->IsDone(m_timeKeeper->GetFrameTime()))
         {
+            auto tTransEnd = std::chrono::steady_clock::now();
             m_activePreset = std::move(m_transitioningPreset);
             m_transitioningPreset.reset();
             m_transition.reset();
+            auto usTransEnd = std::chrono::duration_cast<std::chrono::microseconds>(
+                std::chrono::steady_clock::now() - tTransEnd).count();
+            LOG_INFO("[PresetSwitch] TransitionEnd=" + std::to_string(usTransEnd / 1000.0f)
+                + "ms (old preset destroyed)");
         }
         else
         {
@@ -270,6 +285,35 @@ void ProjectM::RenderFrame(uint32_t targetFramebufferObject /*= 0*/)
 
     m_frameCount++;
     m_previousFrameVolume = audioData.vol;
+
+    // Frame-time spike detection.  Log the first few frames after a
+    // preset switch and any frame that exceeds a threshold.
+    if (m_framesAfterSwitch >= 0)
+    {
+        m_framesAfterSwitch++;
+    }
+
+    auto usFrame = std::chrono::duration_cast<std::chrono::microseconds>(
+        std::chrono::steady_clock::now() - tFrameStart).count();
+    auto usSwitch = std::chrono::duration_cast<std::chrono::microseconds>(
+        tAfterSwitch - tFrameStart).count();
+    float msFrame = usFrame / 1000.0f;
+    float msSwitch = usSwitch / 1000.0f;
+    float msRender = (usFrame - usSwitch) / 1000.0f;
+
+    if (m_framesAfterSwitch >= 0 && m_framesAfterSwitch <= 5)
+    {
+        LOG_INFO("[FrameTime] after_switch=" + std::to_string(m_framesAfterSwitch)
+            + " total=" + std::to_string(msFrame)
+            + "ms switch=" + std::to_string(msSwitch)
+            + "ms render=" + std::to_string(msRender) + "ms");
+    }
+    else if (msFrame > 5.0f)
+    {
+        LOG_INFO("[FrameTime] SPIKE total=" + std::to_string(msFrame)
+            + "ms switch=" + std::to_string(msSwitch)
+            + "ms render=" + std::to_string(msRender) + "ms");
+    }
 }
 
 void ProjectM::Initialize()
@@ -365,7 +409,11 @@ void ProjectM::StartPresetTransition(std::unique_ptr<Preset>&& preset, bool hard
 
     if (m_activePreset && !m_presetStartClean)
     {
+        auto tDraw = std::chrono::steady_clock::now();
         preset->DrawInitialImage(m_activePreset->OutputTexture(), GetRenderContext());
+        auto usDraw = std::chrono::duration_cast<std::chrono::microseconds>(
+            std::chrono::steady_clock::now() - tDraw).count();
+        LOG_INFO("[PresetSwitch] DrawInitialImage=" + std::to_string(usDraw / 1000.0f) + "ms");
     }
 
     if (hardCut)
@@ -377,7 +425,11 @@ void ProjectM::StartPresetTransition(std::unique_ptr<Preset>&& preset, bool hard
     {
         m_transitioningPreset = std::move(preset);
         m_timeKeeper->StartSmoothing();
+        auto tTransition = std::chrono::steady_clock::now();
         m_transition = std::make_unique<Renderer::PresetTransition>(m_transitionShaderManager->RandomTransition(), m_softCutDuration, m_timeKeeper->GetFrameTime());
+        auto usTransition = std::chrono::duration_cast<std::chrono::microseconds>(
+            std::chrono::steady_clock::now() - tTransition).count();
+        LOG_INFO("[PresetSwitch] TransitionSetup=" + std::to_string(usTransition / 1000.0f) + "ms");
     }
 }
 
@@ -859,7 +911,13 @@ void ProjectM::FinalizePresetActivation(std::shared_ptr<PresetSwitchContext>& ct
     }
 
     // Hand the fully-initialized preset to the transition logic.
+    auto tActivate = std::chrono::steady_clock::now();
     StartPresetTransition(std::move(ctx->preset), !ctx->smoothTransition);
+    auto usActivate = std::chrono::duration_cast<std::chrono::microseconds>(
+        std::chrono::steady_clock::now() - tActivate).count();
+    LOG_INFO("[PresetSwitch] Activate=" + std::to_string(usActivate / 1000.0f) + "ms");
+
+    m_framesAfterSwitch = 0;
 
     ctx->state.store(PresetSwitchState::Completed, std::memory_order_release);
 }

src/libprojectM/ProjectM.hpp

@@ -352,6 +352,7 @@ class PROJECTM_CXX_EXPORT ProjectM
 
     /** Timing information */
     int m_frameCount{0}; //!< Rendered frame count since start
+    int m_framesAfterSwitch{-1}; //!< Counts frames after preset activation, -1 when not tracking.
 
     bool m_presetLocked{false};         //!< If true, the preset change event will not be sent.
     bool m_presetChangeNotified{false}; //!< Stores whether the user has been notified that projectM wants to switch the preset.