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>

12 files changed, 143 insertions, 87 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);
     }
 
diff --git a/src/foundation/Qt3DSPerfTimer.cpp b/src/foundation/Qt3DSPerfTimer.cpp
index 923e36e..9b213ba 100644
--- a/src/foundation/Qt3DSPerfTimer.cpp
+++ b/src/foundation/Qt3DSPerfTimer.cpp
@@ -44,6 +44,7 @@ struct STimerEntry
 {
     QT3DSU64 m_Total;
     QT3DSU64 m_Max;
+    QT3DSU64 m_CumulativeTime;
     QT3DSU32 m_UpdateCount;
     CRegisteredString m_Tag;
     size_t m_Order;
@@ -51,29 +52,35 @@ struct STimerEntry
     STimerEntry(CRegisteredString tag, size_t order)
         : m_Total(0)
         , m_Max(0)
+        , m_CumulativeTime(0)
         , m_UpdateCount(0)
         , m_Tag(tag)
         , m_Order(order)
     {
     }
-    void Update(QT3DSU64 increment)
+    void Update(QT3DSU64 increment, QT3DSU64 cumulativeTime = 0)
     {
         m_Total += increment;
         m_Max = increment > m_Max ? increment : m_Max;
+        m_CumulativeTime = cumulativeTime;
         ++m_UpdateCount;
     }
 
-    void Output(QT3DSU32 inFramesPassed)
+    void Output(QT3DSU32 idx, QT3DSU32 inFramesPassed)
     {
         if (m_Total) {
             QT3DSU64 tensNanos = Time::sCounterFreq.toTensOfNanos(m_Total);
             QT3DSU64 maxNanos = Time::sCounterFreq.toTensOfNanos(m_Max);
+            QT3DSU64 cumNanos = Time::sCounterFreq.toTensOfNanos(m_CumulativeTime);
 
             double milliseconds = tensNanos / 100000.0;
             double maxMilliseconds = maxNanos / 100000.0;
-            if (inFramesPassed == 0)
-                qCWarning(WARNING, PERF_INFO, "%s - %fms", m_Tag.c_str(), milliseconds);
-            else {
+            double cumulativeMs = cumNanos / 100000.0;
+
+            if (inFramesPassed == 0) {
+                qCWarning(WARNING, PERF_INFO, "%d. (%d) %s - %fms = %fms", (idx+1),
+                          m_UpdateCount, m_Tag.c_str(), milliseconds, cumulativeMs);
+            } else {
                 milliseconds /= inFramesPassed;
                 qCWarning(WARNING, PERF_INFO, "%s - %fms/frame-total %fms-max %u hits",
                     m_Tag.c_str(), milliseconds, maxMilliseconds, m_UpdateCount);
@@ -88,7 +95,7 @@ struct STimerEntry
         m_UpdateCount = 0;
     }
 
-    bool operator<(const STimerEntry &other) const { return m_Order < other.m_Order; }
+    bool operator<(const STimerEntry &other) const { return m_CumulativeTime < other.m_CumulativeTime; }
 };
 struct SPerfTimer : public IPerfTimer
 {
@@ -101,6 +108,7 @@ struct SPerfTimer : public IPerfTimer
     eastl::vector<STimerEntry> m_PrintEntries;
     Mutex m_Mutex;
     QT3DSI32 mRefCount;
+    QT3DSU64 m_startTime;
 
     SPerfTimer(NVFoundationBase &fnd)
         : m_Foundation(fnd)
@@ -112,13 +120,20 @@ struct SPerfTimer : public IPerfTimer
 
     QT3DS_IMPLEMENT_REF_COUNT_ADDREF_RELEASE_OVERRIDE(m_Foundation.getAllocator())
 
-    void Update(const char *inId, QT3DSU64 inAmount) override
+    void StartMeasuring() override
+    {
+        Mutex::ScopedLock __locker(m_Mutex);
+        m_startTime = Time::getCurrentCounterValue();
+    }
+
+    void Update(const char *inId, QT3DSU64 inAmount, QT3DSU64 inStop) override
     {
         Mutex::ScopedLock __locker(m_Mutex);
+        QT3DSU64 cumulativeTime = inStop - m_startTime;
         CRegisteredString theStr(m_StringTable->RegisterStr(inId));
         THashMapType::iterator theFind =
             m_Entries.insert(eastl::make_pair(theStr, STimerEntry(theStr, m_Entries.size()))).first;
-        theFind->second.Update(inAmount);
+        theFind->second.Update(inAmount, cumulativeTime);
     }
 
     // Dump current summation of timer data.
@@ -135,7 +150,7 @@ struct SPerfTimer : public IPerfTimer
         eastl::sort(m_PrintEntries.begin(), m_PrintEntries.end());
 
         for (QT3DSU32 idx = 0, end = (QT3DSU32)m_PrintEntries.size(); idx < end; ++idx) {
-            m_PrintEntries[idx].Output(inFramesPassed);
+            m_PrintEntries[idx].Output(idx, inFramesPassed);
         }
     }
 
diff --git a/src/foundation/Qt3DSPerfTimer.h b/src/foundation/Qt3DSPerfTimer.h
index d539e6a..399d6f5 100644
--- a/src/foundation/Qt3DSPerfTimer.h
+++ b/src/foundation/Qt3DSPerfTimer.h
@@ -44,8 +44,9 @@ namespace foundation {
     protected:
         virtual ~IPerfTimer() {}
     public:
+        virtual void StartMeasuring() = 0;
         // amount is in counter frequency units
-        virtual void Update(const char *inTag, QT3DSU64 inAmount) = 0;
+        virtual void Update(const char *inTag, QT3DSU64 inAmount, QT3DSU64 inStop) = 0;
         // Dump current summation of timer data.
         virtual void OutputTimerData(QT3DSU32 inFrameCount = 0) = 0;
         virtual void ResetTimerData() = 0;
@@ -94,7 +95,7 @@ namespace foundation {
             if (m_Timer) {
                 QT3DSU64 theStop = Time::getCurrentCounterValue();
                 QT3DSU64 theAmount = theStop - m_Start;
-                m_Timer->Update(m_Id, theAmount);
+                m_Timer->Update(m_Id, theAmount, theStop);
             }
         }
     };
diff --git a/src/runtime/Qt3DSActivationManager.cpp b/src/runtime/Qt3DSActivationManager.cpp
index 526dd41..784f42e 100644
--- a/src/runtime/Qt3DSActivationManager.cpp
+++ b/src/runtime/Qt3DSActivationManager.cpp
@@ -660,7 +660,6 @@ struct STimeContext
                 bool &scriptBufferRequiresSort, Q3DStudio::CComponentManager &inComponentManager,
                 IPerfTimer &inPerfTimer, IActivityZone &inZone)
     {
-        QT3DSU64 start = qt3ds::foundation::Time::getCurrentCounterValue();
         SComponent &theContextNode = m_Component;
         bool parentActive = true;
         SElement *theParent = theContextNode.m_Parent;
@@ -675,10 +674,9 @@ struct STimeContext
         bool isActive = isControlledByDi ? theContextNode.IsControlledActive()
                                          : theContextNode.IsGlobalActive(parentActive);
         bool activationChange = isActive != wasActive;
-        inPerfTimer.Update("ActivationManager - Update Initial Vars",
-                           qt3ds::foundation::Time::getCurrentCounterValue() - start);
+
         if (activationChange) {
-            QT3DS_PERF_SCOPED_TIMER(inPerfTimer, "ActivationManager - Activation Change")
+            QT3DS_PERF_SCOPED_TIMER(inPerfTimer, "ActivationManager: Activation Change")
             HandleActivationChange(theContextNode, activateBuffer, deactivateBuffer, scriptBuffer,
                                    m_ElementAccessMutex, scriptBufferRequiresSort, isActive);
             m_DirtyList.clear();
@@ -696,7 +694,7 @@ struct STimeContext
                 RemoveOverride();
         }
         if (isActive) {
-            QT3DS_PERF_SCOPED_TIMER(inPerfTimer, "ActivationManager - Update Local Time")
+            QT3DS_PERF_SCOPED_TIMER(inPerfTimer, "ActivationManager: Update Local Time")
             bool atEndOfTime = CalculateNewTime(inGlobalTime);
             if (atEndOfTime) {
                 Mutex::ScopedLock __locker(m_ElementAccessMutex);
@@ -709,7 +707,7 @@ struct STimeContext
         }
         if (isActive || activationChange) {
             if (m_AllNodesDirty || m_DirtyList.size()) {
-                QT3DS_PERF_SCOPED_TIMER(inPerfTimer, "ActivationManager - Dirty Scan")
+                QT3DS_PERF_SCOPED_TIMER(inPerfTimer, "ActivationManager: Dirty Scan")
                 RunDirtyScan(inScanBuffer, inTempDirtyList, activateBuffer, deactivateBuffer,
                              scriptBuffer, scriptBufferRequiresSort);
             }
@@ -974,7 +972,7 @@ struct SActivityZone : public IActivityZone
 
     void DoUpdate()
     {
-        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "ActivationManager - DoUpdate")
+        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "ActivationManager: DoUpdate")
         if (m_Active) {
             // We know that parent elements are added before children.
             // So we know the time contexts are in an appropriate order, assuming they completely
diff --git a/src/runtime/Qt3DSApplication.cpp b/src/runtime/Qt3DSApplication.cpp
index 691d4e0..8d8740d 100644
--- a/src/runtime/Qt3DSApplication.cpp
+++ b/src/runtime/Qt3DSApplication.cpp
@@ -931,7 +931,7 @@ struct SApp : public IApplication
 
     void UpdatePresentations()
     {
-        QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(), "UpdatePresentations")
+        QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(), "UpdatePresentations: Total")
         // Transfer the input frame to the kernel for pick processing
         // the scene manager now handles the picking on each of its scenes
         SetPickFrame(m_RuntimeFactory->GetSceneManager().AdvancePickFrame(
@@ -948,14 +948,14 @@ struct SApp : public IApplication
 
         {
             QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(),
-                                    "UpdatePresentations - pre update")
+                                    "UpdatePresentations: PreUpdate")
             forAllPresentations(presentations, true, [globalTime](CPresentation *p) {
                 p->PreUpdate(globalTime);
             });
         }
         {
             QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(),
-                                    "UpdatePresentations - begin update")
+                                    "UpdatePresentations: BeginUpdate")
             forAllPresentations(presentations, true, [](CPresentation *p) {
                 p->BeginUpdate();
             });
@@ -963,14 +963,14 @@ struct SApp : public IApplication
         // Allow EndUpdate and PostUpdate for inactive presentations so we can activate it
         {
             QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(),
-                                    "UpdatePresentations - end update")
+                                    "UpdatePresentations: EndUpdate")
             forAllPresentations(presentations, false, [](CPresentation *p) {
                 p->EndUpdate();
             });
         }
         {
             QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(),
-                                    "UpdatePresentations - postupdate")
+                                    "UpdatePresentations: PostUpdate")
             forAllPresentations(presentations, false, [globalTime](CPresentation *p) {
                 p->PostUpdate(globalTime);
             });
