QmlProfiler: SceneGraph profiling

Change-Id: Ide71b330b13fc3816ed191bd9af84e0fce0d9587
Reviewed-by: Kai Koehne <kai.koehne@digia.com>

diff --git a/src/qml/debugger/qqmlprofilerservice.cpp b/src/qml/debugger/qqmlprofilerservice.cpp
index e016b2f..963a861 100644 (file)
--- a/src/qml/debugger/qqmlprofilerservice.cpp
+++ b/src/qml/debugger/qqmlprofilerservice.cpp
@@ -55,7 +55,7 @@ QT_BEGIN_NAMESPACE
 // instance will be set, unset in constructor. Allows static methods to be inlined.
 QQmlProfilerService *QQmlProfilerService::instance = 0;
 Q_GLOBAL_STATIC(QQmlProfilerService, profilerInstance)
-
+bool QQmlProfilerService::enabled = false;
 
 // convert to a QByteArray that can be sent to the debug client
 // use of QDataStream can skew results
@@ -85,12 +85,37 @@ QByteArray QQmlProfilerData::toByteArray() const
         default: break;
         }
     }
+    if (messageType == (int)QQmlProfilerService::SceneGraphFrame) {
+        switch (detailType) {
+        // RendererFrame: preprocessTime, updateTime, bindingTime, renderTime
+        case QQmlProfilerService::SceneGraphRendererFrame: ds << subtime_1 << subtime_2 << subtime_3 << subtime_4; break;
+        // AdaptationLayerFrame: glyphCount (which is an integer), glyphRenderTime, glyphStoreTime
+        case QQmlProfilerService::SceneGraphAdaptationLayerFrame: ds << (int)subtime_1 << subtime_2 << subtime_3; break;
+        // ContextFrame: compiling material time
+        case QQmlProfilerService::SceneGraphContextFrame: ds << subtime_1; break;
+        // RenderLoop: syncTime, renderTime, swapTime
+        case QQmlProfilerService::SceneGraphRenderLoopFrame: ds << subtime_1 << subtime_2 << subtime_3; break;
+        // TexturePrepare: bind, convert, swizzle, upload, mipmap
+        case QQmlProfilerService::SceneGraphTexturePrepare: ds << subtime_1 << subtime_2 << subtime_3 << subtime_4 << subtime_5; break;
+        // TextureDeletion: deletionTime
+        case QQmlProfilerService::SceneGraphTextureDeletion: ds << subtime_1; break;
+        // PolishAndSync: polishTime, waitTime, syncTime, animationsTime,
+        case QQmlProfilerService::SceneGraphPolishAndSync: ds << subtime_1 << subtime_2 << subtime_3 << subtime_4; break;
+        // WindowsRenderLoop: GL time, make current time, SceneGraph time
+        case QQmlProfilerService::SceneGraphWindowsRenderShow: ds << subtime_1 << subtime_2 << subtime_3; break;
+        // WindowsAnimations: update time
+        case QQmlProfilerService::SceneGraphWindowsAnimations: ds << subtime_1; break;
+        // WindowsRenderWindow: polish time, sync time, render time, swap time
+        case QQmlProfilerService::SceneGraphWindowsPolishFrame: ds << subtime_1; break;
+        default:break;
+        }
+    }
+
     return data;
 }
 
 QQmlProfilerService::QQmlProfilerService()
-    : QQmlDebugService(QStringLiteral("CanvasFrameRate"), 1),
-      m_enabled(false)
+    : QQmlDebugService(QStringLiteral("CanvasFrameRate"), 1)
 {
     m_timer.start();
 
@@ -140,6 +165,11 @@ void QQmlProfilerService::animationFrame(qint64 delta)
     profilerInstance()->animationFrameImpl(delta);
 }
 
+void QQmlProfilerService::sceneGraphFrame(SceneGraphFrameType frameType, qint64 value1, qint64 value2, qint64 value3, qint64 value4, qint64 value5)
+{
+    profilerInstance()->sceneGraphFrameImpl(frameType, value1, value2, value3, value4, value5);
+}
+
 void QQmlProfilerService::sendProfilingData()
 {
     profilerInstance()->sendMessages();
@@ -169,81 +199,89 @@ bool QQmlProfilerService::stopProfilingImpl()
 
 void QQmlProfilerService::sendStartedProfilingMessageImpl()
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData ed = {m_timer.nsecsElapsed(), (int)Event, (int)StartTrace,
-                           QString(), -1, -1, 0, 0, 0};
+                           QString(), -1, -1, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     QQmlDebugService::sendMessage(ed.toByteArray());
 }
 
 void QQmlProfilerService::addEventImpl(EventType event)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData ed = {m_timer.nsecsElapsed(), (int)Event, (int)event,
-                           QString(), -1, -1, 0, 0, 0};
+                           QString(), -1, -1, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     processMessage(ed);
 }
 
 void QQmlProfilerService::startRange(RangeType range, BindingType bindingType)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)RangeStart, (int)range,
-                           QString(), -1, -1, 0, 0, (int)bindingType};
+                           QString(), -1, -1, 0, 0, (int)bindingType,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
 void QQmlProfilerService::rangeData(RangeType range, const QString &rData)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)RangeData, (int)range,
-                           rData, -1, -1, 0, 0, 0};
+                           rData, -1, -1, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
 void QQmlProfilerService::rangeData(RangeType range, const QUrl &rData)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)RangeData, (int)range,
-                           rData.toString(), -1, -1, 0, 0, 0};
+                           rData.toString(), -1, -1, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
 void QQmlProfilerService::rangeLocation(RangeType range, const QString &fileName, int line, int column)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)RangeLocation, (int)range,
-                           fileName, line, column, 0, 0, 0};
+                           fileName, line, column, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
 void QQmlProfilerService::rangeLocation(RangeType range, const QUrl &fileName, int line, int column)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)RangeLocation, (int)range,
