Add trace points for Qt Quick Scene Graph

This adds Q_TRACE tracepoints for all places that are covered by
the QML profiler's QSG integration. The big advantage over the
existing framework is that these trace points can be visualized
next to other system tracepoints to correlate the data better with
load and resource consumption induced by other processes on the
system.

Change-Id: I0c5b70a0870f0b89e4533c351c099e13fd18a55f
Reviewed-by: Ulf Hermann <ulf.hermann@qt.io>

7 files changed, 70 insertions, 0 deletions

diff --git a/src/plugins/scenegraph/d3d12/d3d12.pro b/src/plugins/scenegraph/d3d12/d3d12.pro
index 9cca5458ee..7192efe449 100644
--- a/src/plugins/scenegraph/d3d12/d3d12.pro
+++ b/src/plugins/scenegraph/d3d12/d3d12.pro
@@ -6,6 +6,18 @@ PLUGIN_TYPE = scenegraph
 PLUGIN_CLASS_NAME = QSGD3D12Adaptation
 load(qt_plugin)
 
+TRACEPOINT_PROVIDER = $$PWD/d3d12.tracepoints
+CONFIG += qt_tracepoints
+debug_and_release {
+    CONFIG(debug, debug|release) {
+        INCLUDEPATH += $$OUT_PWD/../../../quick/.tracegen/debug
+    } else {
+        INCLUDEPATH += $$OUT_PWD/../../../quick/.tracegen/release
+    }
+} else {
+    INCLUDEPATH += $$OUT_PWD/../../../quick/.tracegen/
+}
+
 QMAKE_TARGET_PRODUCT = "Qt Quick D3D12 Renderer (Qt $$QT_VERSION)"
 QMAKE_TARGET_DESCRIPTION = "Quick D3D12 Renderer for Qt."
 
diff --git a/src/plugins/scenegraph/d3d12/d3d12.tracepoints b/src/plugins/scenegraph/d3d12/d3d12.tracepoints
new file mode 100644
index 0000000000..e69de29bb2
--- /dev/null
+++ b/src/plugins/scenegraph/d3d12/d3d12.tracepoints
diff --git a/src/plugins/scenegraph/d3d12/qsgd3d12renderloop.cpp b/src/plugins/scenegraph/d3d12/qsgd3d12renderloop.cpp
index 4a6894e69e..79ffee7689 100644
--- a/src/plugins/scenegraph/d3d12/qsgd3d12renderloop.cpp
+++ b/src/plugins/scenegraph/d3d12/qsgd3d12renderloop.cpp
@@ -49,6 +49,8 @@
 #include <QGuiApplication>
 #include <QScreen>
 
+#include <qtquick_tracepoints_p.h>
+
 QT_BEGIN_NAMESPACE
 
 // NOTE: Avoid categorized logging. It is slow.
@@ -403,6 +405,8 @@ void QSGD3D12RenderLoop::renderWindow(QQuickWindow *window)
         return;
     }
 
+    Q_TRACE_SCOPE(QSG_renderWindow);
+
     if (!data.grabOnly)
         wd->flushFrameSynchronousEvents();
 
@@ -412,14 +416,17 @@ void QSGD3D12RenderLoop::renderWindow(QQuickWindow *window)
     if (profileFrames)
         renderTimer.start();
     Q_QUICK_SG_PROFILE_START(QQuickProfiler::SceneGraphPolishFrame);
+    Q_TRACE(QSG_polishItems_entry);
 
     wd->polishItems();
 
     if (profileFrames)
         polishTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_polishItems_exit);
     Q_QUICK_SG_PROFILE_SWITCH(QQuickProfiler::SceneGraphPolishFrame,
                               QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphPolishPolish);
+    Q_TRACE(QSG_sync_entry);
 
     emit window->afterAnimating();
 
@@ -462,15 +469,19 @@ void QSGD3D12RenderLoop::renderWindow(QQuickWindow *window)
 
     if (profileFrames)
         syncTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_sync_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphRenderLoopSync);
