From 7a8cc93a0546bc38c54343d640e63062c3b398b2 Mon Sep 17 00:00:00 2001 From: Gunnar Sletta Date: Thu, 26 Jun 2014 20:48:47 +0200 Subject: [PATCH] Use categorized logging for all things scenegraph. Change-Id: I865ee838b0fd6c257b7189f24130012b98206fd1 Reviewed-by: Shawn Rutledge --- .../doc/src/concepts/visualcanvas/scenegraph.qdoc | 22 +++ src/quick/scenegraph/coreapi/qsgbatchrenderer.cpp | 22 +-- src/quick/scenegraph/coreapi/qsgrenderer.cpp | 35 +--- src/quick/scenegraph/qsgadaptationlayer.cpp | 27 +-- src/quick/scenegraph/qsgcontext.cpp | 52 ++++- src/quick/scenegraph/qsgcontext_p.h | 8 + src/quick/scenegraph/qsgrenderloop.cpp | 56 +++--- src/quick/scenegraph/qsgthreadedrenderloop.cpp | 218 +++++++++------------ src/quick/scenegraph/qsgwindowsrenderloop.cpp | 71 ++----- src/quick/scenegraph/util/qsgatlastexture.cpp | 21 +- src/quick/scenegraph/util/qsgtexture.cpp | 61 ++---- 11 files changed, 261 insertions(+), 332 deletions(-) diff --git a/src/quick/doc/src/concepts/visualcanvas/scenegraph.qdoc b/src/quick/doc/src/concepts/visualcanvas/scenegraph.qdoc index 1f8147c..f07d981 100644 --- a/src/quick/doc/src/concepts/visualcanvas/scenegraph.qdoc +++ b/src/quick/doc/src/concepts/visualcanvas/scenegraph.qdoc @@ -325,7 +325,29 @@ framebuffer object (FBO), so the rendering is a two-step operation. First rasterize the surface, then draw the surface. Using scene graph API directly is always significantly faster. +\section1 Logging Support +The scene graph has support for a number of logging categories. These +can be useful in tracking down both performance issues and bugs in +addition to being helpful to Qt contributors. + +\list + +\li \c {qt.scenegraph.time.texture} - logs the time spent doing texture uploads + +\li \c {qt.scenegraph.time.compilation} - logs the time spent doing shader compilation + +\li \c {qt.scenegraph.time.renderer} - logs the time spent in the various steps of the renderer + +\li \c {qt.scenegraph.time.renderloop} - logs the time spent in the various steps of the render loop + +\li \c {qt.scenegraph.time.glyph} - logs the time spent preparing distance field glyphs + +\li \c {qt.scenegraph.info} - logs general information about various parts of the scene graph and the graphics stack + +\li \c {qt.scenegraph.renderloop} - creates a detailed log of the various stages involved in rendering. This log mode is primarily useful for developers working on Qt. + +\endlist \section1 Scene Graph Backend diff --git a/src/quick/scenegraph/coreapi/qsgbatchrenderer.cpp b/src/quick/scenegraph/coreapi/qsgbatchrenderer.cpp index b3342be..c064023 100644 --- a/src/quick/scenegraph/coreapi/qsgbatchrenderer.cpp +++ b/src/quick/scenegraph/coreapi/qsgbatchrenderer.cpp @@ -80,10 +80,7 @@ const bool debug_noalpha = qgetenv("QSG_RENDERER_DEBUG").contains("noalpha"); const bool debug_noopaque = qgetenv("QSG_RENDERER_DEBUG").contains("noopaque"); const bool debug_noclip = qgetenv("QSG_RENDERER_DEBUG").contains("noclip"); -#ifndef QSG_NO_RENDER_TIMING -static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty(); static QElapsedTimer qsg_renderer_timer; -#endif #define QSGNODE_TRAVERSE(NODE) for (QSGNode *child = NODE->firstChild(); child; child = child->nextSibling()) #define SHADOWNODE_TRAVERSE(NODE) for (QList::const_iterator child = NODE->children.constBegin(); child != NODE->children.constEnd(); ++child) @@ -134,10 +131,8 @@ ShaderManager::Shader *ShaderManager::prepareMaterial(QSGMaterial *material) if (shader) return shader; -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing || QQuickProfiler::enabled) + if (QSG_LOG_TIME_COMPILATION().isDebugEnabled() || QQuickProfiler::enabled) qsg_renderer_timer.start(); -#endif QSGMaterialShader *s = material->createShader(); QOpenGLContext *ctx = QOpenGLContext::currentContext(); @@ -165,13 +160,10 @@ ShaderManager::Shader *ShaderManager::prepareMaterial(QSGMaterial *material) Q_ASSERT(shader->pos_order >= 0); Q_ASSERT(shader->id_zRange >= 0); -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) - qDebug(" - compiling material: %dms", (int) qsg_renderer_timer.elapsed()); + qCDebug(QSG_LOG_TIME_COMPILATION, "shader compiled in %dms", (int) qsg_renderer_timer.elapsed()); Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphContextFrame, ( qsg_renderer_timer.nsecsElapsed())); -#endif rewrittenShaders[type] = shader; return shader; @@ -184,10 +176,8 @@ ShaderManager::Shader *ShaderManager::prepareMaterialNoRewrite(QSGMaterial *mate if (shader) return shader; -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing || QQuickProfiler::enabled) + if (QSG_LOG_TIME_COMPILATION().isDebugEnabled() || QQuickProfiler::enabled) qsg_renderer_timer.start(); -#endif QSGMaterialShader *s = static_cast(material->createShader()); context->compile(s, material); @@ -201,14 +191,10 @@ ShaderManager::Shader *ShaderManager::prepareMaterialNoRewrite(QSGMaterial *mate stockShaders[type] = shader; -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) - qDebug(" - compiling material: %dms", (int) qsg_renderer_timer.elapsed()); + qCDebug(QSG_LOG_TIME_COMPILATION, "shader compiled in %dms (no rewrite)", (int) qsg_renderer_timer.elapsed()); Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphContextFrame, ( qsg_renderer_timer.nsecsElapsed())); -#endif - return shader; } diff --git a/src/quick/scenegraph/coreapi/qsgrenderer.cpp b/src/quick/scenegraph/coreapi/qsgrenderer.cpp index 4a26eae..d64bd4e 100644 --- a/src/quick/scenegraph/coreapi/qsgrenderer.cpp +++ b/src/quick/scenegraph/coreapi/qsgrenderer.cpp @@ -63,12 +63,9 @@ QT_BEGIN_NAMESPACE static bool qsg_sanity_check = qgetenv("QSG_SANITY_CHECK").toInt(); -#ifndef QSG_NO_RENDER_TIMING -static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty(); static QElapsedTimer frameTimer; static qint64 preprocessTime; static qint64 updatePassTime; -#endif void QSGBindable::clear(QSGRenderer::ClearMode mode) const { @@ -226,22 +223,18 @@ void QSGRenderer::renderScene(const QSGBindable &bindable) m_is_rendering = true; -#ifndef QSG_NO_RENDER_TIMING - bool profileFrames = qsg_render_timing || QQuickProfiler::enabled; + bool profileFrames = QSG_LOG_TIME_RENDERER().isDebugEnabled() || QQuickProfiler::enabled; if (profileFrames) frameTimer.start(); qint64 bindTime = 0; qint64 renderTime = 0; -#endif m_bindable = &bindable; preprocess(); bindable.bind(); -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) bindTime = frameTimer.nsecsElapsed(); -#endif // Sanity check that attribute registers are disabled if (qsg_sanity_check) { @@ -257,10 +250,8 @@ void QSGRenderer::renderScene(const QSGBindable &bindable) } render(); -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) renderTime = frameTimer.nsecsElapsed(); -#endif glDisable(GL_SCISSOR_TEST); m_is_rendering = false; @@ -277,15 +268,13 @@ void QSGRenderer::renderScene(const QSGBindable &bindable) m_index_buffer_bound = false; } -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) { - qDebug(" - Breakdown of render time: preprocess=%d, updates=%d, binding=%d, render=%d, total=%d", - int(preprocessTime / 1000000), - int((updatePassTime - preprocessTime) / 1000000), - int((bindTime - updatePassTime) / 1000000), - int((renderTime - bindTime) / 1000000), - int(renderTime / 1000000)); - } + qCDebug(QSG_LOG_TIME_RENDERER, + "time in renderer: total=%dms, preprocess=%d, updates=%d, binding=%d, rendering=%d", + int(renderTime / 1000000), + int(preprocessTime / 1000000), + int((updatePassTime - preprocessTime) / 1000000), + int((bindTime - updatePassTime) / 1000000), + int((renderTime - bindTime) / 1000000)); Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphRendererFrame, ( preprocessTime, @@ -293,7 +282,6 @@ void QSGRenderer::renderScene(const QSGBindable &bindable) bindTime - updatePassTime, renderTime - bindTime)); -#endif } void QSGRenderer::setProjectionMatrixToDeviceRect() @@ -374,19 +362,14 @@ void QSGRenderer::preprocess() } } -#ifndef QSG_NO_RENDER_TIMING - bool profileFrames = qsg_render_timing || QQuickProfiler::enabled; + bool profileFrames = QSG_LOG_TIME_RENDERER().isDebugEnabled()|| QQuickProfiler::enabled; if (profileFrames) preprocessTime = frameTimer.nsecsElapsed(); -#endif nodeUpdater()->updateStates(m_root_node); -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) updatePassTime = frameTimer.nsecsElapsed(); -#endif - } void QSGRenderer::addNodesToPreprocess(QSGNode *node) diff --git a/src/quick/scenegraph/qsgadaptationlayer.cpp b/src/quick/scenegraph/qsgadaptationlayer.cpp index 17f4ba1..0ac5f23 100644 --- a/src/quick/scenegraph/qsgadaptationlayer.cpp +++ b/src/quick/scenegraph/qsgadaptationlayer.cpp @@ -44,6 +44,7 @@ #include #include #include +#include #include #include #include @@ -53,10 +54,7 @@ QT_BEGIN_NAMESPACE -#ifndef QSG_NO_RENDER_TIMING -static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty(); static QElapsedTimer qsg_render_timer; -#endif QSGDistanceFieldGlyphCache::Texture QSGDistanceFieldGlyphCache::s_emptyTexture; @@ -163,11 +161,9 @@ void QSGDistanceFieldGlyphCache::update() if (m_pendingGlyphs.isEmpty()) return; -#ifndef QSG_NO_RENDER_TIMING - bool profileFrames = qsg_render_timing || QQuickProfiler::enabled; + bool profileFrames = QSG_LOG_TIME_GLYPH().isDebugEnabled() || QQuickProfiler::enabled; if (profileFrames) qsg_render_timer.start(); -#endif QList distanceFields; for (int i = 0; i < m_pendingGlyphs.size(); ++i) { @@ -176,31 +172,28 @@ void QSGDistanceFieldGlyphCache::update() m_doubleGlyphResolution)); } -#ifndef QSG_NO_RENDER_TIMING qint64 renderTime = 0; int count = m_pendingGlyphs.size(); if (profileFrames) renderTime = qsg_render_timer.nsecsElapsed(); -#endif m_pendingGlyphs.reset(); storeGlyphs(distanceFields); -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) { - qDebug(" - glyphs: count=%d, render=%d, store=%d, total=%d", - count, - int(renderTime/1000000), - (int) qsg_render_timer.elapsed() - int(renderTime/1000000), - (int) qsg_render_timer.elapsed()); - + if (QSG_LOG_TIME_GLYPH().isDebugEnabled()) { + quint64 now = qsg_render_timer.elapsed(); + qCDebug(QSG_LOG_TIME_GLYPH, + "distancefield: %d glyphs prepared in %dms, rendering=%d, upload=%d", + count, + (int) now, + int(renderTime / 1000000), + int((now - (renderTime / 1000000)))); } Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphAdaptationLayerFrame, ( count, renderTime, qsg_render_timer.nsecsElapsed() - renderTime)); -#endif } void QSGDistanceFieldGlyphCache::setGlyphsPosition(const QList &glyphs) diff --git a/src/quick/scenegraph/qsgcontext.cpp b/src/quick/scenegraph/qsgcontext.cpp index 9328c30..1a3565b 100644 --- a/src/quick/scenegraph/qsgcontext.cpp +++ b/src/quick/scenegraph/qsgcontext.cpp @@ -50,6 +50,7 @@ #include #include #include +#include #include #include @@ -93,6 +94,30 @@ DEFINE_BOOL_CONFIG_OPTION(qmlDisableDistanceField, QML_DISABLE_DISTANCEFIELD) QT_BEGIN_NAMESPACE +// Used for very high-level info about the renderering and gl context +// Includes GL_VERSION, type of render loop, atlas size, etc. +Q_LOGGING_CATEGORY(QSG_LOG_INFO, "qt.scenegraph.info") + +// Used to debug the renderloop logic. Primarily useful for platform integrators +// and when investigating the render loop logic. +Q_LOGGING_CATEGORY(QSG_LOG_RENDERLOOP, "qt.scenegraph.renderloop") + + +// GLSL shader compilation +Q_LOGGING_CATEGORY(QSG_LOG_TIME_COMPILATION, "qt.scenegraph.time.compilation") + +// polish, animations, sync, render and swap in the render loop +Q_LOGGING_CATEGORY(QSG_LOG_TIME_RENDERLOOP, "qt.scenegraph.time.renderloop") + +// Texture uploads and swizzling +Q_LOGGING_CATEGORY(QSG_LOG_TIME_TEXTURE, "qt.scenegraph.time.texture") + +// Glyph preparation (only for distance fields atm) +Q_LOGGING_CATEGORY(QSG_LOG_TIME_GLYPH, "qt.scenegraph.time.glyph") + +// Timing inside the renderer base class +Q_LOGGING_CATEGORY(QSG_LOG_TIME_RENDERER, "qt.scenegraph.time.renderer") + class QSGContextPrivate : public QObjectPrivate { public: @@ -161,6 +186,15 @@ QSGContext::QSGContext(QObject *parent) : d->distanceFieldAntialiasing = QSGGlyphNode::LowQualitySubPixelAntialiasing; else if (mode == "gray") d->distanceFieldAntialiasing = QSGGlyphNode::GrayAntialiasing; + + // Adds compatibility with Qt 5.3 and earlier's QSG_RENDER_TIMING + if (qEnvironmentVariableIsSet("QSG_RENDER_TIMING")) { + ((QLoggingCategory &) QSG_LOG_TIME_GLYPH()).setEnabled(QtDebugMsg, true); + ((QLoggingCategory &) QSG_LOG_TIME_TEXTURE()).setEnabled(QtDebugMsg, true); + ((QLoggingCategory &) QSG_LOG_TIME_RENDERER()).setEnabled(QtDebugMsg, true); + ((QLoggingCategory &) QSG_LOG_TIME_RENDERLOOP()).setEnabled(QtDebugMsg, true); + ((QLoggingCategory &) QSG_LOG_TIME_COMPILATION()).setEnabled(QtDebugMsg, true); + } } @@ -204,20 +238,20 @@ void QSGContext::renderContextInitialized(QSGRenderContext *renderContext) } static bool dumped = false; - if (!dumped && qEnvironmentVariableIsSet("QSG_INFO")) { + if (!dumped && QSG_LOG_INFO().isDebugEnabled()) { dumped = true; QSurfaceFormat format = renderContext->openglContext()->format(); QOpenGLFunctions *funcs = QOpenGLContext::currentContext()->functions(); - qDebug() << "R/G/B/A Buffers: " << format.redBufferSize() << format.greenBufferSize() << format.blueBufferSize() << format.alphaBufferSize(); - qDebug() << "Depth Buffer: " << format.depthBufferSize(); - qDebug() << "Stencil Buffer: " << format.stencilBufferSize(); - qDebug() << "Samples: " << format.samples(); - qDebug() << "GL_VENDOR: " << (const char *) funcs->glGetString(GL_VENDOR); - qDebug() << "GL_RENDERER: " << (const char *) funcs->glGetString(GL_RENDERER); - qDebug() << "GL_VERSION: " << (const char *) funcs->glGetString(GL_VERSION); + qCDebug(QSG_LOG_INFO) << "R/G/B/A Buffers: " << format.redBufferSize() << format.greenBufferSize() << format.blueBufferSize() << format.alphaBufferSize(); + qCDebug(QSG_LOG_INFO) << "Depth Buffer: " << format.depthBufferSize(); + qCDebug(QSG_LOG_INFO) << "Stencil Buffer: " << format.stencilBufferSize(); + qCDebug(QSG_LOG_INFO) << "Samples: " << format.samples(); + qCDebug(QSG_LOG_INFO) << "GL_VENDOR: " << (const char *) funcs->glGetString(GL_VENDOR); + qCDebug(QSG_LOG_INFO) << "GL_RENDERER: " << (const char *) funcs->glGetString(GL_RENDERER); + qCDebug(QSG_LOG_INFO) << "GL_VERSION: " << (const char *) funcs->glGetString(GL_VERSION); QSet exts = renderContext->openglContext()->extensions(); QByteArray all; foreach (const QByteArray &e, exts) all += ' ' + e; - qDebug() << "GL_EXTENSIONS: " << all.constData(); + qCDebug(QSG_LOG_INFO) << "GL_EXTENSIONS: " << all.constData(); } d->mutex.unlock(); diff --git a/src/quick/scenegraph/qsgcontext_p.h b/src/quick/scenegraph/qsgcontext_p.h index ac372b9..faad57b 100644 --- a/src/quick/scenegraph/qsgcontext_p.h +++ b/src/quick/scenegraph/qsgcontext_p.h @@ -79,6 +79,14 @@ class QQuickTextureFactory; class QSGDistanceFieldGlyphCacheManager; class QSGContext; +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_TIME_RENDERLOOP) +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_TIME_COMPILATION) +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_TIME_TEXTURE) +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_TIME_GLYPH) +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_TIME_RENDERER) + +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_INFO) +Q_DECLARE_LOGGING_CATEGORY(QSG_LOG_RENDERLOOP) class Q_QUICK_PRIVATE_EXPORT QSGRenderContext : public QObject { diff --git a/src/quick/scenegraph/qsgrenderloop.cpp b/src/quick/scenegraph/qsgrenderloop.cpp index 38de4a5..fba2114 100644 --- a/src/quick/scenegraph/qsgrenderloop.cpp +++ b/src/quick/scenegraph/qsgrenderloop.cpp @@ -65,7 +65,6 @@ QT_BEGIN_NAMESPACE -DEFINE_BOOL_CONFIG_OPTION(qsg_render_timing, QSG_RENDER_TIMING) extern Q_GUI_EXPORT QImage qt_gl_read_framebuffer(const QSize &size, bool alpha_format, bool include_alpha); @@ -163,14 +162,16 @@ bool QSGRenderLoop::useConsistentTiming() QSGRenderLoop *QSGRenderLoop::instance() { if (!s_instance) { - s_instance = QSGContext::createWindowManager(); - bool info = qEnvironmentVariableIsSet("QSG_INFO"); + // For compatibility with 5.3 and earlier's QSG_INFO environment variables + if (qEnvironmentVariableIsSet("QSG_INFO")) + ((QLoggingCategory &) QSG_LOG_INFO()).setEnabled(QtDebugMsg, true); + + s_instance = QSGContext::createWindowManager(); if (useConsistentTiming()) { QUnifiedTimer::instance(true)->setConsistentTiming(true); - if (info) - qDebug() << "QSG: using fixed animation steps"; + qCDebug(QSG_LOG_INFO, "using fixed animation steps"); } if (!s_instance) { @@ -204,15 +205,15 @@ QSGRenderLoop *QSGRenderLoop::instance() switch (loopType) { case ThreadedRenderLoop: - if (info) qDebug() << "QSG: threaded render loop"; + qCDebug(QSG_LOG_INFO, "threaded render loop"); s_instance = new QSGThreadedRenderLoop(); break; case WindowsRenderLoop: - if (info) qDebug() << "QSG: windows render loop"; + qCDebug(QSG_LOG_INFO, "windows render loop"); s_instance = new QSGWindowsRenderLoop(); break; default: - if (info) qDebug() << "QSG: basic render loop"; + qCDebug(QSG_LOG_INFO, "QSG: basic render loop"); s_instance = new QSGGuiThreadRenderLoop(); break; } @@ -358,16 +359,19 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window) if (!m_windows.contains(window)) return; } - cd->polishItems(); - - emit window->afterAnimating(); - - qint64 renderTime = 0, syncTime = 0; QElapsedTimer renderTimer; - bool profileFrames = qsg_render_timing() || QQuickProfiler::enabled; + qint64 renderTime = 0, syncTime = 0, polishTime = 0; + bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled() || QQuickProfiler::enabled; if (profileFrames) renderTimer.start(); + cd->polishItems(); + + if (profileFrames) + polishTime = renderTimer.nsecsElapsed(); + + emit window->afterAnimating(); + cd->syncSceneGraph(); if (profileFrames) @@ -376,7 +380,7 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window) cd->renderSceneGraph(window->size()); if (profileFrames) - renderTime = renderTimer.nsecsElapsed() - syncTime; + renderTime = renderTimer.nsecsElapsed(); if (data.grabOnly) { grabContent = qt_gl_read_framebuffer(window->size() * window->devicePixelRatio(), false, false); @@ -389,23 +393,25 @@ void QSGGuiThreadRenderLoop::renderWindow(QQuickWindow *window) } qint64 swapTime = 0; - if (profileFrames) { - swapTime = renderTimer.nsecsElapsed() - renderTime - syncTime; - } + if (profileFrames) + swapTime = renderTimer.nsecsElapsed() - renderTime; - if (qsg_render_timing()) { + if (QSG_LOG_TIME_RENDERLOOP().isDebugEnabled()) { static QTime lastFrameTime = QTime::currentTime(); - 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"; + qCDebug(QSG_LOG_TIME_RENDERLOOP, + "Frame rendered with 'basic' renderloop in %dms, polish=%d, sync=%d, render=%d, swap=%d, frameDelta=%d", + int(swapTime / 1000000), + int(polishTime / 1000000), + int((syncTime - polishTime) / 1000000), + int((renderTime - syncTime) / 1000000), + int((swapTime - renderTime) / 10000000), + int(lastFrameTime.msecsTo(QTime::currentTime()))); lastFrameTime = QTime::currentTime(); } Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphRenderLoopFrame, ( syncTime, - renderTime, + renderTime - syncTime, swapTime)); // Might have been set during syncSceneGraph() diff --git a/src/quick/scenegraph/qsgthreadedrenderloop.cpp b/src/quick/scenegraph/qsgthreadedrenderloop.cpp index f8771e6..106819e 100644 --- a/src/quick/scenegraph/qsgthreadedrenderloop.cpp +++ b/src/quick/scenegraph/qsgthreadedrenderloop.cpp @@ -111,18 +111,7 @@ QT_BEGIN_NAMESPACE - -// #define QSG_RENDER_LOOP_DEBUG - -#if defined (QSG_RENDER_LOOP_DEBUG) -QElapsedTimer qsgrl_timer; -# define QSG_RT_DEBUG(MSG) qDebug("(%6d) line=%4d - win=%10p): Render: %s", (int) qsgrl_timer.elapsed(), __LINE__, window, MSG); -# define QSG_GUI_DEBUG(WIN, MSG) qDebug("(%6d) line=%4d - win=%10p): Gui: %s", (int) qsgrl_timer.elapsed(), __LINE__, WIN, MSG); -#else -# define QSG_RT_DEBUG(MSG) -# define QSG_GUI_DEBUG(WIN,MSG) -#endif - +#define QSG_RT_PAD " (RT)" static int get_env_int(const char *name, int defaultValue) { @@ -144,13 +133,10 @@ static inline int qsgrl_animation_interval() { } -#ifndef QSG_NO_RENDER_TIMING -static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty(); 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); @@ -318,7 +304,7 @@ public: public slots: void sceneGraphChanged() { - QSG_RT_DEBUG("sceneGraphChanged()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "sceneGraphChanged"; syncResultedInChanges = true; } @@ -361,14 +347,14 @@ bool QSGRenderThread::event(QEvent *e) switch ((int) e->type()) { case WM_Obscure: { - QSG_RT_DEBUG("WM_Obscure"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "WM_Obscure"; Q_ASSERT(!window || window == static_cast(e)->window); mutex.lock(); if (window) { QQuickWindowPrivate::get(window)->fireAboutToStop(); - QSG_RT_DEBUG(" - removed window..."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- window removed"; gl->doneCurrent(); window = 0; } @@ -378,7 +364,7 @@ bool QSGRenderThread::event(QEvent *e) return true; } case WM_RequestSync: { - QSG_RT_DEBUG("WM_RequestSync"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "WM_RequestSync"; WMSyncEvent *se = static_cast(e); if (sleeping) stopEventProcessing = true; @@ -387,25 +373,25 @@ bool QSGRenderThread::event(QEvent *e) pendingUpdate |= SyncRequest; if (se->syncInExpose) { - QSG_RT_DEBUG(" - triggered from expose"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- triggered from expose"; pendingUpdate |= ExposeRequest; } return true; } case WM_TryRelease: { - QSG_RT_DEBUG("WM_TryRelease"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "WM_TryRelease"; mutex.lock(); wm->m_lockedForSync = true; WMTryReleaseEvent *wme = static_cast(e); if (!window || wme->inDestructor) { - QSG_RT_DEBUG(" - setting exit flag and invalidating GL"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- setting exit flag and invalidating OpenGL"; invalidateOpenGL(wme->window, wme->inDestructor, wme->fallbackSurface); active = gl; Q_ASSERT_X(!wme->inDestructor || !active, "QSGRenderThread::invalidateOpenGL()", "Thread's active state is not set to false when shutting down"); if (sleeping) stopEventProcessing = true; } else { - QSG_RT_DEBUG(" - not releasing anything because we have active windows..."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- not releasing because window is still active"; } waitCondition.wakeOne(); wm->m_lockedForSync = false; @@ -414,30 +400,31 @@ bool QSGRenderThread::event(QEvent *e) } case WM_Grab: { - QSG_RT_DEBUG("WM_Grab"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "WM_Grab"; WMGrabEvent *ce = static_cast(e); Q_ASSERT(ce->window == window); mutex.lock(); if (window) { gl->makeCurrent(window); - QSG_RT_DEBUG(" - syncing scene graph"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- sync scene graph"; QQuickWindowPrivate *d = QQuickWindowPrivate::get(window); d->syncSceneGraph(); - QSG_RT_DEBUG(" - rendering scene graph"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- rendering scene graph"; QQuickWindowPrivate::get(window)->renderSceneGraph(windowSize); - QSG_RT_DEBUG(" - grabbing result..."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- grabbing result"; *ce->image = qt_gl_read_framebuffer(windowSize * window->devicePixelRatio(), false, false); } - QSG_RT_DEBUG(" - waking gui to handle grab result"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- waking gui to handle result"; waitCondition.wakeOne(); mutex.unlock(); return true; } case WM_RequestRepaint: + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "WM_RequestPaint"; // When GUI posts this event, it is followed by a polishAndSync, so we mustn't // exit the event loop yet. pendingUpdate |= RepaintRequest; @@ -451,13 +438,13 @@ bool QSGRenderThread::event(QEvent *e) void QSGRenderThread::invalidateOpenGL(QQuickWindow *window, bool inDestructor, QOffscreenSurface *fallback) { - QSG_RT_DEBUG("invalidateOpenGL()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "invalidateOpenGL()"; if (!gl) return; if (!window) { - qWarning("QSGThreadedRenderLoop:QSGRenderThread: no window to make current..."); + qCWarning(QSG_LOG_RENDERLOOP()) << "QSGThreadedRenderLoop:QSGRenderThread: no window to make current..."; return; } @@ -467,7 +454,7 @@ void QSGRenderThread::invalidateOpenGL(QQuickWindow *window, bool inDestructor, bool current = gl->makeCurrent(fallback ? static_cast(fallback) : static_cast(window)); if (Q_UNLIKELY(!current)) { - QSG_RT_DEBUG(" - cleanup without an OpenGL context"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- cleanup without an OpenGL context"; } // The canvas nodes must be cleaned up regardless if we are in the destructor.. @@ -475,7 +462,7 @@ void QSGRenderThread::invalidateOpenGL(QQuickWindow *window, bool inDestructor, QQuickWindowPrivate *dd = QQuickWindowPrivate::get(window); dd->cleanupNodesOnShutdown(); } else { - QSG_RT_DEBUG(" - persistent SG, avoiding cleanup"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- persistent SG, avoiding cleanup"; if (current) gl->doneCurrent(); return; @@ -486,14 +473,14 @@ void QSGRenderThread::invalidateOpenGL(QQuickWindow *window, bool inDestructor, QCoreApplication::sendPostedEvents(0, QEvent::DeferredDelete); if (current) gl->doneCurrent(); - QSG_RT_DEBUG(" - invalidated scenegraph.."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- invalidating scene graph"; if (wipeGL) { delete gl; gl = 0; - QSG_RT_DEBUG(" - invalidated OpenGL"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- invalidated OpenGL"; } else { - QSG_RT_DEBUG(" - persistent GL, avoiding cleanup"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- persistent GL, avoiding cleanup"; } } @@ -503,7 +490,7 @@ void QSGRenderThread::invalidateOpenGL(QQuickWindow *window, bool inDestructor, */ void QSGRenderThread::sync(bool inExpose) { - QSG_RT_DEBUG("sync()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "sync()"; mutex.lock(); Q_ASSERT_X(wm->m_lockedForSync, "QSGRenderThread::sync()", "sync triggered on bad terms as gui is not already locked..."); @@ -520,7 +507,7 @@ void QSGRenderThread::sync(bool inExpose) d->renderer->clearChangedFlag(); d->syncSceneGraph(); if (!hadRenderer && d->renderer) { - QSG_RT_DEBUG(" - renderer was created, hooking up changed signal"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- renderer was created"; syncResultedInChanges = true; connect(d->renderer, SIGNAL(sceneGraphChanged()), this, SLOT(sceneGraphChanged()), Qt::DirectConnection); } @@ -530,11 +517,11 @@ void QSGRenderThread::sync(bool inExpose) // and the delete is a safe operation. QCoreApplication::sendPostedEvents(0, QEvent::DeferredDelete); } else { - QSG_RT_DEBUG(" - window has bad size, waiting..."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- window has bad size, sync aborted"; } if (!inExpose) { - QSG_RT_DEBUG(" - sync complete, waking GUI"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- sync complete, waking Gui"; waitCondition.wakeOne(); mutex.unlock(); } @@ -542,17 +529,16 @@ void QSGRenderThread::sync(bool inExpose) void QSGRenderThread::syncAndRender() { -#ifndef QSG_NO_RENDER_TIMING - bool profileFrames = qsg_render_timing || QQuickProfiler::enabled; + bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled() || QQuickProfiler::enabled; if (profileFrames) { sinceLastTime = threadTimer.nsecsElapsed(); threadTimer.start(); } -#endif + QElapsedTimer waitTimer; waitTimer.start(); - QSG_RT_DEBUG("syncAndRender()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "syncAndRender()"; syncResultedInChanges = false; @@ -560,23 +546,22 @@ void QSGRenderThread::syncAndRender() pendingUpdate = 0; if (pending & SyncRequest) { - QSG_RT_DEBUG(" - update pending, doing sync"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- updatePending, doing sync"; sync(pending == ExposeRequest); } if (!syncResultedInChanges && ((pending & RepaintRequest) == 0)) { - QSG_RT_DEBUG(" - no changes, rendering aborted"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- no changes, render aborted"; int waitTime = vsyncDelta - (int) waitTimer.elapsed(); if (waitTime > 0) msleep(waitTime); return; } -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) syncTime = threadTimer.nsecsElapsed(); -#endif - QSG_RT_DEBUG(" - rendering starting"); + + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- rendering started"; QQuickWindowPrivate *d = QQuickWindowPrivate::get(window); @@ -591,17 +576,15 @@ void QSGRenderThread::syncAndRender() current = gl->makeCurrent(window); if (current) { d->renderSceneGraph(windowSize); -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) renderTime = threadTimer.nsecsElapsed(); -#endif gl->swapBuffers(window); d->fireFrameSwapped(); } else { - QSG_RT_DEBUG(" - Window not yet ready, skipping render..."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- window not ready, skipping render"; } - QSG_RT_DEBUG(" - rendering done"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- rendering done"; // Though it would be more correct to put this block directly after // fireFrameSwapped in the if (current) branch above, we don't do @@ -609,25 +592,23 @@ void QSGRenderThread::syncAndRender() // has started rendering with a bad window, causing makeCurrent to // fail or if the window has a bad size. if (pending == ExposeRequest) { - QSG_RT_DEBUG(" - waking GUI after expose"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "- wake Gui after initial expose"; waitCondition.wakeOne(); mutex.unlock(); } -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) - qDebug("Render Thread: window=%p, framedelta=%d, sync=%d, first render=%d, after final swap=%d", - window, - int(sinceLastTime/1000000), - int(syncTime/1000000), - int((renderTime - syncTime)/1000000), - int(threadTimer.elapsed() - renderTime/1000000)); + qCDebug(QSG_LOG_TIME_RENDERLOOP, + "Frame rendered with 'threaded' renderloop in %dms, sync=%d, render=%d, swap=%d - (on render thread)", + int(threadTimer.elapsed()), + int((syncTime/1000000)), + int((renderTime - syncTime) / 1000000), + int(threadTimer.elapsed() - renderTime / 1000000)); + Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphRenderLoopFrame, ( syncTime, renderTime - syncTime, threadTimer.nsecsElapsed() - renderTime)); -#endif } @@ -641,30 +622,30 @@ void QSGRenderThread::postEvent(QEvent *e) void QSGRenderThread::processEvents() { - QSG_RT_DEBUG("processEvents()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "--- begin processEvents()"; while (eventQueue.hasMoreEvents()) { QEvent *e = eventQueue.takeEvent(false); event(e); delete e; } - QSG_RT_DEBUG(" - done with processEvents()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "--- done processEvents()"; } void QSGRenderThread::processEventsAndWaitForMore() { - QSG_RT_DEBUG("processEventsAndWaitForMore()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "--- begin processEventsAndWaitForMore()"; stopEventProcessing = false; while (!stopEventProcessing) { QEvent *e = eventQueue.takeEvent(true); event(e); delete e; } - QSG_RT_DEBUG(" - done with processEventsAndWaitForMore()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "--- done processEventsAndWaitForMore()"; } void QSGRenderThread::run() { - QSG_RT_DEBUG("run()"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "run()"; animatorDriver = sgrc->sceneGraphContext()->createAnimationDriver(0); animatorDriver->install(); QUnifiedTimer::instance(true)->setConsistentTiming(QSGRenderLoop::useConsistentTiming()); @@ -683,7 +664,7 @@ void QSGRenderThread::run() QCoreApplication::processEvents(); if (active && (pendingUpdate == 0 || !window)) { - QSG_RT_DEBUG("enter event loop (going to sleep)"); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "done drawing, sleep..."; sleeping = true; processEventsAndWaitForMore(); sleeping = false; @@ -692,7 +673,7 @@ void QSGRenderThread::run() Q_ASSERT_X(!gl, "QSGRenderThread::run()", "The OpenGL context should be cleaned up before exiting the render thread..."); - QSG_RT_DEBUG("run() completed..."); + qCDebug(QSG_LOG_RENDERLOOP) << QSG_RT_PAD << "run() completed"; delete animatorDriver; animatorDriver = 0; @@ -717,7 +698,6 @@ QSGThreadedRenderLoop::QSGThreadedRenderLoop() connect(m_animation_driver, SIGNAL(stopped()), this, SLOT(animationStopped())); m_animation_driver->install(); - QSG_GUI_DEBUG((void *) 0, "QSGThreadedRenderLoop() created"); } QSGRenderContext *QSGThreadedRenderLoop::createRenderContext(QSGContext *sg) const @@ -728,7 +708,7 @@ QSGRenderContext *QSGThreadedRenderLoop::createRenderContext(QSGContext *sg) con void QSGThreadedRenderLoop::maybePostPolishRequest(Window *w) { if (w->timerId == 0) { - QSG_GUI_DEBUG(w->window, " - posting update"); + qCDebug(QSG_LOG_RENDERLOOP) << "- posting update"; w->timerId = startTimer(m_exhaust_delay, Qt::PreciseTimer); } } @@ -760,7 +740,7 @@ bool QSGThreadedRenderLoop::interleaveIncubation() const void QSGThreadedRenderLoop::animationStarted() { - QSG_GUI_DEBUG((void *) 0, "animationStarted()"); + qCDebug(QSG_LOG_RENDERLOOP) << "- animationStarted()"; startOrStopAnimationTimer(); for (int i=0; iisExposed()) handleObscurity(windowFor(m_windows, window)); @@ -827,7 +807,7 @@ void QSGThreadedRenderLoop::hide(QQuickWindow *window) */ void QSGThreadedRenderLoop::windowDestroyed(QQuickWindow *window) { - QSG_GUI_DEBUG(window, "windowDestroyed()"); + qCDebug(QSG_LOG_RENDERLOOP) << "begin windowDestroyed()" << window; Window *w = windowFor(m_windows, window); if (!w) @@ -849,13 +829,13 @@ void QSGThreadedRenderLoop::windowDestroyed(QQuickWindow *window) } } - QSG_GUI_DEBUG(window, " - done with windowDestroyed()"); + qCDebug(QSG_LOG_RENDERLOOP) << "done windowDestroyed()" << window; } void QSGThreadedRenderLoop::exposureChanged(QQuickWindow *window) { - QSG_GUI_DEBUG(window, "exposureChanged()"); + qCDebug(QSG_LOG_RENDERLOOP) << "exposureChanged()" << window; if (window->isExposed()) { handleExposure(window); } else { @@ -871,11 +851,11 @@ void QSGThreadedRenderLoop::exposureChanged(QQuickWindow *window) */ void QSGThreadedRenderLoop::handleExposure(QQuickWindow *window) { - QSG_GUI_DEBUG(window, "handleExposure"); + qCDebug(QSG_LOG_RENDERLOOP) << "handleExposure()" << window; Window *w = windowFor(m_windows, window); if (!w) { - QSG_GUI_DEBUG(window, " - adding window to list"); + qCDebug(QSG_LOG_RENDERLOOP) << "- adding window to list"; Window win; win.window = window; win.actualWindowFormat = window->format(); @@ -905,7 +885,7 @@ void QSGThreadedRenderLoop::handleExposure(QQuickWindow *window) // Start render thread if it is not running if (!w->thread->isRunning()) { - QSG_GUI_DEBUG(w->window, " - starting render thread..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- starting render thread"; if (!w->thread->gl) { w->thread->gl = new QOpenGLContext(); @@ -923,7 +903,7 @@ void QSGThreadedRenderLoop::handleExposure(QQuickWindow *window) QQuickWindowPrivate::get(w->window)->fireOpenGLContextCreated(w->thread->gl); w->thread->gl->moveToThread(w->thread); - QSG_GUI_DEBUG(w->window, " - OpenGL context created..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- OpenGL context created"; } QQuickAnimatorController *controller = QQuickWindowPrivate::get(w->window)->animationController; @@ -938,11 +918,11 @@ void QSGThreadedRenderLoop::handleExposure(QQuickWindow *window) w->thread->start(); } else { - QSG_GUI_DEBUG(w->window, " - render thread already running"); + qCDebug(QSG_LOG_RENDERLOOP) << "- render thread already running"; } polishAndSync(w, true); - QSG_GUI_DEBUG(w->window, " - handleExposure completed..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- done with handleExposure()"; startOrStopAnimationTimer(); } @@ -956,7 +936,7 @@ void QSGThreadedRenderLoop::handleExposure(QQuickWindow *window) */ void QSGThreadedRenderLoop::handleObscurity(Window *w) { - QSG_GUI_DEBUG(w->window, "handleObscurity"); + qCDebug(QSG_LOG_RENDERLOOP) << "handleObscurity()" << w->window; if (w->thread->isRunning()) { w->thread->mutex.lock(); w->thread->postEvent(new WMWindowEvent(w->window, WM_Obscure)); @@ -989,15 +969,15 @@ void QSGThreadedRenderLoop::maybeUpdate(Window *w) return; } - QSG_GUI_DEBUG(w->window, "maybeUpdate..."); if (!w || !w->thread->isRunning()) { return; } + qCDebug(QSG_LOG_RENDERLOOP) << "update from item" << w->window; // Call this function from the Gui thread later as startTimer cannot be // called from the render thread. if (QThread::currentThread() == w->thread) { - QSG_GUI_DEBUG(w->window, " - on render thread, will update later.."); + qCDebug(QSG_LOG_RENDERLOOP) << "- on render thread"; w->updateDuringSync = true; return; } @@ -1017,12 +997,12 @@ void QSGThreadedRenderLoop::update(QQuickWindow *window) return; if (w->thread == QThread::currentThread()) { - QSG_RT_DEBUG("QQuickWindow::update called on render thread"); + qCDebug(QSG_LOG_RENDERLOOP) << "update on window - on render thread" << w->window; w->thread->requestRepaint(); return; } - QSG_GUI_DEBUG(w->window, "update called"); + qCDebug(QSG_LOG_RENDERLOOP) << "update on window" << w->window; w->thread->postEvent(new QEvent(WM_RequestRepaint)); maybeUpdate(w); } @@ -1041,7 +1021,7 @@ void QSGThreadedRenderLoop::releaseResources(QQuickWindow *window) */ void QSGThreadedRenderLoop::releaseResources(Window *w, bool inDestructor) { - QSG_GUI_DEBUG(w->window, "releaseResources requested..."); + qCDebug(QSG_LOG_RENDERLOOP) << "releaseResources()" << (inDestructor ? "in destructor" : "in api-call") << w->window; w->thread->mutex.lock(); if (w->thread->isRunning() && w->thread->active) { @@ -1055,13 +1035,13 @@ void QSGThreadedRenderLoop::releaseResources(Window *w, bool inDestructor) // create it here and pass it on to QSGRenderThread::invalidateGL() QOffscreenSurface *fallback = 0; if (!window->handle()) { - QSG_GUI_DEBUG(window, " - using fallback surface"); + qCDebug(QSG_LOG_RENDERLOOP) << "- using fallback surface"; fallback = new QOffscreenSurface(); fallback->setFormat(w->actualWindowFormat); fallback->create(); } - QSG_GUI_DEBUG(window, " - posting release request to render thread"); + qCDebug(QSG_LOG_RENDERLOOP) << "- posting release request to render thread"; w->thread->postEvent(new WMTryReleaseEvent(window, inDestructor, fallback)); w->thread->waitCondition.wait(&w->thread->mutex); delete fallback; @@ -1075,11 +1055,11 @@ void QSGThreadedRenderLoop::releaseResources(Window *w, bool inDestructor) */ void QSGThreadedRenderLoop::polishAndSync(Window *w, bool inExpose) { - QSG_GUI_DEBUG(w->window, "polishAndSync()"); + qCDebug(QSG_LOG_RENDERLOOP) << "polishAndSync" << (inExpose ? "(in expose)" : "(normal)") << w->window; QQuickWindow *window = w->window; if (!w->thread || !w->thread->window) { - QSG_GUI_DEBUG(w->window, " - not exposed, aborting..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- not exposed, abort"; killTimer(w->timerId); w->timerId = 0; return; @@ -1098,62 +1078,54 @@ void QSGThreadedRenderLoop::polishAndSync(Window *w, bool inExpose) w = windowFor(m_windows, window); } if (!w || !w->thread || !w->thread->window) { - QSG_GUI_DEBUG(w->window, " - removed after event flushing.."); + qCDebug(QSG_LOG_RENDERLOOP) << "- removed after event flushing, abort"; killTimer(w->timerId); w->timerId = 0; return; } -#ifndef QSG_NO_RENDER_TIMING QElapsedTimer timer; qint64 polishTime = 0; qint64 waitTime = 0; qint64 syncTime = 0; - bool profileFrames = qsg_render_timing || QQuickProfiler::enabled; + bool profileFrames = QSG_LOG_TIME_RENDERLOOP().isDebugEnabled() || QQuickProfiler::enabled; if (profileFrames) timer.start(); -#endif QQuickWindowPrivate *d = QQuickWindowPrivate::get(window); d->polishItems(); -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) polishTime = timer.nsecsElapsed(); -#endif w->updateDuringSync = false; emit window->afterAnimating(); - QSG_GUI_DEBUG(window, " - lock for sync..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- lock for sync"; w->thread->mutex.lock(); m_lockedForSync = true; w->thread->postEvent(new WMSyncEvent(window, inExpose)); - QSG_GUI_DEBUG(window, " - wait for sync..."); -#ifndef QSG_NO_RENDER_TIMING + qCDebug(QSG_LOG_RENDERLOOP) << "- wait for sync"; if (profileFrames) waitTime = timer.nsecsElapsed(); -#endif w->thread->waitCondition.wait(&w->thread->mutex); m_lockedForSync = false; w->thread->mutex.unlock(); - QSG_GUI_DEBUG(window, " - unlocked after sync..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- unlock after sync"; -#ifndef QSG_NO_RENDER_TIMING if (profileFrames) syncTime = timer.nsecsElapsed(); -#endif killTimer(w->timerId); w->timerId = 0; if (m_animation_timer == 0 && m_animation_driver->isRunning()) { - QSG_GUI_DEBUG(window, " - animations advancing"); + qCDebug(QSG_LOG_RENDERLOOP) << "- advancing animations"; m_animation_driver->advance(); - QSG_GUI_DEBUG(window, " - animations done"); + qCDebug(QSG_LOG_RENDERLOOP) << "- animations done.."; // We need to trigger another sync to keep animations running... maybePostPolishRequest(w); emit timeToIncubate(); @@ -1161,22 +1133,19 @@ void QSGThreadedRenderLoop::polishAndSync(Window *w, bool inExpose) maybePostPolishRequest(w); } - -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) - qDebug(" - Gui Thread: window=%p, polish=%d, lock=%d, block/sync=%d -- animations=%d", - window, - int(polishTime/1000000), - int((waitTime - polishTime)/1000000), - int((syncTime - waitTime)/1000000), - int((timer.nsecsElapsed() - syncTime)/1000000)); + qCDebug(QSG_LOG_TIME_RENDERLOOP()).nospace() + << "Frame prepared with 'threaded' renderloop" + << ", polish=" << (polishTime / 1000000) + << ", lock=" << (waitTime - polishTime) / 1000000 + << ", blockedForSync=" << (syncTime - waitTime) / 1000000 + << ", animations=" << (timer.nsecsElapsed() - syncTime) / 1000000 + << " - (on Gui thread) " << window; Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphPolishAndSync, ( polishTime, waitTime - polishTime, syncTime - waitTime, timer.nsecsElapsed() - syncTime)); -#endif } QSGThreadedRenderLoop::Window *QSGThreadedRenderLoop::windowForTimer(int timerId) const @@ -1197,11 +1166,11 @@ bool QSGThreadedRenderLoop::event(QEvent *e) case QEvent::Timer: { QTimerEvent *te = static_cast(e); if (te->timerId() == m_animation_timer) { - QSG_GUI_DEBUG((void *) 0, "QEvent::Timer -> non-visual animation"); + qCDebug(QSG_LOG_RENDERLOOP) << "- ticking non-visual timer"; m_animation_driver->advance(); emit timeToIncubate(); } else { - QSG_GUI_DEBUG((void *) 0, "QEvent::Timer -> Polish & Sync"); + qCDebug(QSG_LOG_RENDERLOOP) << "- polish and sync timer"; Window *w = windowForTimer(te->timerId()); if (w) polishAndSync(w); @@ -1232,7 +1201,7 @@ bool QSGThreadedRenderLoop::event(QEvent *e) QImage QSGThreadedRenderLoop::grab(QQuickWindow *window) { - QSG_GUI_DEBUG(window, "grab"); + qCDebug(QSG_LOG_RENDERLOOP) << "grab()" << window; Window *w = windowFor(m_windows, window); Q_ASSERT(w); @@ -1243,19 +1212,18 @@ QImage QSGThreadedRenderLoop::grab(QQuickWindow *window) if (!window->handle()) window->create(); - QSG_GUI_DEBUG(w->window, " - polishing items..."); + qCDebug(QSG_LOG_RENDERLOOP) << "- polishing items"; QQuickWindowPrivate *d = QQuickWindowPrivate::get(window); d->polishItems(); QImage result; w->thread->mutex.lock(); - QSG_GUI_DEBUG(w->window, " - locking, posting grab event"); + qCDebug(QSG_LOG_RENDERLOOP) << "- posting grab event"; w->thread->postEvent(new WMGrabEvent(window, &result)); w->thread->waitCondition.wait(&w->thread->mutex); - QSG_GUI_DEBUG(w->window, " - locking, grab done, unlocking"); w->thread->mutex.unlock(); - QSG_GUI_DEBUG(w->window, " - grab complete"); + qCDebug(QSG_LOG_RENDERLOOP) << "- grab complete"; return result; } diff --git a/src/quick/scenegraph/qsgwindowsrenderloop.cpp b/src/quick/scenegraph/qsgwindowsrenderloop.cpp index dc12d00..5961c96 100644 --- a/src/quick/scenegraph/qsgwindowsrenderloop.cpp +++ b/src/quick/scenegraph/qsgwindowsrenderloop.cpp @@ -58,22 +58,13 @@ QT_BEGIN_NAMESPACE extern Q_GUI_EXPORT QImage qt_gl_read_framebuffer(const QSize &size, bool alpha_format, bool include_alpha); -// #define QSG_RENDER_LOOP_DEBUG +#define RLDEBUG(x) qCDebug(QSG_LOG_RENDERLOOP) << x; -#ifdef QSG_RENDER_LOOP_DEBUG -static QElapsedTimer qsg_debug_timer; -# define RLDEBUG(x) qDebug("(%6d) %s : %4d - %s", (int) qsg_debug_timer.elapsed(), __FILE__, __LINE__, x) -#else -# define RLDEBUG(x) -#endif - -#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) qint64 sampleName = 0; if (qsg_render_timing || QQuickProfiler::enabled) sampleName = qsg_render_timer.nsecsElapsed() -#else -#define QSG_RENDER_TIMING_SAMPLE(sampleName) -#endif +#define QSG_RENDER_TIMING_SAMPLE(sampleName) \ + qint64 sampleName = 0; \ + if (QSG_LOG_TIME_RENDERLOOP().isDebugEnabled() || QQuickProfiler::enabled) \ + sampleName = qsg_render_timer.nsecsElapsed() QSGWindowsRenderLoop::QSGWindowsRenderLoop() @@ -82,10 +73,6 @@ QSGWindowsRenderLoop::QSGWindowsRenderLoop() , m_updateTimer(0) , m_animationTimer(0) { -#ifdef QSG_RENDER_LOOP_DEBUG - qsg_debug_timer.start(); -#endif - m_rc = m_sg->createRenderContext(); m_animationDriver = m_sg->createAnimationDriver(m_sg); @@ -100,9 +87,7 @@ QSGWindowsRenderLoop::QSGWindowsRenderLoop() RLDEBUG("Windows Render Loop created"); -#ifndef QSG_NO_RENDER_TIMIMG qsg_render_timer.start(); -#endif } QSGWindowsRenderLoop::~QSGWindowsRenderLoop() @@ -174,8 +159,6 @@ void QSGWindowsRenderLoop::show(QQuickWindow *window) // By preparing the GL context here, it is feasible (if the app // is quick enough) to have a perfect first frame. if (!m_gl) { - QSG_RENDER_TIMING_SAMPLE(time_start); - RLDEBUG(" - creating GL context"); m_gl = new QOpenGLContext(); m_gl->setFormat(window->requestedFormat()); @@ -192,27 +175,11 @@ void QSGWindowsRenderLoop::show(QQuickWindow *window) QQuickWindowPrivate::get(window)->fireOpenGLContextCreated(m_gl); - QSG_RENDER_TIMING_SAMPLE(time_created); RLDEBUG(" - making current"); bool current = m_gl->makeCurrent(window); RLDEBUG(" - initializing SG"); - QSG_RENDER_TIMING_SAMPLE(time_current); if (current) m_rc->initialize(m_gl); - -#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)/1000000), - int((time_current - time_created)/1000000), - int((qsg_render_timer.nsecsElapsed() - time_current)/1000000)); - } - Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphWindowsRenderShow, ( - time_created - time_start, - time_current - time_created, - qsg_render_timer.nsecsElapsed() - time_current)); -#endif - } WindowData data; @@ -405,14 +372,12 @@ void QSGWindowsRenderLoop::render() m_animationDriver->advance(); RLDEBUG("animations advanced"); -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) { - qDebug("WindowsRenderLoop: animations=%d ms", - int((qsg_render_timer.nsecsElapsed() - time_start)/1000000)); - } + qCDebug(QSG_LOG_TIME_RENDERLOOP, + "animations ticked in %dms", + int((qsg_render_timer.nsecsElapsed() - time_start)/1000000)); + Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphWindowsAnimations, ( qsg_render_timer.nsecsElapsed() - time_start)); -#endif // It is not given that animations triggered another maybeUpdate() // and thus another render pass, so to keep things running, @@ -470,16 +435,13 @@ void QSGWindowsRenderLoop::renderWindow(QQuickWindow *window) RLDEBUG(" - frameDone"); d->fireFrameSwapped(); -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) { - 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)/1000000), - int((time_synced - time_polished)/1000000), - int((time_rendered - time_synced)/1000000), - int((time_swapped - time_rendered)/1000000)); - } + qCDebug(QSG_LOG_TIME_RENDERLOOP()).nospace() + << "Frame rendered with 'windows' renderloop in: " << time_swapped << "ms" + << ", polish=" << (time_polished - time_start) / 1000000 + << ", sync=" << (time_synced - time_polished) / 1000000 + << ", render=" << (time_rendered - time_synced) / 1000000 + << ", swap=" << (time_swapped - time_rendered) / 1000000 + << " - " << window; Q_QUICK_SG_PROFILE2(QQuickProfiler::SceneGraphWindowsPolishFrame, QQuickProfiler::SceneGraphRenderLoopFrame, ( @@ -487,7 +449,6 @@ void QSGWindowsRenderLoop::renderWindow(QQuickWindow *window) time_rendered - time_synced, time_swapped - time_rendered, time_polished - time_start)); -#endif } QT_END_NAMESPACE diff --git a/src/quick/scenegraph/util/qsgatlastexture.cpp b/src/quick/scenegraph/util/qsgatlastexture.cpp index ae9390a..fcd10ee 100644 --- a/src/quick/scenegraph/util/qsgatlastexture.cpp +++ b/src/quick/scenegraph/util/qsgatlastexture.cpp @@ -62,10 +62,7 @@ QT_BEGIN_NAMESPACE #endif -#ifndef QSG_NO_RENDER_TIMING -static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty(); static QElapsedTimer qsg_renderer_timer; -#endif namespace QSGAtlasTexture { @@ -116,8 +113,7 @@ Manager::Manager() m_atlas_size_limit = qsg_envInt("QSG_ATLAS_SIZE_LIMIT", qMax(w, h) / 2); m_atlas_size = QSize(w, h); - if (qEnvironmentVariableIsSet("QSG_INFO")) - qDebug() << "QSG: texture atlas dimensions:" << w << "x" << h; + qCDebug(QSG_LOG_INFO, "texture atlas dimensions: %dx%d", w, h); } @@ -388,11 +384,9 @@ void Atlas::bind(QSGTexture::Filtering filtering) // Upload all pending images.. for (int i=0; iimage().width(), - m_pending_uploads.at(i)->image().height(), - (int) (qsg_renderer_timer.elapsed())); - } + qCDebug(QSG_LOG_TIME_TEXTURE).nospace() << "atlastexture uploaded in: " << qsg_renderer_timer.elapsed() + << "ms (" << m_pending_uploads.at(i)->image().width() << "x" + << m_pending_uploads.at(i)->image().height() << ")"; Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphTexturePrepare, ( 0, // bind (not relevant) @@ -415,7 +405,6 @@ void Atlas::bind(QSGTexture::Filtering filtering) 0, // swizzle (not relevant) qsg_renderer_timer.nsecsElapsed(), // (upload all of the above) 0)); // mipmap (not used ever...) -#endif } GLenum f = filtering == QSGTexture::Nearest ? GL_NEAREST : GL_LINEAR; diff --git a/src/quick/scenegraph/util/qsgtexture.cpp b/src/quick/scenegraph/util/qsgtexture.cpp index 882c78b..995bfc1 100644 --- a/src/quick/scenegraph/util/qsgtexture.cpp +++ b/src/quick/scenegraph/util/qsgtexture.cpp @@ -65,14 +65,12 @@ #include #endif +static QElapsedTimer qsg_renderer_timer; + #ifndef QT_NO_DEBUG static bool qsg_leak_check = !qgetenv("QML_LEAK_CHECK").isEmpty(); #endif -#ifndef QSG_NO_RENDER_TIMING -static bool qsg_render_timing = !qgetenv("QSG_RENDER_TIMING").isEmpty(); -static QElapsedTimer qsg_renderer_timer; -#endif #ifndef GL_BGRA #define GL_BGRA 0x80E1 @@ -616,25 +614,19 @@ void QSGPlainTexture::bind() m_dirty_texture = false; -#ifndef QSG_NO_RENDER_TIMING - bool profileFrames = qsg_render_timing || QQuickProfiler::enabled; + bool profileFrames = QSG_LOG_TIME_TEXTURE().isDebugEnabled() || QQuickProfiler::enabled; if (profileFrames) qsg_renderer_timer.start(); -#endif if (m_image.isNull()) { if (m_texture_id && m_owns_texture) { funcs->glDeleteTextures(1, &m_texture_id); -#ifndef QSG_NO_RENDER_TIMING - if (qsg_render_timing) { - qDebug(" - texture deleted in %dms (size: %dx%d)", - (int) qsg_renderer_timer.elapsed(), - m_texture_size.width(), - m_texture_size.height()); - } + qCDebug(QSG_LOG_TIME_TEXTURE, "plain texture deleted in %dms - %dx%d", + (int) qsg_renderer_timer.elapsed(), + m_texture_size.width(), + m_texture_size.height()); Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphTextureDeletion, ( qsg_renderer_timer.nsecsElapsed())); -#endif } m_texture_id = 0; m_texture_size = QSize(); @@ -647,11 +639,9 @@ void QSGPlainTexture::bind() funcs->glGenTextures(1, &m_texture_id); funcs->glBindTexture(GL_TEXTURE_2D, m_texture_id); -#ifndef QSG_NO_RENDER_TIMING qint64 bindTime = 0; if (profileFrames) bindTime = qsg_renderer_timer.nsecsElapsed(); -#endif // ### TODO: check for out-of-memory situations... int w = m_image.width(); @@ -663,11 +653,9 @@ void QSGPlainTexture::bind() if (tmp.width() * 4 != tmp.bytesPerLine()) tmp = tmp.copy(); -#ifndef QSG_NO_RENDER_TIMING qint64 convertTime = 0; if (profileFrames) convertTime = qsg_renderer_timer.nsecsElapsed(); -#endif updateBindOptions(m_dirty_bind_options); @@ -707,41 +695,35 @@ void QSGPlainTexture::bind() qsg_swizzleBGRAToRGBA(&tmp); } -#ifndef QSG_NO_RENDER_TIMING qint64 swizzleTime = 0; if (profileFrames) swizzleTime = qsg_renderer_timer.nsecsElapsed(); -#endif + funcs->glTexImage2D(GL_TEXTURE_2D, 0, internalFormat, w, h, 0, externalFormat, GL_UNSIGNED_BYTE, tmp.constBits()); -#ifndef QSG_NO_RENDER_TIMING qint64 uploadTime = 0; if (profileFrames) uploadTime = qsg_renderer_timer.nsecsElapsed(); -#endif - if (mipmapFiltering() != QSGTexture::None) { funcs->glGenerateMipmap(GL_TEXTURE_2D); m_mipmaps_generated = true; } -#ifndef QSG_NO_RENDER_TIMING qint64 mipmapTime = 0; - if (qsg_render_timing) { + if (profileFrames) { mipmapTime = qsg_renderer_timer.nsecsElapsed(); - - qDebug(" - plaintexture(%dx%d) bind=%d, convert=%d, swizzle=%d (%s->%s), upload=%d, mipmap=%d, total=%d", - m_texture_size.width(), m_texture_size.height(), - int(bindTime/1000000), - int((convertTime - bindTime)/1000000), - int((swizzleTime - convertTime)/1000000), - externalFormat == GL_BGRA ? "BGRA" : "RGBA", - internalFormat == GL_BGRA ? "BGRA" : "RGBA", - int((uploadTime - swizzleTime)/1000000), - int((mipmapTime - uploadTime)/1000000), - (int) qsg_renderer_timer.elapsed()); - + qCDebug(QSG_LOG_TIME_TEXTURE, + "plain texture uploaded in: %dms (%dx%d), bind=%d, convert=%d, swizzle=%d (%s->%s), upload=%d, mipmap=%d", + int(mipmapTime / 1000000), + m_texture_size.width(), m_texture_size.height(), + int(bindTime / 1000000), + int((convertTime - bindTime)/1000000), + int((swizzleTime - convertTime)/1000000), + (externalFormat == GL_BGRA ? "BGRA" : "RGBA"), + (internalFormat == GL_BGRA ? "BGRA" : "RGBA"), + int((uploadTime - swizzleTime)/1000000), + int((mipmapTime - uploadTime)/1000000)); } Q_QUICK_SG_PROFILE1(QQuickProfiler::SceneGraphTexturePrepare, ( @@ -751,9 +733,6 @@ void QSGPlainTexture::bind() uploadTime - swizzleTime, qsg_renderer_timer.nsecsElapsed() - uploadTime)); -#endif - - m_texture_size = QSize(w, h); m_texture_rect = QRectF(0, 0, 1, 1); -- 2.7.4