@@ -984,7 +984,7 @@ struct SApp : public IApplication
     {
         {
             QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(),
-                                    "NotifyDataOutputs")
+                                    "Application: NotifyDataOutputs")
 
             // Allow presentations to notify of registered data output changes
             for (QT3DSU32 idx = 0, end = m_OrderedAssets.size(); idx < end; ++idx) {
@@ -1086,7 +1086,7 @@ struct SApp : public IApplication
 
     void Render()
     {
-        QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(), "Render")
+        QT3DS_PERF_SCOPED_TIMER(m_RuntimeFactory->GetPerfTimer(), "Application: Render")
         CPresentation *pres = GetPrimaryPresentation();
         if (pres) {
             auto &rc = m_RuntimeFactory->GetQt3DSRenderContext();
@@ -1177,8 +1177,6 @@ struct SApp : public IApplication
             }
         }
 
-        m_CoreFactory->GetPerfTimer().ResetTimerData();
-
         fflush(stdout);
         m_LastFrameStartTime = m_ThisFrameStartTime;
         if (m_LastRenderWasDirty)
@@ -1208,6 +1206,8 @@ struct SApp : public IApplication
     {
         if (m_RuntimeFactory->GetQt3DSRenderContext().GetBufferManager()
                 .isReloadableResourcesEnabled()) {
+            QT3DS_PERF_SCOPED_TIMER(m_CoreFactory->GetPerfTimer(),
+                                    "Application: Load Slide Resources")
             auto &slidesystem = presentation->GetSlideSystem();
             SSlideKey key;
             key.m_Component = component;
@@ -1300,6 +1300,7 @@ struct SApp : public IApplication
                  NVConstDataRef<SElementAttributeReference> inExternalReferences,
                  bool initInRenderThread)
     {
+        QT3DS_PERF_SCOPED_TIMER(m_CoreFactory->GetPerfTimer(), "Application: LoadUIP")
         GetMetaData();
         eastl::string theFile;
         CFileTools::CombineBaseAndRelative(GetProjectDirectory().c_str(), inAsset.m_Src.c_str(),
@@ -1575,6 +1576,7 @@ struct SApp : public IApplication
 
     bool BeginLoad(const QString &sourcePath, const QStringList &variantList) override
     {
+        m_CoreFactory->GetPerfTimer().StartMeasuring();
         QT3DS_PERF_SCOPED_TIMER(m_CoreFactory->GetPerfTimer(), "Application: Begin Load")
         eastl::string directory;
         eastl::string filename;
@@ -1848,8 +1850,6 @@ struct SApp : public IApplication
         if (!shaderCache.isEmpty())
             inFactory.GetQt3DSRenderContext().GetShaderCache().importShaderCache(shaderCache);
 
-        m_CoreFactory->GetPerfTimer().OutputTimerData();
-
         m_AudioPlayer.SetPlayer(inAudioPlayer);
 
         auto &rc = m_RuntimeFactory->GetQt3DSRenderContext();
@@ -2015,6 +2015,7 @@ struct SApp : public IApplication
 
     Q3DStudio::IRuntimeMetaData &GetMetaData() override
     {
+        QT3DS_PERF_SCOPED_TIMER(m_CoreFactory->GetPerfTimer(), "Application: GetMetaData")
         if (!m_MetaData) {
             m_MetaData = &IRuntimeMetaData::Create(m_CoreFactory->GetInputStreamFactory());
             if (!m_MetaData) {
@@ -2038,6 +2039,11 @@ struct SApp : public IApplication
     {
         return GetElementAllocator().FindElementByHandle(inHandle);
     }
+
+    void OutputPerfLoggingData() override {
+        m_CoreFactory->GetPerfTimer().OutputTimerData();
+        m_CoreFactory->GetPerfTimer().ResetTimerData();
+    }
 };
 
 struct SXMLLoader : public IAppLoadContext
@@ -2180,6 +2186,7 @@ IApplication &IApplication::CreateApplicationCore(Q3DStudio::IRuntimeFactoryCore
 
 bool AssetHandlers::handlePresentation(SApp &app, SAssetValue &asset, bool initInRenderThread)
 {
+    QT3DS_PERF_SCOPED_TIMER(app.m_CoreFactory->GetPerfTimer(), "AssetHandlers: handlePresentation")
     eastl::string thePathStr;
 
     CFileTools::CombineBaseAndRelative(app.GetProjectDirectory().c_str(),
diff --git a/src/runtime/Qt3DSApplication.h b/src/runtime/Qt3DSApplication.h
index deaafe7..72d88a1 100644
--- a/src/runtime/Qt3DSApplication.h
+++ b/src/runtime/Qt3DSApplication.h
@@ -259,6 +259,9 @@ public:
     static IApplication &CreateApplicationCore(Q3DStudio::IRuntimeFactoryCore &inFactory,
                                                const char8_t *inApplicationDirectory);
     static bool isPickingEvent(Q3DStudio::TEventCommandHash event);
+
+    // This will print out and reset the startup perf logs
+    virtual void OutputPerfLoggingData() = 0;
 };
 
 bool isImagePath(const QString &path);
diff --git a/src/runtimerender/Qt3DSRenderShaderCache.cpp b/src/runtimerender/Qt3DSRenderShaderCache.cpp
index a71d3fd..4693cb6 100644
--- a/src/runtimerender/Qt3DSRenderShaderCache.cpp
+++ b/src/runtimerender/Qt3DSRenderShaderCache.cpp
@@ -411,7 +411,7 @@ struct ShaderCache : public IShaderCache
         if (!inFrag)
             inFrag = "";
 
-        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "Shader Compilation")
+        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "ShaderCache: Compilation")
         m_VertexCode.assign(inVert);
         m_TessCtrlCode.assign(inTessCtrl);
         m_TessEvalCode.assign(inTessEval);
@@ -553,7 +553,7 @@ struct ShaderCache : public IShaderCache
         if (shaderCache.isEmpty())
             BAILOUT("Shader cache Empty")
 
-        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "ShaderCache - Import")
+        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "ShaderCache: Import")
 
         QDataStream data(shaderCache);
         quint32 type;
diff --git a/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderData.cpp b/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderData.cpp
index 95cbc9e..9c92bda 100644
--- a/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderData.cpp
+++ b/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderData.cpp
@@ -668,7 +668,7 @@ namespace render {
     void SLayerRenderData::RenderShadowMapPass(CResourceFrameBuffer *theFB)
     {
         QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
-                                "SLayerRenderData::RenderShadowMapPass")
+                                "LayerRenderData: RenderShadowMapPass")
 
         if (m_Camera == NULL || !GetShadowMapManager())
             return;
@@ -826,7 +826,7 @@ namespace render {
     void SLayerRenderData::RenderDepthPass(bool inEnableTransparentDepthWrite)
     {
         QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
-                                "SLayerRenderData::RenderDepthPass")
+                                "LayerRenderData: RenderDepthPass")
         if (m_Camera == NULL)
             return;
 
@@ -1007,54 +1007,69 @@ namespace render {
         theRenderContext.SetDepthFunction(qt3ds::render::NVRenderBoolOp::LessThanOrEqual);
         theRenderContext.SetBlendingEnabled(false);
         QT3DSVec2 theCameraProps = QT3DSVec2(m_Camera->m_ClipNear, m_Camera->m_ClipFar);
-        NVDataRef<SRenderableObject *> theOpaqueObjects = GetOpaqueRenderableObjects();
+        {
+            QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
+                                    "LayerRenderData: Render opaque")
+            NVDataRef<SRenderableObject *> theOpaqueObjects = GetOpaqueRenderableObjects();
 
-        if (m_Layer.m_Flags.IsLayerEnableDepthTest()) {
-            theRenderContext.SetDepthTestEnabled(true);
-            theRenderContext.SetDepthWriteEnabled(inEnableDepthWrite);
-        } else {
-            theRenderContext.SetDepthWriteEnabled(false);
-            theRenderContext.SetDepthTestEnabled(false);
-        }
+            if (m_Layer.m_Flags.IsLayerEnableDepthTest()) {
+                theRenderContext.SetDepthTestEnabled(true);
+                theRenderContext.SetDepthWriteEnabled(inEnableDepthWrite);
+            } else {
+                theRenderContext.SetDepthWriteEnabled(false);
+                theRenderContext.SetDepthTestEnabled(false);
+            }
 
-        for (QT3DSU32 idx = 0, end = theOpaqueObjects.size(); idx < end; ++idx) {
-            SRenderableObject &theObject(*theOpaqueObjects[idx]);
-            SScopedLightsListScope lightsScope(m_Lights, m_LightDirections, m_SourceLightDirections,
-                                               theObject.m_ScopedLights);
-            SetShaderFeature(m_CGLightingFeatureName, m_Lights.empty() == false);
-            inRenderFn(*this, theObject, theCameraProps, GetShaderFeatureSet(), indexLight,
-                       inCamera);
+            for (QT3DSU32 idx = 0, end = theOpaqueObjects.size(); idx < end; ++idx) {
+                SRenderableObject &theObject(*theOpaqueObjects[idx]);
+                SScopedLightsListScope lightsScope(m_Lights, m_LightDirections, m_SourceLightDirections,
+                                                   theObject.m_ScopedLights);
+                SetShaderFeature(m_CGLightingFeatureName, m_Lights.empty() == false);
+                inRenderFn(*this, theObject, theCameraProps, GetShaderFeatureSet(), indexLight,
+                           inCamera);
+            }
         }
-
-        NVDataRef<SRenderableObject *> theTransparentObjects = GetTransparentRenderableObjects();
-        // Also draw opaque parts of transparent objects
-        m_Renderer.setAlphaTest(true, 1.0f, -1.0f + (1.0f / 255.0f));
-        for (QT3DSU32 idx = 0, end = theTransparentObjects.size(); idx < end; ++idx) {
-            SRenderableObject &theObject(*theTransparentObjects[idx]);
-            SScopedLightsListScope lightsScope(m_Lights, m_LightDirections, m_SourceLightDirections,
-                                               theObject.m_ScopedLights);
-            SetShaderFeature(m_CGLightingFeatureName, m_Lights.empty() == false);
-            inRenderFn(*this, theObject, theCameraProps, GetShaderFeatureSet(), indexLight,
-                       inCamera);
+        {
+            QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
+                                    "LayerRenderData: Render transparent pass1")
+
+            NVDataRef<SRenderableObject *> theTransparentObjects = GetTransparentRenderableObjects();
+            // Also draw opaque parts of transparent objects
+            m_Renderer.setAlphaTest(true, 1.0f, -1.0f + (1.0f / 255.0f));
+            for (QT3DSU32 idx = 0, end = theTransparentObjects.size(); idx < end; ++idx) {
+                SRenderableObject &theObject(*theTransparentObjects[idx]);
+                SScopedLightsListScope lightsScope(m_Lights, m_LightDirections, m_SourceLightDirections,
+                                                   theObject.m_ScopedLights);
+                SetShaderFeature(m_CGLightingFeatureName, m_Lights.empty() == false);
+                inRenderFn(*this, theObject, theCameraProps, GetShaderFeatureSet(), indexLight,
+                           inCamera);
+            }
         }
 
-        m_Renderer.setAlphaTest(true, -1.0f, 1.0f);
-        // transparent parts of transparent objects
-        // does not render objects without alpha test enabled so
-        // we need another pass without alpha test
-        renderTransparentObjectsPass(inRenderFn, inEnableBlending, inEnableTransparentDepthWrite,
-                                     indexLight, inCamera, theFB);
-
-        m_Renderer.setAlphaTest(false, 1.0, 1.0);
-        // transparent objects without alpha test
-        renderTransparentObjectsPass(inRenderFn, inEnableBlending, inEnableTransparentDepthWrite,
-                                     indexLight, inCamera, theFB);
+        {
+            QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
+                                    "LayerRenderData: Render transparent pass2")
+            m_Renderer.setAlphaTest(true, -1.0f, 1.0f);
+            // transparent parts of transparent objects
+            // does not render objects without alpha test enabled so
+            // we need another pass without alpha test
+            renderTransparentObjectsPass(inRenderFn, inEnableBlending, inEnableTransparentDepthWrite,
+                                         indexLight, inCamera, theFB);
+        }
+        {
+            QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
+                                    "LayerRenderData: Render transparent pass3")
+            m_Renderer.setAlphaTest(false, 1.0, 1.0);
+            // transparent objects without alpha test
+            renderTransparentObjectsPass(inRenderFn, inEnableBlending, inEnableTransparentDepthWrite,
+                                         indexLight, inCamera, theFB);
+        }
     }
 
     void SLayerRenderData::Render(CResourceFrameBuffer *theFB)
     {
         QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
-                                "SLayerRenderData::Render")
+                                "LayerRenderData: Render")
         if (m_Camera == NULL)
             return;
 
@@ -2214,7 +2229,7 @@ namespace render {
     void SLayerRenderData::AddLayerRenderStep()
     {
         QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
-                                "SLayerRenderData::AddLayerRenderStep")
+                                "LayerRenderData: AddLayerRenderStep")
         QT3DS_ASSERT(m_Camera);
         if (!m_Camera)
             return;
diff --git a/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderPreparationData.cpp b/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderPreparationData.cpp
index df60f64..eb768d3 100644
--- a/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderPreparationData.cpp
+++ b/src/runtimerender/rendererimpl/Qt3DSRendererImplLayerRenderPreparationData.cpp
@@ -1055,7 +1055,7 @@ namespace render {
             QT3DSF32 inTextScaleFactor, SLayerRenderPreparationResultFlags &ioFlags)
     {
         QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
-                                "SLayerRenderData::PrepareRenderablesForRender")
+                                "LayerRenderData: PrepareRenderablesForRender")
         m_ViewProjection = inViewProjection;
         QT3DSF32 theTextScaleFactor = inTextScaleFactor;
         bool wasDataDirty = false;