+    Q_TRACE(QSG_render_entry);
 
     wd->renderSceneGraph(window->size());
 
     if (profileFrames)
         renderTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_render_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphRenderLoopRender);
+    Q_TRACE(QSG_swap_entry);
 
     if (!data.grabOnly) {
         // The engine is able to have multiple frames in flight. This in effect is
@@ -497,6 +508,7 @@ void QSGD3D12RenderLoop::renderWindow(QQuickWindow *window)
     qint64 swapTime = 0;
     if (profileFrames)
         swapTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_swap_exit);
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphRenderLoopFrame,
                            QQuickProfiler::SceneGraphRenderLoopSwap);
 
diff --git a/src/plugins/scenegraph/d3d12/qsgd3d12threadedrenderloop.cpp b/src/plugins/scenegraph/d3d12/qsgd3d12threadedrenderloop.cpp
index 4302a9119b..91a35627ea 100644
--- a/src/plugins/scenegraph/d3d12/qsgd3d12threadedrenderloop.cpp
+++ b/src/plugins/scenegraph/d3d12/qsgd3d12threadedrenderloop.cpp
@@ -52,6 +52,8 @@
 #include <QQueue>
 #include <QGuiApplication>
 
+#include <qtquick_tracepoints_p.h>
+
 QT_BEGIN_NAMESPACE
 
 // NOTE: Avoid categorized logging. It is slow.
@@ -560,11 +562,13 @@ void QSGD3D12RenderThread::sync(bool inExpose)
 
 void QSGD3D12RenderThread::syncAndRender()
 {
+    Q_TRACE_SCOPE(QSG_syncAndRender);
     if (Q_UNLIKELY(debug_time())) {
         sinceLastTime = threadTimer.nsecsElapsed();
         threadTimer.start();
     }
     Q_QUICK_SG_PROFILE_START(QQuickProfiler::SceneGraphRenderLoopFrame);
+    Q_TRACE(QSG_sync_entry);
 
     QElapsedTimer waitTimer;
     waitTimer.start();
@@ -587,6 +591,7 @@ void QSGD3D12RenderThread::syncAndRender()
     if (Q_UNLIKELY(debug_time()))
         syncTime = threadTimer.nsecsElapsed();
 #endif
+    Q_TRACE(QSG_sync_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphRenderLoopSync);
 
@@ -598,6 +603,7 @@ void QSGD3D12RenderThread::syncAndRender()
             msleep(waitTime);
         return;
     }
+    Q_TRACE(QSG_render_entry);
 
     if (Q_UNLIKELY(debug_loop()))
         qDebug("RT - rendering started");
@@ -623,8 +629,10 @@ void QSGD3D12RenderThread::syncAndRender()
         wd->renderSceneGraph(engine->windowSize());
         if (Q_UNLIKELY(debug_time()))
             renderTime = threadTimer.nsecsElapsed();
+        Q_TRACE(QSG_render_exit);
         Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphRenderLoopFrame,
                                   QQuickProfiler::SceneGraphRenderLoopRender);
+        Q_TRACE(QSG_swap_entry);
 
         // The engine is able to have multiple frames in flight. This in effect is
         // similar to BufferQueueingOpenGL. Provide an env var to force the
@@ -641,8 +649,10 @@ void QSGD3D12RenderThread::syncAndRender()
         // blockOnEachFrame is not used, but emit it for compatibility.
         wd->fireFrameSwapped();
     } else {
+        Q_TRACE(QSG_render_exit);
         Q_QUICK_SG_PROFILE_SKIP(QQuickProfiler::SceneGraphRenderLoopFrame,
                                 QQuickProfiler::SceneGraphRenderLoopSync, 1);
+        Q_TRACE(QSG_swap_entry);
         if (Q_UNLIKELY(debug_loop()))
             qDebug("RT - window not ready, skipping render");
     }
@@ -664,6 +674,7 @@ void QSGD3D12RenderThread::syncAndRender()
                int((renderTime - syncTime) / 1000000),
                int(threadTimer.elapsed() - renderTime / 1000000));
 
