Improve perf logging #2

Improve startup perf logging, including:
- Move outputting startup perf logs into better place. Previously
  only part of the logs were printed as output happened too soon,
  now printing at first frame rendering.
- Show also amount of calls and cumulative timestamps.
- Improve log labels formatting.
- Add more logging points into hot spots.

Task-number: QT3DS-4021
Change-Id: I7db5a11ff10be1ccb691f82b10161e8ba7c316a6
Reviewed-by: Antti Määttä <antti.maatta@qt.io>
Reviewed-by: Tomi Korpipää <tomi.korpipaa@qt.io>

2 files changed, 27 insertions, 10 deletions

diff --git a/src/engine/Qt3DSRenderRuntimeBinding.cpp b/src/engine/Qt3DSRenderRuntimeBinding.cpp
index fc413f6..a8107a4 100644
--- a/src/engine/Qt3DSRenderRuntimeBinding.cpp
+++ b/src/engine/Qt3DSRenderRuntimeBinding.cpp
@@ -872,6 +872,8 @@ struct Qt3DSRenderSceneManager : public Q3DStudio::ISceneManager,
                                  Q3DStudio::IScriptBridge &inBridge,
                                  const qt3ds::Q3DSVariantConfig &variantConfig) override
     {
+        QT3DS_PERF_SCOPED_TIMER(m_Context->m_CoreContext->GetPerfTimer(),
+                                "Binding: LoadScene")
         // We have to initialize the tags late so that we can load flow data before adding anything
         // to the string table.
         Qt3DSTranslator::InitializePointerTags(m_Context->m_RenderContext->GetStringTable());
@@ -1006,7 +1008,7 @@ struct Qt3DSRenderSceneManager : public Q3DStudio::ISceneManager,
                                       qt3ds::render::ILoadedBuffer &inData) override
     {
         QT3DS_PERF_SCOPED_TIMER(m_Context->m_CoreContext->GetPerfTimer(),
-                                "Load Scene Graph Stage 1")
+                                "Binding: Load Scene Graph Stage 1")
         NVDataRef<QT3DSU8> theLoadedData(inData.Data());
         SDataReader theReader(theLoadedData.begin(), theLoadedData.end());
 
@@ -1064,7 +1066,7 @@ struct Qt3DSRenderSceneManager : public Q3DStudio::ISceneManager,
                                  size_t inElementMemoryOffset, Q3DStudio::IScriptBridge &inBridge) override
     {
         QT3DS_PERF_SCOPED_TIMER(m_Context->m_CoreContext->GetPerfTimer(),
-                                "Load Scene Graph Stage 2")
+                                "Binding: Load Scene Graph Stage 2")
         QT3DSU32 theSceneIndex = QT3DS_MAX_U32;
         SSceneLoadData *theScene;
         {
@@ -1134,7 +1136,7 @@ struct Qt3DSRenderSceneManager : public Q3DStudio::ISceneManager,
 
         {
             QT3DS_PERF_SCOPED_TIMER(m_Context->m_CoreContext->GetPerfTimer(),
-                                    "Initial Batch Image Load")
+                                    "Binding: Initial Batch Image Load")
 
             m_Context->m_Context->GetImageBatchLoader().LoadImageBatch(
                 toConstDataRef(imagePathList.data(), imagePathList.size()),
@@ -1149,7 +1151,7 @@ struct Qt3DSRenderSceneManager : public Q3DStudio::ISceneManager,
         {
 
             QT3DS_PERF_SCOPED_TIMER(m_Context->m_CoreContext->GetPerfTimer(),
-                                    "Initialize Scenes")
+                                    "Binding: Initialize Scenes")
             for (QT3DSU32 idx = 0, end = m_LoadingScenes.size(); idx < end; ++idx) {
                 SSceneLoadData &theScene = *m_LoadingScenes[idx];
                 // m_Context->m_Foundation->error( QT3DS_WARN, "Finalizing scene %d", (int)idx+1 );
@@ -1523,7 +1525,11 @@ struct Qt3DSRenderSceneManager : public Q3DStudio::ISceneManager,
         }
 
         m_Context->m_Context->BeginFrame(firstFrame);
-        m_Context->m_RenderContext->ResetBlendState();
+        {
+                QT3DS_PERF_SCOPED_TIMER(m_Context->m_CoreContext->GetPerfTimer(),
+                                        "RenderContext: ResetBlendState")
+                m_Context->m_RenderContext->ResetBlendState();
+        }
 
         // How exactly does this work, I have no idea.
         // Should we only render the first scene and not every scene, perhaps?
@@ -1781,9 +1787,11 @@ struct SRenderFactory : public IQt3DSRenderFactoryCore, public IQt3DSRenderFacto
     IQt3DSRenderFactory &CreateRenderFactory(const QSurfaceFormat& format,
                                              bool delayedLoading) override
     {
-
-        SContextTypeRenderFactory theContextFactory(format);
-        m_Context->CreateRenderContext(theContextFactory, delayedLoading);
+        {
+            QT3DS_PERF_SCOPED_TIMER(GetPerfTimer(), "Context: CreateRenderContext")
+            SContextTypeRenderFactory theContextFactory(format);
+            m_Context->CreateRenderContext(theContextFactory, delayedLoading);
+        }
 
         GetSceneLoader();
         {
diff --git a/src/engine/Qt3DSRuntimeView.cpp b/src/engine/Qt3DSRuntimeView.cpp
index 0a8fd54..bc48866 100644
--- a/src/engine/Qt3DSRuntimeView.cpp
+++ b/src/engine/Qt3DSRuntimeView.cpp
@@ -52,6 +52,7 @@
 #include "Qt3DSDLLManager.h"
 #include "foundation/Qt3DSSimpleTypes.h"
 #include "foundation/TrackingAllocator.h"
+#include "foundation/Qt3DSPerfTimer.h"
 // For perf log timestamp
 #include <time.h>
 #include "Qt3DSArray.h"
@@ -397,8 +398,16 @@ void CRuntimeView::Render()
     m_Application->UpdateAndRender();
 
     if (m_startupTime < 0 && m_startupTimer && m_startupTimer->isValid()) {
-        m_startupTime = m_startupTimer->elapsed();
-        m_startupTimer->invalidate();
+        {
+            QT3DS_PERF_SCOPED_TIMER(m_Application.mPtr->GetRuntimeFactoryCore()
+                                    .GetPerfTimer(), "RuntimeView: Stopping startup timer")
+            m_startupTime = m_startupTimer->elapsed();
+            m_startupTimer->invalidate();
+        }
+
+        // Output startup perf logging data
+        m_Application->OutputPerfLoggingData();
+
         qCDebug(PERF_INFO, "RuntimeView: First frame at - %dms", m_startupTime);
     }