@@ -1164,7 +1164,7 @@ namespace render {
     void SLayerRenderPreparationData::PrepareForRender(const QSize &inViewportDimensions)
     {
         QT3DS_PERF_SCOPED_TIMER(m_Renderer.GetQt3DSContext().GetPerfTimer(),
-                                "SLayerRenderData::PrepareForRender")
+                                "LayerRenderData: PrepareForRender")
         if (m_LayerPrepResult.hasValue())
             return;
 
diff --git a/src/runtimerender/resourcemanager/Qt3DSRenderBufferManager.cpp b/src/runtimerender/resourcemanager/Qt3DSRenderBufferManager.cpp
index 5c47a38..b07f16b 100644
--- a/src/runtimerender/resourcemanager/Qt3DSRenderBufferManager.cpp
+++ b/src/runtimerender/resourcemanager/Qt3DSRenderBufferManager.cpp
@@ -377,7 +377,7 @@ struct SBufferManager : public IBufferManager
     void doImageLoad(CRegisteredString inImagePath,
                      NVScopedReleasable<SLoadedTexture> &theLoadedImage)
     {
-        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "Image Decompression")
+        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "BufferManager: Image Decompression")
         theLoadedImage = SLoadedTexture::Load(
                     inImagePath.c_str(), m_Context->GetFoundation(), *m_InputStreamFactory,
                     true, m_Context->GetRenderContextType(), false, this);