+    Q_TRACE(QSG_swap_exit);
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphRenderLoopFrame,
                            QQuickProfiler::SceneGraphRenderLoopSwap);
 
@@ -1103,6 +1114,8 @@ void QSGD3D12ThreadedRenderLoop::polishAndSync(WindowData *w, bool inExpose)
         return;
     }
 
+    Q_TRACE_SCOPE(QSG_polishAndSync);
+
     // Flush pending touch events.
     QQuickWindowPrivate::get(window)->flushFrameSynchronousEvents();
     // The delivery of the event might have caused the window to stop rendering
@@ -1120,14 +1133,17 @@ void QSGD3D12ThreadedRenderLoop::polishAndSync(WindowData *w, bool inExpose)
     if (Q_UNLIKELY(debug_time()))
         timer.start();
     Q_QUICK_SG_PROFILE_START(QQuickProfiler::SceneGraphPolishAndSync);
+    Q_TRACE(QSG_polishItems_entry);
 
     QQuickWindowPrivate *wd = QQuickWindowPrivate::get(window);
     wd->polishItems();
 
     if (Q_UNLIKELY(debug_time()))
         polishTime = timer.nsecsElapsed();
+    Q_TRACE(QSG_polishItems_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphPolishAndSync,
                               QQuickProfiler::SceneGraphPolishAndSyncPolish);
+    Q_TRACE(QSG_wait_entry);
 
     w->updateDuringSync = false;
 
@@ -1144,8 +1160,11 @@ void QSGD3D12ThreadedRenderLoop::polishAndSync(WindowData *w, bool inExpose)
         qDebug("polishAndSync - wait for sync");
     if (Q_UNLIKELY(debug_time()))
         waitTime = timer.nsecsElapsed();
+    Q_TRACE(QSG_wait_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphPolishAndSync,
                               QQuickProfiler::SceneGraphPolishAndSyncWait);
+    Q_TRACE(QSG_sync_entry);
+
     w->thread->waitCondition.wait(&w->thread->mutex);
     lockedForSync = false;
     w->thread->mutex.unlock();
@@ -1154,8 +1173,10 @@ void QSGD3D12ThreadedRenderLoop::polishAndSync(WindowData *w, bool inExpose)
 
     if (Q_UNLIKELY(debug_time()))
         syncTime = timer.nsecsElapsed();
+    Q_TRACE(QSG_sync_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphPolishAndSync,
                               QQuickProfiler::SceneGraphPolishAndSyncSync);
+    Q_TRACE(QSG_animations_entry);
 
     if (!animationTimer && anim->isRunning()) {
         if (Q_UNLIKELY(debug_loop()))
@@ -1177,6 +1198,7 @@ void QSGD3D12ThreadedRenderLoop::polishAndSync(WindowData *w, bool inExpose)
                 << ", animations=" << (timer.nsecsElapsed() - syncTime) / 1000000
                 << " - (on gui thread) " << window;
 
+    Q_TRACE(QSG_animations_exit);
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphPolishAndSync,
                            QQuickProfiler::SceneGraphPolishAndSyncAnimations);
 }
diff --git a/src/plugins/scenegraph/openvg/openvg.pro b/src/plugins/scenegraph/openvg/openvg.pro
index 43c2636343..7f9f4bfec5 100644
--- a/src/plugins/scenegraph/openvg/openvg.pro
+++ b/src/plugins/scenegraph/openvg/openvg.pro
@@ -6,6 +6,18 @@ PLUGIN_TYPE = scenegraph
 PLUGIN_CLASS_NAME = QSGOpenVGAdaptation
 load(qt_plugin)
 
