Output the thread and window in the render loop timing prints

Also fixes a plain bug in the basic render loop: using static to measure
elapsed time is broken in a multi-window setup.

Change-Id: Ie81fd9f4ec274f8ef095a8be7f280173f143de04
Reviewed-by: Andy Nichols <andy.nichols@qt.io>

3 files changed, 55 insertions, 24 deletions

diff --git a/src/quick/scenegraph/qsgrenderloop.cpp b/src/quick/scenegraph/qsgrenderloop.cpp
index f5234bbf5e..80f022ddb4 100644
--- a/src/quick/scenegraph/qsgrenderloop.cpp
+++ b/src/quick/scenegraph/qsgrenderloop.cpp
@@ -43,7 +43,7 @@
 #include <private/qquickanimatorcontroller_p.h>
 
 #include <QtCore/QCoreApplication>
-#include <QtCore/QTime>
+#include <QtCore/QElapsedTimer>
 #include <QtCore/QLibraryInfo>
 #include <QtCore/private/qabstractanimation_p.h>
 
@@ -177,6 +177,7 @@ public:
               rhiDeviceLost(false),
               rhiDoomed(false)
         { }
+        QElapsedTimer timeBetweenRenders;
         bool updatePending : 1;
         bool grabOnly : 1;
         bool rhiDeviceLost : 1;
@@ -329,6 +330,7 @@ QSGGuiThreadRenderLoop::~QSGGuiThreadRenderLoop()
 void QSGGuiThreadRenderLoop::show(QQuickWindow *window)
 {
     m_windows[window] = WindowData();
+    m_windows[window].timeBetweenRenders.start();
 
     maybeUpdate(window);
 }
@@ -586,7 +588,7 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window)
     Q_TRACE_SCOPE(QSG_renderWindow);
     QElapsedTimer renderTimer;
     qint64 renderTime = 0, syncTime = 0, polishTime = 0;
-    bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled();
+    const bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled();
     if (profileFrames)
         renderTimer.start();
     Q_TRACE(QSG_polishItems_entry);
@@ -709,17 +711,16 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window)
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphRenderLoopFrame,
                            QQuickProfiler::SceneGraphRenderLoopSwap);
 
-    if (QSG_LOG_TIME_RENDERLOOP().isDebugEnabled()) {
-        static QTime lastFrameTime = QTime::currentTime();
+    if (profileFrames) {
         qCDebug(QSG_LOG_TIME_RENDERLOOP,
-                "Frame rendered with 'basic' renderloop in %dms, polish=%d, sync=%d, render=%d, swap=%d, frameDelta=%d",
+                "[window %p][gui thread] syncAndRender: frame rendered in %dms, polish=%d, sync=%d, render=%d, swap=%d, perWindowFrameDelta=%d",
+                window,
                 int(swapTime / 1000000),
                 int(polishTime / 1000000),
                 int((syncTime - polishTime) / 1000000),
                 int((renderTime - syncTime) / 1000000),
                 int((swapTime - renderTime) / 1000000),
-                int(lastFrameTime.msecsTo(QTime::currentTime())));
-        lastFrameTime = QTime::currentTime();
+                int(data.timeBetweenRenders.restart()));
     }
 
     QSGRhiProfileConnection::instance()->send(rhi);
diff --git a/src/quick/scenegraph/qsgthreadedrenderloop.cpp b/src/quick/scenegraph/qsgthreadedrenderloop.cpp
index 83095dad7c..a4bd6ba7ef 100644
--- a/src/quick/scenegraph/qsgthreadedrenderloop.cpp
+++ b/src/quick/scenegraph/qsgthreadedrenderloop.cpp
@@ -352,7 +352,7 @@ public:
     QMutex mutex;
     QWaitCondition waitCondition;
 
-    QElapsedTimer m_timer;
+    QElapsedTimer m_threadTimeBetweenRenders;
 
     QQuickWindow *window; // Will be 0 when window is not exposed
     QSize windowSize;
@@ -635,7 +635,7 @@ void QSGRenderThread::handleDeviceLoss()
 
 void QSGRenderThread::syncAndRender(QImage *grabImage)
 {
-    bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled();
+    const bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled();
     QElapsedTimer threadTimer;
     qint64 syncTime = 0, renderTime = 0;
     if (profileFrames)
@@ -649,6 +649,14 @@ void QSGRenderThread::syncAndRender(QImage *grabImage)
 
     qCDebug(QSG_LOG_RENDERLOOP, QSG_RT_PAD, "syncAndRender()");
 
+    if (profileFrames) {
+        const qint64 elapsedSinceLastMs = m_threadTimeBetweenRenders.restart();
+        qCDebug(QSG_LOG_TIME_RENDERLOOP, "[window %p][render thread %p] syncAndRender: start, elapsed since last call: %d ms",
+                window,
+                QThread::currentThread(),
+                int(elapsedSinceLastMs));
+    }
+
     syncResultedInChanges = false;
     QQuickWindowPrivate *d = QQuickWindowPrivate::get(window);
 
@@ -831,12 +839,23 @@ void QSGRenderThread::syncAndRender(QImage *grabImage)
         mutex.unlock();
     }
 