-                           fileName.toString(), line, column, 0, 0, 0};
+                           fileName.toString(), line, column, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
 void QQmlProfilerService::endRange(RangeType range)
 {
-    if (!QQmlDebugService::isDebuggingEnabled() || !m_enabled)
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
         return;
 
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)RangeEnd, (int)range,
-                           QString(), -1, -1, 0, 0, 0};
+                           QString(), -1, -1, 0, 0, 0,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
@@ -251,7 +289,8 @@ void QQmlProfilerService::pixmapEventImpl(PixmapEventType eventType, const QUrl
 {
     // assuming enabled checked by caller
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)PixmapCacheEvent, (int)eventType,
-                           url.toString(), -1, -1, -1, -1, -1};
+                           url.toString(), -1, -1, -1, -1, -1,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
@@ -259,7 +298,8 @@ void QQmlProfilerService::pixmapEventImpl(PixmapEventType eventType, const QUrl
 {
     // assuming enabled checked by caller
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)PixmapCacheEvent, (int)eventType,
-                           url.toString(), width, height, -1, -1, -1};
+                           url.toString(), width, height, -1, -1, -1,
+                           0, 0, 0, 0, 0};
     processMessage(rd);
 }
 
@@ -267,14 +307,28 @@ void QQmlProfilerService::pixmapEventImpl(PixmapEventType eventType, const QUrl
 {
     // assuming enabled checked by caller
     QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)PixmapCacheEvent, (int)eventType,
-                           url.toString(), -1, -1, -1, count, -1};
+                           url.toString(), -1, -1, -1, count, -1,
+                           0, 0, 0, 0, 0};
+    processMessage(rd);
+}
+
+void QQmlProfilerService::sceneGraphFrameImpl(SceneGraphFrameType frameType, qint64 value1, qint64 value2, qint64 value3, qint64 value4, qint64 value5)
+{
+    if (!QQmlDebugService::isDebuggingEnabled() || !enabled)
+        return;
+
+    // because I already have some space to store ints in the struct, I'll use it to store the frame data
+    // even though the field names do not match
+    QQmlProfilerData rd = {m_timer.nsecsElapsed(), (int)SceneGraphFrame, (int)frameType, QString(),
+                           -1, -1, -1, -1, -1,
+                           value1, value2, value3, value4, value5};
     processMessage(rd);
 }
 
 void QQmlProfilerService::animationFrameImpl(qint64 delta)
 {
     Q_ASSERT(QQmlDebugService::isDebuggingEnabled());
-    if (!m_enabled)
+    if (!enabled)
         return;
 
     int animCount = QUnifiedTimer::instance()->runningAnimationCount();
@@ -283,7 +337,8 @@ void QQmlProfilerService::animationFrameImpl(qint64 delta)
         // trim fps to integer
         int fps = 1000 / delta;
         QQmlProfilerData ed = {m_timer.nsecsElapsed(), (int)Event, (int)AnimationFrame,
-                               QString(), -1, -1, fps, animCount, 0};
+                               QString(), -1, -1, fps, animCount, 0,
+                               0, 0, 0, 0, 0};
         processMessage(ed);
     }
 }