+TRACEPOINT_PROVIDER = $$PWD/openvg.tracepoints
+CONFIG += qt_tracepoints
+debug_and_release {
+    CONFIG(debug, debug|release) {
+        INCLUDEPATH += $$OUT_PWD/../../../quick/.tracegen/debug
+    } else {
+        INCLUDEPATH += $$OUT_PWD/../../../quick/.tracegen/release
+    }
+} else {
+    INCLUDEPATH += $$OUT_PWD/../../../quick/.tracegen/
+}
+
 QMAKE_TARGET_PRODUCT = "Qt Quick OpenVG Renderer (Qt $$QT_VERSION)"
 QMAKE_TARGET_DESCRIPTION = "Quick OpenVG Renderer for Qt."
 
diff --git a/src/plugins/scenegraph/openvg/openvg.tracepoints b/src/plugins/scenegraph/openvg/openvg.tracepoints
new file mode 100644
index 0000000000..e69de29bb2
--- /dev/null
+++ b/src/plugins/scenegraph/openvg/openvg.tracepoints
diff --git a/src/plugins/scenegraph/openvg/qsgopenvgrenderloop.cpp b/src/plugins/scenegraph/openvg/qsgopenvgrenderloop.cpp
index 85651ece9d..90ccab2682 100644
--- a/src/plugins/scenegraph/openvg/qsgopenvgrenderloop.cpp
+++ b/src/plugins/scenegraph/openvg/qsgopenvgrenderloop.cpp
@@ -47,6 +47,8 @@
 #include <private/qquickwindow_p.h>
 #include <private/qquickprofiler_p.h>
 
+#include <qtquick_tracepoints_p.h>
+
 #include "qopenvgcontext_p.h"
 
 QT_BEGIN_NAMESPACE
@@ -171,6 +173,8 @@ void QSGOpenVGRenderLoop::renderWindow(QQuickWindow *window)
     if (!cd->isRenderable() || !m_windows.contains(window))
         return;
 
+    Q_TRACE_SCOPE(QSG_renderWindow);
+
     WindowData &data = const_cast<WindowData &>(m_windows[window]);
 
     if (vg == nullptr) {
@@ -198,14 +202,17 @@ void QSGOpenVGRenderLoop::renderWindow(QQuickWindow *window)
     if (profileFrames)
         renderTimer.start();
     Q_QUICK_SG_PROFILE_START(QQuickProfiler::SceneGraphPolishFrame);
+    Q_TRACE(QSG_polishItems_entry);
 
     cd->polishItems();
 
     if (profileFrames)
         polishTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_polishItems_exit);
     Q_QUICK_SG_PROFILE_SWITCH(QQuickProfiler::SceneGraphPolishFrame,
                               QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphPolishPolish);
+    Q_TRACE(QSG_sync_entry);
 
     emit window->afterAnimating();
 
@@ -214,8 +221,10 @@ void QSGOpenVGRenderLoop::renderWindow(QQuickWindow *window)
 
     if (profileFrames)
         syncTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_sync_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphRenderLoopSync);
+    Q_TRACE(QSG_render_entry);
 
     // setup coordinate system for window
     vgSeti(VG_MATRIX_MODE, VG_MATRIX_PATH_USER_TO_SURFACE);
@@ -227,8 +236,10 @@ void QSGOpenVGRenderLoop::renderWindow(QQuickWindow *window)
 
     if (profileFrames)
         renderTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_render_exit);
     Q_QUICK_SG_PROFILE_RECORD(QQuickProfiler::SceneGraphRenderLoopFrame,
                               QQuickProfiler::SceneGraphRenderLoopRender);
+    Q_TRACE(QSG_swap_entry);
 
     if (data.grabOnly) {
         grabContent = vg->readFramebuffer(window->size() * window->effectiveDevicePixelRatio());
@@ -243,6 +254,7 @@ void QSGOpenVGRenderLoop::renderWindow(QQuickWindow *window)
     qint64 swapTime = 0;
     if (profileFrames)
         swapTime = renderTimer.nsecsElapsed();
+    Q_TRACE(QSG_swap_exit);
     Q_QUICK_SG_PROFILE_END(QQuickProfiler::SceneGraphRenderLoopFrame,
                            QQuickProfiler::SceneGraphRenderLoopSwap);