Minor perf logging tweak

Show more clearly total runtime & application startup times.
When QT3DS_ENABLE_PERF_LOGGING isn't defined, only these total
times are shown.

Task-number: QT3DS-4028
Change-Id: I1d9fe8bab5ed32584b2ad1c09b14cb01d25dc82f
Reviewed-by: Tomi Korpipää <tomi.korpipaa@qt.io>
Reviewed-by: Miikka Heikkinen <miikka.heikkinen@qt.io>

4 files changed, 24 insertions, 11 deletions

diff --git a/src/api/studio3d/doc/src/building-opengl-runtime.qdoc b/src/api/studio3d/doc/src/building-opengl-runtime.qdoc
index 60462bc..f33715c 100644
--- a/src/api/studio3d/doc/src/building-opengl-runtime.qdoc
+++ b/src/api/studio3d/doc/src/building-opengl-runtime.qdoc
@@ -52,8 +52,10 @@ qt3ds.perf_info: 6. (1) Application: EndLoad - 0.000500ms = 193.574900ms
 qt3ds.perf_info: 7. (1) Application: GetMetaData - 59.171400ms = 252.875800ms
 qt3ds.perf_info: 8. (3) BatchLoader: Image Decompression - 15.395400ms = 294.876900ms
 ...
-qt3ds.perf_info: 37. (1) RuntimeView: Stopping startup timer - 0.000500ms = 477.483800ms
-qt3ds.perf_info: RuntimeView: First frame at - 1601ms
+qt3ds.perf_info: 36. (1) Application: NotifyDataOutputs - 0.080800ms = 477.483800ms
+qt3ds.perf_info: *** First frame rendered ***
+qt3ds.perf_info: Runtime startup time: 477ms
+qt3ds.perf_info: Application startup time: 1601ms
 qt3ds.perf_info: Render Statistics: 33.62fps, frame count 34
 qt3ds.perf_info: Render Statistics: 59.92fps, frame count 60
 qt3ds.perf_info: Render Statistics: 59.92fps, frame count 60
@@ -69,7 +71,7 @@ Log format is: \c {(n) [task name] - [time] = [cumulative time]} where:
 \endlist
 
 \note When analyzing the results, please note that tasks overlap with each other, some tasks include other tasks etc.
-Also, cumulative time only contains time spent inside runtime methods where \c {"First frame at"} contains the whole startup time.
+\c {Runtime startup time} contains the time spent inside runtime methods where \c {Application startup time} contains the whole startup time.
 
 \note \c QT3DS_ENABLE_PERF_LOGGING should not be enabled in release builds as logging increases performance overhead.
 
diff --git a/src/engine/Qt3DSRuntimeView.cpp b/src/engine/Qt3DSRuntimeView.cpp
index bc48866..ee2a665 100644
--- a/src/engine/Qt3DSRuntimeView.cpp
+++ b/src/engine/Qt3DSRuntimeView.cpp
@@ -398,17 +398,18 @@ void CRuntimeView::Render()
     m_Application->UpdateAndRender();
 
     if (m_startupTime < 0 && m_startupTimer && m_startupTimer->isValid()) {
-        {
-            QT3DS_PERF_SCOPED_TIMER(m_Application.mPtr->GetRuntimeFactoryCore()
-                                    .GetPerfTimer(), "RuntimeView: Stopping startup timer")
-            m_startupTime = m_startupTimer->elapsed();
-            m_startupTimer->invalidate();
-        }
 
+        m_startupTime = m_startupTimer->elapsed();
+        m_startupTimer->invalidate();
+        double currentTime = m_Application.mPtr->GetRuntimeFactoryCore().GetPerfTimer().CurrentDuration();
+
+#ifdef QT3DS_ENABLE_PERF_LOGGING
         // Output startup perf logging data
         m_Application->OutputPerfLoggingData();
-
-        qCDebug(PERF_INFO, "RuntimeView: First frame at - %dms", m_startupTime);
+#endif
+        qCDebug(PERF_INFO, "*** First frame rendered ***");
+        qCDebug(PERF_INFO, "Runtime startup time: %.0fms", currentTime);
+        qCDebug(PERF_INFO, "Application startup time: %dms", m_startupTime);
     }
 
     if (m_showOnScreenStats) {
diff --git a/src/foundation/Qt3DSPerfTimer.cpp b/src/foundation/Qt3DSPerfTimer.cpp
index 9b213ba..ea8de71 100644
--- a/src/foundation/Qt3DSPerfTimer.cpp
+++ b/src/foundation/Qt3DSPerfTimer.cpp
@@ -163,6 +163,14 @@ struct SPerfTimer : public IPerfTimer
         }
     }
 
+    double CurrentDuration() override
+    {
+        QT3DSU64 duration = Time::getCurrentCounterValue() - m_startTime;
+        QT3DSU64 tensNanos = Time::sCounterFreq.toTensOfNanos(duration);
+        double durationMs = tensNanos / 100000.0;
+        return durationMs;
+    }
+
     virtual void ClearPerfKeys()
     {
         Mutex::ScopedLock __locker(m_Mutex);
diff --git a/src/foundation/Qt3DSPerfTimer.h b/src/foundation/Qt3DSPerfTimer.h
index 399d6f5..122e176 100644
--- a/src/foundation/Qt3DSPerfTimer.h
+++ b/src/foundation/Qt3DSPerfTimer.h
@@ -50,6 +50,8 @@ namespace foundation {
         // Dump current summation of timer data.
         virtual void OutputTimerData(QT3DSU32 inFrameCount = 0) = 0;
         virtual void ResetTimerData() = 0;
+        // Returns current duration in ms
+        virtual double CurrentDuration() = 0;
 
         static IPerfTimer &CreatePerfTimer(NVFoundationBase &inFoundation);
     };