From 49ef011e33b9ef977679b3d30f883fccea0d8748 Mon Sep 17 00:00:00 2001 From: Christiaan Janssen Date: Wed, 17 Apr 2013 16:46:12 +0200 Subject: [PATCH] QmlProfiler: SceneGraph profiling Change-Id: Ide71b330b13fc3816ed191bd9af84e0fce0d9587 Reviewed-by: Kai Koehne --- src/qml/debugger/qqmlprofilerservice.cpp | 110 +++++++++++++++----- src/qml/debugger/qqmlprofilerservice_p.h | 32 ++++++- src/quick/scenegraph/coreapi/qsgrenderer.cpp | 52 ++++++---- src/quick/scenegraph/qsgadaptationlayer.cpp | 21 +++- src/quick/scenegraph/qsgcontext.cpp | 10 ++- src/quick/scenegraph/qsgrenderloop.cpp | 36 +++++-- src/quick/scenegraph/qsgthreadedrenderloop.cpp | 77 +++++++++----- src/quick/scenegraph/qsgwindowsrenderloop.cpp | 45 +++++++-- src/quick/scenegraph/util/qsgtexture.cpp | 58 +++++++---- .../qqmlprofilerservice/data/scenegraphTest.qml | 18 +++ .../tst_qqmlprofilerservice.cpp | 79 ++++++++++++++ 11 files changed, 418 insertions(+), 120 deletions(-) create mode 100644 tests/auto/qml/debugger/qqmlprofilerservice/data/scenegraphTest.qml diff --git a/src/qml/debugger/qqmlprofilerservice.cpp b/src/qml/debugger/qqmlprofilerservice.cpp index e016b2f..963a861 100644 --- 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 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 --- 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 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 --- a/src/quick/scenegraph/coreapi/qsgrenderer.cpp +++ b/src/quick/scenegraph/coreapi/qsgrenderer.cpp @@ -53,6 +53,8 @@ #include +#include + 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 --- a/src/quick/scenegraph/qsgadaptationlayer.cpp +++ b/src/quick/scenegraph/qsgadaptationlayer.cpp @@ -48,6 +48,7 @@ #include #include +#include #include 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 --- a/src/quick/scenegraph/qsgcontext.cpp +++ b/src/quick/scenegraph/qsgcontext.cpp @@ -67,6 +67,8 @@ #include #include +#include + 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 --- a/src/quick/scenegraph/qsgrenderloop.cpp +++ b/src/quick/scenegraph/qsgrenderloop.cpp @@ -56,6 +56,7 @@ #include #include #include +#include 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 --- a/src/quick/scenegraph/qsgthreadedrenderloop.cpp +++ b/src/quick/scenegraph/qsgthreadedrenderloop.cpp @@ -55,6 +55,8 @@ #include "qsgthreadedrenderloop_p.h" +#include + /* 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 --- a/src/quick/scenegraph/qsgwindowsrenderloop.cpp +++ b/src/quick/scenegraph/qsgwindowsrenderloop.cpp @@ -51,6 +51,8 @@ #include +#include + 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 --- 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 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 --- 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"); -- 1.7.2.5