From 7f8214c866cd7144a4630e234368a1ae70405a17 Mon Sep 17 00:00:00 2001 From: Laszlo Agocs Date: Tue, 8 Sep 2020 11:50:26 +0200 Subject: 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 --- src/quick/scenegraph/qsgrenderloop.cpp | 15 ++++--- src/quick/scenegraph/qsgthreadedrenderloop.cpp | 62 +++++++++++++++++++------- src/quick/scenegraph/qsgthreadedrenderloop_p.h | 2 + 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 #include -#include +#include #include #include @@ -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()) 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 +#include #include #include "qsgrenderloop_p.h" @@ -100,6 +101,7 @@ private: QQuickWindow *window; QSGRenderThread *thread; QSurfaceFormat actualWindowFormat; + QElapsedTimer timeBetweenPolishAndSyncs; uint updateDuringSync : 1; uint forceRenderPass : 1; }; -- cgit v1.2.3