@@ -435,7 +435,7 @@ struct SBufferManager : public IBufferManager
                                       SLoadedTexture &inLoadedImage,
                                       bool inForceScanForTransparency, bool inBsdfMipmaps) override
     {
-        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "Image Upload")
+        QT3DS_PERF_SCOPED_TIMER(m_PerfTimer, "BufferManager: Image Upload")
         {
             Mutex::ScopedLock __mapLocker(m_LoadedImageSetMutex);
             m_LoadedImageSet.insert(inImagePath);
diff --git a/src/runtimerender/resourcemanager/Qt3DSRenderImageBatchLoader.cpp b/src/runtimerender/resourcemanager/Qt3DSRenderImageBatchLoader.cpp
index 37f965b..8c3f929 100644
--- a/src/runtimerender/resourcemanager/Qt3DSRenderImageBatchLoader.cpp
+++ b/src/runtimerender/resourcemanager/Qt3DSRenderImageBatchLoader.cpp
@@ -382,7 +382,7 @@ void SLoadingImage::Setup(SImageLoaderBatch &inBatch)
 void SLoadingImage::LoadImage(void *inImg)
 {
     SLoadingImage *theThis = reinterpret_cast<SLoadingImage *>(inImg);
-    QT3DS_PERF_SCOPED_TIMER(theThis->m_Batch->m_Loader.m_PerfTimer, "Image Decompression")
+    QT3DS_PERF_SCOPED_TIMER(theThis->m_Batch->m_Loader.m_PerfTimer, "BatchLoader: Image Decompression")
     if (theThis->m_Batch->m_Loader.m_BufferManager.IsImageLoaded(theThis->m_SourcePath) == false) {
         SLoadedTexture *theTexture = SLoadedTexture::Load(
             theThis->m_SourcePath.c_str(), theThis->m_Batch->m_Loader.m_Foundation,