@@ -300,12 +355,12 @@ void QQmlProfilerService::processMessage(const QQmlProfilerData &message)
 
 bool QQmlProfilerService::profilingEnabled()
 {
-    return m_enabled;
+    return enabled;
 }
 
 void QQmlProfilerService::setProfilingEnabled(bool enable)
 {
-    m_enabled = enable;
+    enabled = enable;
 }
 
 /*
@@ -314,6 +369,7 @@ void QQmlProfilerService::setProfilingEnabled(bool enable)
 void QQmlProfilerService::sendMessages()
 {
     QMutexLocker locker(&m_dataMutex);
+
     QList<QByteArray> messages;
     for (int i = 0; i < m_data.count(); ++i)
         messages << m_data.at(i).toByteArray();
@@ -336,7 +392,7 @@ void QQmlProfilerService::stateAboutToBeChanged(QQmlDebugService::State newState
         return;
 
     if (state() == Enabled
-            && m_enabled) {
+            && enabled) {
         stopProfilingImpl();
         sendMessages();
     }

diff --git a/src/qml/debugger/qqmlprofilerservice_p.h b/src/qml/debugger/qqmlprofilerservice_p.h
index 30eb2eb..fb08a30 100644 (file)
--- a/src/qml/debugger/qqmlprofilerservice_p.h
+++ b/src/qml/debugger/qqmlprofilerservice_p.h
@@ -80,6 +80,12 @@ struct Q_AUTOTEST_EXPORT QQmlProfilerData
     int animationcount; //used by animation events, also as "cache/reference count" for pixmaps
     int bindingType;
 
+    qint64 subtime_1;
+    qint64 subtime_2;
+    qint64 subtime_3;
+    qint64 subtime_4;
+    qint64 subtime_5;
+
     QByteArray toByteArray() const;
 };
 
@@ -100,6 +106,7 @@ public:
         RangeEnd,
         Complete, // end of transmission
         PixmapCacheEvent,
+        SceneGraphFrame,
 
         MaximumMessage
     };
@@ -144,14 +151,32 @@ public:
         MaximumPixmapEventType
     };
 
+    enum SceneGraphFrameType {
+        SceneGraphRendererFrame,
+        SceneGraphAdaptationLayerFrame,
+        SceneGraphContextFrame,
+        SceneGraphRenderLoopFrame,
+        SceneGraphTexturePrepare,
+        SceneGraphTextureDeletion,
+        SceneGraphPolishAndSync,
+        SceneGraphWindowsRenderShow,
+        SceneGraphWindowsAnimations,
+        SceneGraphWindowsPolishFrame,
+
+        MaximumSceneGraphFrameType
+    };
+
     static void initialize();
 
     static bool startProfiling();
     static bool stopProfiling();
     static void sendStartedProfilingMessage();
+    static bool profilingEnabled();
+
     static void addEvent(EventType);
     static void animationFrame(qint64);
 
+    static void sceneGraphFrame(SceneGraphFrameType frameType, qint64 value1, qint64 value2 = -1, qint64 value3 = -1, qint64 value4 = -1, qint64 value5 = -1);
     static void sendProfilingData();
 
     QQmlProfilerService();
@@ -180,14 +205,17 @@ private:
     void pixmapEventImpl(PixmapEventType eventType, const QUrl &url, int width, int height);
     void pixmapEventImpl(PixmapEventType eventType, const QUrl &url, int count);
 
-    bool profilingEnabled();
+    void sceneGraphFrameImpl(SceneGraphFrameType frameType, qint64 value1, qint64 value2, qint64 value3, qint64 value4, qint64 value5);
+
+
     void setProfilingEnabled(bool enable);
     void sendMessages();
     void processMessage(const QQmlProfilerData &);
 
+public:
+    static bool enabled;
 private:
     QElapsedTimer m_timer;
-    bool m_enabled;
     QVector<QQmlProfilerData> m_data;
     QMutex m_dataMutex;
     QMutex m_initializeMutex;

diff --git a/src/quick/scenegraph/coreapi/qsgrenderer.cpp b/src/quick/scenegraph/coreapi/qsgrenderer.cpp
index b46d45b..805cfaa 100644 (file)
--- a/src/quick/scenegraph/coreapi/qsgrenderer.cpp
+++ b/src/quick/scenegraph/coreapi/qsgrenderer.cpp
@@ -53,6 +53,8 @@
 
 #include <qdatetime.h>
 
+#include <private/qqmlprofilerservice_p.h>
+
 QT_BEGIN_NAMESPACE
 
 //#define RENDERER_DEBUG
@@ -62,9 +64,9 @@ QT_BEGIN_NAMESPACE
 
 #ifndef QSG_NO_RENDER_TIMING
 static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty();
-static QTime frameTimer;
-static int preprocessTime;
-static int updatePassTime;
+static QElapsedTimer frameTimer;
+static qint64 preprocessTime;
+static qint64 updatePassTime;
 #endif
 
 void QSGBindable::clear(QSGRenderer::ClearMode mode) const
@@ -238,10 +240,11 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
 
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
+    bool profileFrames = qsg_render_timing || QQmlProfilerService::enabled;
+    if (profileFrames)
         frameTimer.start();
-    int bindTime = 0;
-    int renderTime = 0;
+    qint64 bindTime = 0;
+    qint64 renderTime = 0;
 #endif
 
     m_bindable = &bindable;
@@ -249,8 +252,8 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
 
     bindable.bind();
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        bindTime = frameTimer.elapsed();
+    if (profileFrames)
+        bindTime = frameTimer.nsecsElapsed();
 #endif
 
 #ifndef QT_NO_DEBUG
@@ -270,8 +273,8 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
 
     render();
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        renderTime = frameTimer.elapsed();
+    if (profileFrames)
+        renderTime = frameTimer.nsecsElapsed();
 #endif
 
     glDisable(GL_SCISSOR_TEST);
@@ -292,12 +295,22 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
 #ifndef QSG_NO_RENDER_TIMING
     if (qsg_render_timing) {
         printf(" - Breakdown of render time: preprocess=%d, updates=%d, binding=%d, render=%d, total=%d\n",
-               preprocessTime,
-               updatePassTime - preprocessTime,
-               bindTime - updatePassTime,
-               renderTime - bindTime,
-               renderTime);
+               int(preprocessTime / 1000000),
+               int((updatePassTime - preprocessTime) / 1000000),
+               int((bindTime - updatePassTime) / 1000000),
+               int((renderTime - bindTime) / 1000000),
+               int(renderTime / 1000000));
+    }
+
+    if (QQmlProfilerService::enabled) {
+        QQmlProfilerService::sceneGraphFrame(
+                    QQmlProfilerService::SceneGraphRendererFrame,
+                    preprocessTime,
+                    updatePassTime - preprocessTime,
+                    bindTime - updatePassTime,
+                    renderTime - bindTime);
     }
+
 #endif
 }
 
@@ -380,16 +393,17 @@ void QSGRenderer::preprocess()
     }
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        preprocessTime = frameTimer.elapsed();
+    bool profileFrames = qsg_render_timing || QQmlProfilerService::enabled;
+    if (profileFrames)
+        preprocessTime = frameTimer.nsecsElapsed();
 #endif
 
     nodeUpdater()->setToplevelOpacity(context()->renderAlpha());
     nodeUpdater()->updateStates(m_root_node);
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        updatePassTime = frameTimer.elapsed();
+    if (profileFrames)
+        updatePassTime = frameTimer.nsecsElapsed();
 #endif
 
 }

diff --git a/src/quick/scenegraph/qsgadaptationlayer.cpp b/src/quick/scenegraph/qsgadaptationlayer.cpp
index 1d534e3..3536975 100644 (file)
--- a/src/quick/scenegraph/qsgadaptationlayer.cpp
+++ b/src/quick/scenegraph/qsgadaptationlayer.cpp
@@ -48,6 +48,7 @@
 #include <QtGui/qguiapplication.h>
 #include <qdir.h>
 
+#include <private/qqmlprofilerservice_p.h>
 #include <QElapsedTimer>
 
 QT_BEGIN_NAMESPACE
@@ -162,7 +163,8 @@ void QSGDistanceFieldGlyphCache::update()
         return;
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
+    bool profileFrames = qsg_render_timing || QQmlProfilerService::enabled;
+    if (profileFrames)
         qsg_render_timer.start();
 #endif
 
@@ -176,10 +178,10 @@ void QSGDistanceFieldGlyphCache::update()
     }
 
 #ifndef QSG_NO_RENDER_TIMING
-    int renderTime = 0;
+    qint64 renderTime = 0;
     int count = m_pendingGlyphs.size();
-    if (qsg_render_timing)
-        renderTime = qsg_render_timer.elapsed();
+    if (profileFrames)
+        renderTime = qsg_render_timer.nsecsElapsed();
 #endif
 
     m_pendingGlyphs.reset();
@@ -190,11 +192,18 @@ void QSGDistanceFieldGlyphCache::update()
     if (qsg_render_timing) {
         printf("   - glyphs: count=%d, render=%d, store=%d, total=%d\n",
                count,
-               renderTime,
-               (int) qsg_render_timer.elapsed() - renderTime,
+               int(renderTime/1000000),
+               (int) qsg_render_timer.elapsed() - int(renderTime/1000000),
                (int) qsg_render_timer.elapsed());
 
     }
+    if (QQmlProfilerService::enabled) {
+        QQmlProfilerService::sceneGraphFrame(
+                    QQmlProfilerService::SceneGraphAdaptationLayerFrame,
+                    count,
+                    renderTime,
+                    qsg_render_timer.nsecsElapsed() - renderTime);
+    }
 #endif
 }
 

diff --git a/src/quick/scenegraph/qsgcontext.cpp b/src/quick/scenegraph/qsgcontext.cpp
index 5d894e5..14f0fab 100644 (file)
--- a/src/quick/scenegraph/qsgcontext.cpp
+++ b/src/quick/scenegraph/qsgcontext.cpp
@@ -67,6 +67,8 @@
 #include <private/qobject_p.h>
 #include <qmutex.h>
 
+#include <private/qqmlprofilerservice_p.h>
+
 DEFINE_BOOL_CONFIG_OPTION(qmlFlashMode, QML_FLASH_MODE)
 DEFINE_BOOL_CONFIG_OPTION(qmlTranslucentMode, QML_TRANSLUCENT_MODE)
 DEFINE_BOOL_CONFIG_OPTION(qmlDisableDistanceField, QML_DISABLE_DISTANCEFIELD)
@@ -482,7 +484,7 @@ QSGMaterialShader *QSGContext::prepareMaterial(QSGMaterial *material)
         return shader;
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
+    if (qsg_render_timing  || QQmlProfilerService::enabled)
         qsg_renderer_timer.start();
 #endif
 
@@ -494,6 +496,12 @@ QSGMaterialShader *QSGContext::prepareMaterial(QSGMaterial *material)
 #ifndef QSG_NO_RENDER_TIMING
     if (qsg_render_timing)
         printf("   - compiling material: %dms\n", (int) qsg_renderer_timer.elapsed());
+
+    if (QQmlProfilerService::enabled) {
+        QQmlProfilerService::sceneGraphFrame(
+                    QQmlProfilerService::SceneGraphContextFrame,
+                    qsg_renderer_timer.nsecsElapsed());
+    }
 #endif
 
     return shader;

diff --git a/src/quick/scenegraph/qsgrenderloop.cpp b/src/quick/scenegraph/qsgrenderloop.cpp
index f71ccea..3a608a9 100644 (file)
--- a/src/quick/scenegraph/qsgrenderloop.cpp
+++ b/src/quick/scenegraph/qsgrenderloop.cpp
@@ -56,6 +56,7 @@
 #include <QtQuick/QQuickWindow>
 #include <QtQuick/private/qquickwindow_p.h>
 #include <QtQuick/private/qsgcontext_p.h>
+#include <private/qqmlprofilerservice_p.h>
 
 QT_BEGIN_NAMESPACE
 
@@ -273,20 +274,21 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window)
     QQuickWindowPrivate *cd = QQuickWindowPrivate::get(window);
     cd->polishItems();
 
-    int renderTime = 0, syncTime = 0;
-    QTime renderTimer;
-    if (qsg_render_timing())
+    qint64 renderTime = 0, syncTime = 0;
+    QElapsedTimer renderTimer;
+    bool profileFrames = qsg_render_timing()  || QQmlProfilerService::enabled;
+    if (profileFrames)
         renderTimer.start();
 
     cd->syncSceneGraph();
 
-    if (qsg_render_timing())
-        syncTime = renderTimer.elapsed();
+    if (profileFrames)
+        syncTime = renderTimer.nsecsElapsed();
 
     cd->renderSceneGraph(window->size());
 
-    if (qsg_render_timing())
-        renderTime = renderTimer.elapsed() - syncTime;
+    if (profileFrames)
+        renderTime = renderTimer.nsecsElapsed() - syncTime;
 
     if (data.grabOnly) {
         grabContent = qt_gl_read_framebuffer(window->size(), false, false);
@@ -298,17 +300,29 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window)
         cd->fireFrameSwapped();
     }
 
+    qint64 swapTime = 0;
+    if (profileFrames) {
+        swapTime = renderTimer.nsecsElapsed() - renderTime - syncTime;
+    }
+
     if (qsg_render_timing()) {
         static QTime lastFrameTime = QTime::currentTime();
-        const int swapTime = renderTimer.elapsed() - renderTime - syncTime;
-        qDebug() << "- Breakdown of frame time; sync:" << syncTime
-                 << "ms render:" << renderTime << "ms swap:" << swapTime
-                 << "ms total:" << swapTime + renderTime + syncTime
+        qDebug() << "- Breakdown of frame time; sync:" << syncTime/1000000
+                 << "ms render:" << renderTime/1000000 << "ms swap:" << swapTime/1000000
+                 << "ms total:" << (swapTime + renderTime + syncTime)/1000000
                  << "ms time since last frame:" << (lastFrameTime.msecsTo(QTime::currentTime()))
                  << "ms";
         lastFrameTime = QTime::currentTime();
     }
 
+    if (QQmlProfilerService::enabled) {
+        QQmlProfilerService::sceneGraphFrame(
+                    QQmlProfilerService::SceneGraphRenderLoopFrame,
+                    syncTime,
+                    renderTime,
+                    swapTime);
+    }
+
     // Might have been set during syncSceneGraph()
     if (data.updatePending)
         maybeUpdate(window);

diff --git a/src/quick/scenegraph/qsgthreadedrenderloop.cpp b/src/quick/scenegraph/qsgthreadedrenderloop.cpp
index de1e251..c4a9328 100644 (file)
--- a/src/quick/scenegraph/qsgthreadedrenderloop.cpp
+++ b/src/quick/scenegraph/qsgthreadedrenderloop.cpp
@@ -55,6 +55,8 @@
 
 #include "qsgthreadedrenderloop_p.h"
 
+#include <private/qqmlprofilerservice_p.h>
+
 /*
    Overall design:
 
@@ -138,10 +140,10 @@ static inline int qsgrl_animation_interval() {
 
 #ifndef QSG_NO_RENDER_TIMING
 static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty();
-static QTime threadTimer;
-static int syncTime;
-static int renderTime;
-static int sinceLastTime;
+static QElapsedTimer threadTimer;
+static qint64 syncTime;
+static qint64 renderTime;
+static qint64 sinceLastTime;
 #endif
 
 extern Q_GUI_EXPORT QImage qt_gl_read_framebuffer(const QSize &size, bool alpha_format, bool include_alpha);
@@ -545,8 +547,11 @@ void QSGRenderThread::sync()
 void QSGRenderThread::syncAndRender()
 {
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        sinceLastTime = threadTimer.restart();
+    bool profileFrames = qsg_render_timing || QQmlProfilerService::enabled;
+    if (profileFrames) {
+        sinceLastTime = threadTimer.nsecsElapsed();
+        threadTimer.start();
+    }
 #endif
     QElapsedTimer waitTimer;
     waitTimer.start();
@@ -573,8 +578,8 @@ void QSGRenderThread::syncAndRender()
     }
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        syncTime = threadTimer.elapsed();
+    if (profileFrames)
+        syncTime = threadTimer.nsecsElapsed();
 #endif
     RLDEBUG("    Render:  - rendering starting");
 
@@ -588,8 +593,8 @@ void QSGRenderThread::syncAndRender()
         gl->makeCurrent(w.window);
         d->renderSceneGraph(w.size);
 #ifndef QSG_NO_RENDER_TIMING
-        if (qsg_render_timing && i == 0)
-            renderTime = threadTimer.elapsed();
+        if (profileFrames && i == 0)
+            renderTime = threadTimer.nsecsElapsed();
 #endif
         gl->swapBuffers(w.window);
         d->fireFrameSwapped();
@@ -599,10 +604,18 @@ void QSGRenderThread::syncAndRender()
 #ifndef QSG_NO_RENDER_TIMING
         if (qsg_render_timing)
             qDebug("window Time: sinceLast=%d, sync=%d, first render=%d, after final swap=%d",
-                   sinceLastTime,
-                   syncTime,
-                   renderTime - syncTime,
-                   threadTimer.elapsed() - renderTime);
+                   int(sinceLastTime/1000000),
+                   int(syncTime/1000000),
+                   int((renderTime - syncTime)/1000000),
+                   int(threadTimer.elapsed() - renderTime/1000000));
+
+        if (QQmlProfilerService::enabled) {
+            QQmlProfilerService::sceneGraphFrame(
+                        QQmlProfilerService::SceneGraphRenderLoopFrame,
+                        syncTime,
+                        renderTime - syncTime,
+                        threadTimer.nsecsElapsed() - renderTime);
+        }
 #endif
 }
 
@@ -950,10 +963,11 @@ void QSGThreadedRenderLoop::polishAndSync()
 
 #ifndef QSG_NO_RENDER_TIMING
     QElapsedTimer timer;
-    int polishTime = 0;
-    int waitTime = 0;
-    int syncTime;
-    if (qsg_render_timing)
+    qint64 polishTime = 0;
+    qint64 waitTime = 0;
+    qint64 syncTime = 0;
+    bool profileFrames = qsg_render_timing  || QQmlProfilerService::enabled;
+    if (profileFrames)
         timer.start();
 #endif
 
@@ -964,8 +978,8 @@ void QSGThreadedRenderLoop::polishAndSync()
         d->polishItems();
     }
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        polishTime = timer.elapsed();
+    if (profileFrames)
+        polishTime = timer.nsecsElapsed();
 #endif
 
     m_sync_triggered_update = false;
@@ -977,8 +991,8 @@ void QSGThreadedRenderLoop::polishAndSync()
 
     RLDEBUG("GUI:  - wait for sync...");
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        waitTime = timer.elapsed();
+    if (profileFrames)
+        waitTime = timer.nsecsElapsed();
 #endif
     m_thread->waitCondition.wait(&m_thread->mutex);
     m_thread->guiIsLocked = false;
@@ -986,8 +1000,8 @@ void QSGThreadedRenderLoop::polishAndSync()
     RLDEBUG("GUI:  - unlocked after sync...");
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
-        syncTime = timer.elapsed();
+    if (profileFrames)
+        syncTime = timer.nsecsElapsed();
 #endif
 
     killTimer(m_update_timer);
@@ -1006,7 +1020,20 @@ void QSGThreadedRenderLoop::polishAndSync()
 
 #ifndef QSG_NO_RENDER_TIMING
     if (qsg_render_timing)
-        qDebug(" - polish=%d, wait=%d, sync=%d -- animations=%d", polishTime, waitTime - polishTime, syncTime - waitTime, int(timer.elapsed() - syncTime));
+        qDebug(" - polish=%d, wait=%d, sync=%d -- animations=%d",
+               int(polishTime/1000000),
+               int((waitTime - polishTime)/1000000),
+               int((syncTime - waitTime)/1000000),
+               int((timer.nsecsElapsed() - syncTime)/1000000));
+
+    if (QQmlProfilerService::enabled) {
+        QQmlProfilerService::sceneGraphFrame(
+                    QQmlProfilerService::SceneGraphPolishAndSync,
+                    polishTime,
+                    waitTime - polishTime,
+                    syncTime - waitTime,
+                    timer.elapsed() - syncTime);
+    }
 #endif
 }
 

diff --git a/src/quick/scenegraph/qsgwindowsrenderloop.cpp b/src/quick/scenegraph/qsgwindowsrenderloop.cpp
index 3e21af6..ce43ccf 100644 (file)
--- a/src/quick/scenegraph/qsgwindowsrenderloop.cpp
+++ b/src/quick/scenegraph/qsgwindowsrenderloop.cpp
@@ -51,6 +51,8 @@
 
 #include <QtQuick/QQuickWindow>
 
+#include <private/qqmlprofilerservice_p.h>
+
 QT_BEGIN_NAMESPACE
 
 extern Q_GUI_EXPORT QImage qt_gl_read_framebuffer(const QSize &size, bool alpha_format, bool include_alpha);
@@ -67,7 +69,7 @@ static QElapsedTimer qsg_debug_timer;
 #ifndef QSG_NO_RENDER_TIMING
 static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty();
 static QElapsedTimer qsg_render_timer;
-#define QSG_RENDER_TIMING_SAMPLE(sampleName) int sampleName = 0; if (qsg_render_timing) sampleName = qsg_render_timer.elapsed()
+#define QSG_RENDER_TIMING_SAMPLE(sampleName) qint64 sampleName = 0; if (qsg_render_timing || QQmlProfilerService::enabled) sampleName = qsg_render_timer.nsecsElapsed()
 #else
 #define QSG_RENDER_TIMING_SAMPLE(sampleName)
 #endif
@@ -174,9 +176,16 @@ void QSGWindowsRenderLoop::show(QQuickWindow *window)
 #ifndef QSG_NO_RENDER_TIMING
         if (qsg_render_timing) {
             qDebug("WindowsRenderLoop: GL=%d ms, makeCurrent=%d ms, SG=%d ms",
-                   int(time_created - time_start),
-                   int(time_current - time_created),
-                   int(qsg_render_timer.elapsed() - time_current));
+                   int((time_created - time_start)/1000000),
+                   int((time_current - time_created)/1000000),
+                   int((qsg_render_timer.nsecsElapsed() - time_current)/1000000));
+        }
+        if (QQmlProfilerService::enabled) {
+            QQmlProfilerService::sceneGraphFrame(
+                        QQmlProfilerService::SceneGraphWindowsRenderShow,
+                        time_created - time_start,
+                        time_current - time_created,
+                        qsg_render_timer.nsecsElapsed() - time_current);
         }
 #endif
 
@@ -368,7 +377,12 @@ void QSGWindowsRenderLoop::render()
 #ifndef QSG_NO_RENDER_TIMING
         if (qsg_render_timing) {
             qDebug("WindowsRenderLoop: animations=%d ms",
-                   int(qsg_render_timer.elapsed() - time_start));
+                   int((qsg_render_timer.nsecsElapsed() - time_start)/1000000));
+        }
+        if (QQmlProfilerService::Enabled) {
+            QQmlProfilerService::sceneGraphFrame(
+                        QQmlProfilerService::SceneGraphWindowsAnimations,
+                        qsg_render_timer.nsecsElapsed() - time_start);
         }
 #endif
 
@@ -424,10 +438,23 @@ void QSGWindowsRenderLoop::renderWindow(QQuickWindow *window)
             qDebug("WindowsRenderLoop(t=%d): window=%p, polish=%d ms, sync=%d ms, render=%d ms, swap=%d ms",
                    int(qsg_render_timer.elapsed()),
                    window,
-                   int(time_polished - time_start),
-                   int(time_synced - time_polished),
-                   int(time_rendered - time_synced),
-                   int(time_swapped - time_rendered));
+                   int((time_polished - time_start)/1000000),
+                   int((time_synced - time_polished)/1000000),
+                   int((time_rendered - time_synced)/1000000),
+                   int((time_swapped - time_rendered)/1000000));
+        }
+        if (QQmlProfilerService::enabled) {
+            QQmlProfilerService::sceneGraphFrame(
+                        QQmlProfilerService::SceneGraphWindowsPolishFrame,
+                        time_polished - time_start
+                        );
+
+            QQmlProfilerService::sceneGraphFrame(
+                        QQmlProfilerService::SceneGraphRenderLoopFrame,
+                        time_synced - time_polished,
+                        time_rendered - time_synced,
+                        time_swapped - time_rendered
+                        );
         }
 #endif
 }

diff --git a/src/quick/scenegraph/util/qsgtexture.cpp b/src/quick/scenegraph/util/qsgtexture.cpp
index ad98fe9..a104e4a 100644 (file)
--- a/src/quick/scenegraph/util/qsgtexture.cpp
+++ b/src/quick/scenegraph/util/qsgtexture.cpp
@@ -614,7 +614,8 @@ void QSGPlainTexture::bind()
     m_dirty_texture = false;
 
 #ifndef QSG_NO_RENDER_TIMING
-    if (qsg_render_timing)
+    bool profileFrames = qsg_render_timing || QQmlProfilerService::enabled;
+    if (profileFrames)
         qsg_renderer_timer.start();
 #endif
 
@@ -628,6 +629,11 @@ void QSGPlainTexture::bind()
                        m_texture_size.width(),
                        m_texture_size.height());
             }
+            if (QQmlProfilerService::enabled) {
+                QQmlProfilerService::sceneGraphFrame(
+                            QQmlProfilerService::SceneGraphTextureDeletion,
+                            qsg_renderer_timer.nsecsElapsed());
+            }
 #endif
         }
         m_texture_id = 0;
@@ -645,9 +651,9 @@ void QSGPlainTexture::bind()
     glBindTexture(GL_TEXTURE_2D, m_texture_id);
 
 #ifndef QSG_NO_RENDER_TIMING
-    int bindTime = 0;
-    if (qsg_render_timing)
-        bindTime = qsg_renderer_timer.elapsed();
+    qint64 bindTime = 0;
+    if (profileFrames)
+        bindTime = qsg_renderer_timer.nsecsElapsed();
 #endif
 
     // ### TODO: check for out-of-memory situations...
@@ -659,9 +665,9 @@ void QSGPlainTexture::bind()
                  : m_image.convertToFormat(QImage::Format_ARGB32_Premultiplied);
 
 #ifndef QSG_NO_RENDER_TIMING
-    int convertTime = 0;
-    if (qsg_render_timing)
-        convertTime = qsg_renderer_timer.elapsed();
+    qint64 convertTime = 0;
+    if (profileFrames)
+        convertTime = qsg_renderer_timer.nsecsElapsed();
 #endif
 
     updateBindOptions(m_dirty_bind_options);
@@ -684,16 +690,16 @@ void QSGPlainTexture::bind()
     }
 
 #ifndef QSG_NO_RENDER_TIMING
-    int swizzleTime = 0;
-    if (qsg_render_timing)
-        swizzleTime = qsg_renderer_timer.elapsed();
+    qint64 swizzleTime = 0;
+    if (profileFrames)
+        swizzleTime = qsg_renderer_timer.nsecsElapsed();
 #endif
     glTexImage2D(GL_TEXTURE_2D, 0, internalFormat, w, h, 0, externalFormat, GL_UNSIGNED_BYTE, tmp.constBits());
 
 #ifndef QSG_NO_RENDER_TIMING
-    int uploadTime = 0;
-    if (qsg_render_timing)
-        uploadTime = qsg_renderer_timer.elapsed();
+    qint64 uploadTime = 0;
+    if (profileFrames)
+        uploadTime = qsg_renderer_timer.nsecsElapsed();
 #endif
 
 
@@ -704,23 +710,35 @@ void QSGPlainTexture::bind()
     }
 
 #ifndef QSG_NO_RENDER_TIMING
-    int mipmapTime = 0;
+    qint64 mipmapTime = 0;
     if (qsg_render_timing) {
-        mipmapTime = qsg_renderer_timer.elapsed();
+        mipmapTime = qsg_renderer_timer.nsecsElapsed();
 
         printf("   - plaintexture(%dx%d) bind=%d, convert=%d, swizzle=%d (%s->%s), upload=%d, mipmap=%d, total=%d\n",
                m_texture_size.width(), m_texture_size.height(),
-               bindTime,
-               convertTime - bindTime,
-               swizzleTime - convertTime,
+               int(bindTime/1000000),
+               int((convertTime - bindTime)/1000000),
+               int((swizzleTime - convertTime)/1000000),
                externalFormat == GL_BGRA ? "BGRA" : "RGBA",
                internalFormat == GL_BGRA ? "BGRA" : "RGBA",
-               uploadTime - swizzleTime,
-               mipmapTime - uploadTime,
+               int((uploadTime - swizzleTime)/1000000),
+               int((mipmapTime - uploadTime)/1000000),
                (int) qsg_renderer_timer.elapsed());
 
     }
 
+    if (QQmlProfilerService::enabled) {
+        mipmapTime = qsg_renderer_timer.nsecsElapsed();
+
+        QQmlProfilerService::sceneGraphFrame(
+                    QQmlProfilerService::SceneGraphTexturePrepare,
+                    bindTime,
+                    convertTime - bindTime,
+                    swizzleTime - convertTime,
+                    uploadTime - swizzleTime,
+                    mipmapTime - uploadTime);
+    }
+
 #endif
 
 

diff --git a/tests/auto/qml/debugger/qqmlprofilerservice/data/scenegraphTest.qml b/tests/auto/qml/debugger/qqmlprofilerservice/data/scenegraphTest.qml
new file mode 100644 (file)
index 0000000..dd9d053
--- /dev/null
+++ b/tests/auto/qml/debugger/qqmlprofilerservice/data/scenegraphTest.qml
@@ -0,0 +1,18 @@
+import QtQuick 2.0
+
+Rectangle {
+    Rectangle {
+        width: 10
+        height: 10
+        color: "blue"
+    }
+
+    Component.onCompleted: timer.start();
+
+    Timer {
+        id: timer
+        interval: 100 // 100 ms, enough for at least one frame
+        running: false
+        onTriggered: console.log("tick")
+    }
+}

diff --git a/tests/auto/qml/debugger/qqmlprofilerservice/tst_qqmlprofilerservice.cpp b/tests/auto/qml/debugger/qqmlprofilerservice/tst_qqmlprofilerservice.cpp
index 8ad4f52..21fc481 100644 (file)
--- a/tests/auto/qml/debugger/qqmlprofilerservice/tst_qqmlprofilerservice.cpp
+++ b/tests/auto/qml/debugger/qqmlprofilerservice/tst_qqmlprofilerservice.cpp
@@ -78,6 +78,7 @@ public:
         RangeEnd,
         Complete, // end of transmission
         PixmapCacheEvent,
+        SceneGraphFrame,
 
         MaximumMessage
     };
@@ -114,6 +115,21 @@ public:
         MaximumPixmapEventType
     };
 
+    enum SceneGraphFrameType {
+        SceneGraphRendererFrame,
+        SceneGraphAdaptationLayerFrame,
+        SceneGraphContextFrame,
+        SceneGraphRenderLoopFrame,
+        SceneGraphTexturePrepare,
+        SceneGraphTextureDeletion,
+        SceneGraphPolishAndSync,
+        SceneGraphWindowsRenderShow,
+        SceneGraphWindowsAnimations,
+        SceneGraphWindowsPolishFrame,
+
+        MaximumSceneGraphFrameType
+    };
+
     QQmlProfilerClient(QQmlDebugConnection *connection)
         : QQmlDebugClient(QLatin1String("CanvasFrameRate"), connection)
     {
@@ -147,6 +163,7 @@ public:
     {
     }
 
+
 private:
     QQmlDebugProcess *m_process;
     QQmlDebugConnection *m_connection;
@@ -161,6 +178,7 @@ private slots:
     void blockingConnectWithTraceDisabled();
     void nonBlockingConnect();
     void pixmapCacheData();
+    void scenegraphData();
     void profileOnExit();
 };
 
@@ -242,6 +260,34 @@ void QQmlProfilerClient::messageReceived(const QByteArray &message)
             stream >> data.animationcount;
         break;
     }
+    case QQmlProfilerClient::SceneGraphFrame: {
+        stream >> data.detailType;
+        qint64 subtime_1, subtime_2, subtime_3, subtime_4, subtime_5;
+        int glyphCount;
+        switch (data.detailType) {
+        // RendererFrame: preprocessTime, updateTime, bindingTime, renderTime
+        case QQmlProfilerClient::SceneGraphRendererFrame: stream >> subtime_1 >> subtime_2 >> subtime_3 >> subtime_4; break;
+            // AdaptationLayerFrame: glyphCount, glyphRenderTime, glyphStoreTime
+        case QQmlProfilerClient::SceneGraphAdaptationLayerFrame: stream >> glyphCount >> subtime_2 >> subtime_3; break;
+            // ContextFrame: compiling material time
+        case QQmlProfilerClient::SceneGraphContextFrame: stream >> subtime_1; break;
+            // RenderLoop: syncTime, renderTime, swapTime
+        case QQmlProfilerClient::SceneGraphRenderLoopFrame: stream >> subtime_1 >> subtime_2 >> subtime_3; break;
+            // TexturePrepare: bind, convert, swizzle, upload, mipmap
+        case QQmlProfilerClient::SceneGraphTexturePrepare: stream >> subtime_1 >> subtime_2 >> subtime_3 >> subtime_4 >> subtime_5; break;
+            // TextureDeletion: deletionTime
+        case QQmlProfilerClient::SceneGraphTextureDeletion: stream >> subtime_1; break;
+            // PolishAndSync: polishTime, waitTime, syncTime, animationsTime,
+        case QQmlProfilerClient::SceneGraphPolishAndSync: stream >> subtime_1 >> subtime_2 >> subtime_3 >> subtime_4; break;
+            // WindowsRenderLoop: GL time, make current time, SceneGraph time
+        case QQmlProfilerClient::SceneGraphWindowsRenderShow: stream >> subtime_1 >> subtime_2 >> subtime_3; break;
+            // WindowsAnimations: update time
+        case QQmlProfilerClient::SceneGraphWindowsAnimations: stream >> subtime_1; break;
+            // WindowsRenderWindow: polish time, sync time, render time, swap time
+        case QQmlProfilerClient::SceneGraphWindowsPolishFrame: stream >> subtime_1; break;
+        }
+        break;
+    }
     default:
         QString failMsg = QString("Unknown message type:") + data.messageType;
         QFAIL(qPrintable(failMsg));
@@ -388,6 +434,39 @@ void tst_QQmlProfilerService::pixmapCacheData()
 
 }
 
+void tst_QQmlProfilerService::scenegraphData()
+{
+    connect(true, "scenegraphTest.qml");
+    QTRY_COMPARE(m_client->state(), QQmlDebugClient::Enabled);
+
+    m_client->setTraceState(true);
+    QVERIFY(QQmlDebugTest::waitForSignal(m_process, SIGNAL(readyReadStandardOutput())));
+    QVERIFY(m_process->output().indexOf(QLatin1String("tick")) != -1);
+    m_client->setTraceState(false);
+
+    QVERIFY2(QQmlDebugTest::waitForSignal(m_client, SIGNAL(complete())), "No trace received in time.");
+    QVERIFY(m_client->traceMessages.count());
+
+    // check that at least one frame was rendered
+    // there should be a SGPolishAndSync + SGRendererFrame + SGRenderLoopFrame sequence
+    // since the rendering happens in a different thread, there could be other unrelated events interleaved
+    int loopcheck = 0;
+    foreach (const QQmlProfilerData &msg, m_client->traceMessages) {
+        if (msg.messageType == QQmlProfilerClient::SceneGraphFrame) {
+            if (loopcheck == 0 && msg.detailType == QQmlProfilerClient::SceneGraphContextFrame)
+                loopcheck = 1;
+            else
+            if (loopcheck == 1 && msg.detailType == QQmlProfilerClient::SceneGraphRendererFrame)
+                loopcheck = 2;
+            else
+            if (loopcheck == 2 && msg.detailType == QQmlProfilerClient::SceneGraphRenderLoopFrame)
+               loopcheck = 3;
+        }
+    }
+
+    QCOMPARE(loopcheck, 3);
+}
+
 void tst_QQmlProfilerService::profileOnExit()
 {
     connect(true, "exit.qml");