-    qCDebug(QSG_LOG_TIME_RENDERLOOP,
-            "Frame rendered with 'threaded' renderloop in %dms, sync=%d, render=%d, swap=%d - (on render thread)",
-            int(threadTimer.elapsed()),
-            int((syncTime/1000000)),
-            int((renderTime - syncTime) / 1000000),
-            int((threadTimer.nsecsElapsed() - renderTime) / 1000000));
+    if (profileFrames) {
+        // Beware that there is no guarantee the graphics stack always
+        // blocks for a full vsync in beginFrame() or endFrame(). (because
+        // e.g. there is no guarantee that OpenGL blocks in swapBuffers(),
+        // it may block elsewhere; also strategies may change once there
+        // are multiple windows) So process the results printed here with
+        // caution and pay attention to the elapsed-since-last-call time
+        // printed at the beginning of the function too.
+        qCDebug(QSG_LOG_TIME_RENDERLOOP,
+                "[window %p][render thread %p] syncAndRender: frame rendered in %dms, sync=%d, render=%d, swap=%d",
+                window,
+                QThread::currentThread(),
+                int(threadTimer.elapsed()),
+                int((syncTime/1000000)),
+                int((renderTime - syncTime) / 1000000),
+                int((threadTimer.nsecsElapsed() - renderTime) / 1000000));
+    }
 
     Q_TRACE(QSG_swap_exit);
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphRenderLoopFrame,
@@ -945,6 +964,8 @@ void QSGRenderThread::run()
     if (QQmlDebugConnector::service<QQmlProfilerService>())
         QQuickProfiler::registerAnimationCallback();
 
+    m_threadTimeBetweenRenders.start();
+
     while (active) {
 #ifdef Q_OS_DARWIN
         QMacAutoReleasePool frameReleasePool;
@@ -1246,6 +1267,7 @@ void QSGThreadedRenderLoop::handleExposure(QQuickWindow *window)
         win.thread = new QSGRenderThread(this, renderContext);
         win.updateDuringSync = false;
         win.forceRenderPass = true; // also covered by polishAndSync(inExpose=true), but doesn't hurt
+        win.timeBetweenPolishAndSyncs.start();
         m_windows << win;
         w = &m_windows.last();
     }
@@ -1499,9 +1521,14 @@ void QSGThreadedRenderLoop::polishAndSync(Window *w, bool inExpose)
     qint64 polishTime = 0;
     qint64 waitTime = 0;
     qint64 syncTime = 0;
-    bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled();
-    if (profileFrames)
+    const bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled();
+    if (profileFrames) {
         timer.start();
+        const qint64 elapsedSinceLastMs = w->timeBetweenPolishAndSyncs.restart();
+        qCDebug(QSG_LOG_TIME_RENDERLOOP, "[window %p][gui thread] polishAndSync: start, elapsed since last call: %d ms",
+                window,
+                int(elapsedSinceLastMs));
+    }
     Q_QUICK_SG_PROFILE_START(QQuickProfiler::SceneGraphPolishAndSync);
     Q_TRACE(QSG_polishItems_entry);
 
@@ -1575,13 +1602,14 @@ void QSGThreadedRenderLoop::polishAndSync(Window *w, bool inExpose)
         postUpdateRequest(w);
     }
 
-    qCDebug(QSG_LOG_TIME_RENDERLOOP()).nospace()
-            << "Frame prepared with 'threaded' renderloop"
-            << ", polish=" << (polishTime / 1000000)
-            << ", lock=" << (waitTime - polishTime) / 1000000
-            << ", blockedForSync=" << (syncTime - waitTime) / 1000000
-            << ", animations=" << (timer.nsecsElapsed() - syncTime) / 1000000
-            << " - (on Gui thread) " << window;
+    if (profileFrames) {
+        qCDebug(QSG_LOG_TIME_RENDERLOOP, "[window %p][gui thread] Frame prepared, polish=%d ms, lock=%d ms, blockedForSync=%d ms, animations=%d ms",
+                window,
+                int(polishTime / 1000000),
+                int((waitTime - polishTime) / 1000000),
+                int((syncTime - waitTime) / 1000000),
+                int((timer.nsecsElapsed() - syncTime) / 1000000));
+    }
 
     Q_TRACE(QSG_animations_exit);
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphPolishAndSync,
diff --git a/src/quick/scenegraph/qsgthreadedrenderloop_p.h b/src/quick/scenegraph/qsgthreadedrenderloop_p.h
index 1a99cc7ddf..8ccd42c5fd 100644
--- a/src/quick/scenegraph/qsgthreadedrenderloop_p.h
+++ b/src/quick/scenegraph/qsgthreadedrenderloop_p.h
@@ -52,6 +52,7 @@
 //
 
 #include <QtCore/QThread>
+#include <QtCore/QElapsedTimer>
 #include <private/qsgcontext_p.h>
 
 #include "qsgrenderloop_p.h"
@@ -100,6 +101,7 @@ private:
         QQuickWindow *window;
         QSGRenderThread *thread;
         QSurfaceFormat actualWindowFormat;
+        QElapsedTimer timeBetweenPolishAndSyncs;
         uint updateDuringSync : 1;
         uint forceRenderPass : 1;
     };