Added to QML_RENDERER_TIMING logic to capture most render bottlenecks.

The typical bottlenecks during rendering are usually compiling
shader programs, uploading textures and preparing glyphs,
so add profiling data around them.

Change-Id: I9c330a0f6b769836d303a035b2c0dce832842aec
Reviewed-by: Samuel Rødal <samuel.rodal@digia.com>

5 files changed, 140 insertions, 22 deletions

diff --git a/src/quick/scenegraph/coreapi/qsgrenderer.cpp b/src/quick/scenegraph/coreapi/qsgrenderer.cpp
index 6f9d380eb5..02eec70952 100644
--- a/src/quick/scenegraph/coreapi/qsgrenderer.cpp
+++ b/src/quick/scenegraph/coreapi/qsgrenderer.cpp
@@ -60,8 +60,7 @@ QT_BEGIN_NAMESPACE
 
 
 
-#define QSG_RENDERER_TIMING
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
 static bool qsg_render_timing = !qgetenv("QML_RENDERER_TIMING").isEmpty();
 static QTime frameTimer;
 static int preprocessTime;
@@ -237,7 +236,7 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
     m_is_rendering = true;
 
 
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
     if (qsg_render_timing)
         frameTimer.start();
     int bindTime = 0;
@@ -248,7 +247,7 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
     preprocess();
 
     bindable.bind();
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
     if (qsg_render_timing)
         bindTime = frameTimer.elapsed();
 #endif
@@ -269,7 +268,7 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
 #endif
 
     render();
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
     if (qsg_render_timing)
         renderTime = frameTimer.elapsed();
 #endif
@@ -289,9 +288,9 @@ void QSGRenderer::renderScene(const QSGBindable &bindable)
         m_index_buffer_bound = false;
     }
 
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
     if (qsg_render_timing) {
-        printf(" - Breakdown of frametime: preprocess=%d, updates=%d, binding=%d, render=%d, total=%d\n",
+        printf(" - Breakdown of render time: preprocess=%d, updates=%d, binding=%d, render=%d, total=%d\n",
                preprocessTime,
                updatePassTime - preprocessTime,
                bindTime - updatePassTime,
@@ -379,7 +378,7 @@ void QSGRenderer::preprocess()
         }
     }
 
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
     if (qsg_render_timing)
         preprocessTime = frameTimer.elapsed();
 #endif
@@ -387,7 +386,7 @@ void QSGRenderer::preprocess()
     nodeUpdater()->setToplevelOpacity(context()->renderAlpha());
     nodeUpdater()->updateStates(m_root_node);
 
-#ifdef QSG_RENDERER_TIMING
+#ifndef QSG_NO_RENDERER_TIMING
     if (qsg_render_timing)
         updatePassTime = frameTimer.elapsed();
 #endif
diff --git a/src/quick/scenegraph/qsgadaptationlayer.cpp b/src/quick/scenegraph/qsgadaptationlayer.cpp
index 87b13d86d3..4e8bafbe95 100644
--- a/src/quick/scenegraph/qsgadaptationlayer.cpp
+++ b/src/quick/scenegraph/qsgadaptationlayer.cpp
@@ -48,8 +48,14 @@
 #include <QtGui/qguiapplication.h>
 #include <qdir.h>
 
+#include <QElapsedTimer>
+
 QT_BEGIN_NAMESPACE
 
+#ifndef QSG_NO_RENDERER_TIMING
+static bool qsg_render_timing = !qgetenv("QML_RENDERER_TIMING").isEmpty();
+static QElapsedTimer qsg_render_timer;
+#endif
 
 QSGDistanceFieldGlyphCache::Texture QSGDistanceFieldGlyphCache::s_emptyTexture;
 
@@ -155,6 +161,11 @@ void QSGDistanceFieldGlyphCache::update()
     if (m_pendingGlyphs.isEmpty())
         return;
 
+#ifndef QSG_NO_RENDERER_TIMING
+    if (qsg_render_timing)
+        qsg_render_timer.start();
+#endif
+
     QHash<glyph_t, QImage> distanceFields;
 
     for (int i = 0; i < m_pendingGlyphs.size(); ++i) {
@@ -164,9 +175,27 @@ void QSGDistanceFieldGlyphCache::update()
         distanceFields.insert(glyphIndex, distanceField);
     }
 
+#ifndef QSG_NO_RENDERER_TIMING
+    int renderTime = 0;
+    int count = m_pendingGlyphs.size();
+    if (qsg_render_timing)
+        renderTime = qsg_render_timer.elapsed();
+#endif
+
     m_pendingGlyphs.reset();
 
     storeGlyphs(distanceFields);
+
+#ifndef QSG_NO_RENDERER_TIMING
+    if (qsg_render_timing) {
+        printf("   - glyphs: count=%d, render=%d, store=%d, total=%d\n",
+               count,
+               renderTime,
+               (int) qsg_render_timer.elapsed() - renderTime,
+               (int) qsg_render_timer.elapsed());
+
+    }
+#endif
 }
 
 void QSGDistanceFieldGlyphCache::setGlyphsPosition(const QList<GlyphPosition> &glyphs)
diff --git a/src/quick/scenegraph/qsgcontext.cpp b/src/quick/scenegraph/qsgcontext.cpp
index c9ac190e86..e7e10ec2f6 100644
--- a/src/quick/scenegraph/qsgcontext.cpp
+++ b/src/quick/scenegraph/qsgcontext.cpp
@@ -71,6 +71,12 @@ DEFINE_BOOL_CONFIG_OPTION(qmlFlashMode, QML_FLASH_MODE)
 DEFINE_BOOL_CONFIG_OPTION(qmlTranslucentMode, QML_TRANSLUCENT_MODE)
 DEFINE_BOOL_CONFIG_OPTION(qmlDisableDistanceField, QML_DISABLE_DISTANCEFIELD)
 
+
+#ifndef QSG_NO_RENDERER_TIMING
+static bool qsg_render_timing = !qgetenv("QML_RENDERER_TIMING").isEmpty();
+static QElapsedTimer qsg_renderer_timer;
+#endif
+
 /*
     Comments about this class from Gunnar:
 
@@ -463,11 +469,21 @@ QSGMaterialShader *QSGContext::prepareMaterial(QSGMaterial *material)
     if (shader)
         return shader;
 
+#ifndef QSG_NO_RENDERER_TIMING
+    if (qsg_render_timing)
+        qsg_renderer_timer.start();
+#endif
+
     shader = material->createShader();
     shader->compile();
     shader->initialize();
     d->materials[type] = shader;
 
+#ifndef QSG_NO_RENDERER_TIMING
+    if (qsg_render_timing)
+        printf("   - compiling material: %dms\n", (int) qsg_renderer_timer.elapsed());
+#endif
+
     return shader;
 }
 
diff --git a/src/quick/scenegraph/qsgthreadedrenderloop.cpp b/src/quick/scenegraph/qsgthreadedrenderloop.cpp
index 5ec6de2f04..4e8050dd62 100644
--- a/src/quick/scenegraph/qsgthreadedrenderloop.cpp
+++ b/src/quick/scenegraph/qsgthreadedrenderloop.cpp
@@ -133,8 +133,7 @@ static inline int qsgrl_animation_interval() {
 }
 
 
-#define QQUICK_WINDOW_TIMING
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
 static bool qquick_window_timing = !qgetenv("QML_WINDOW_TIMING").isEmpty();
 static QTime threadTimer;
 static int syncTime;
@@ -537,7 +536,7 @@ void QSGRenderThread::sync()
 
 void QSGRenderThread::syncAndRender()
 {
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
     if (qquick_window_timing)
         sinceLastTime = threadTimer.restart();
 #endif
@@ -556,7 +555,7 @@ void QSGRenderThread::syncAndRender()
         sync();
     }
 
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
     if (qquick_window_timing)
         syncTime = threadTimer.elapsed();
 #endif
@@ -570,7 +569,7 @@ void QSGRenderThread::syncAndRender()
         }
         gl->makeCurrent(w.window);
         d->renderSceneGraph(w.size);
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
         if (qquick_window_timing && i == 0)
             renderTime = threadTimer.elapsed();
 #endif
@@ -579,7 +578,7 @@ void QSGRenderThread::syncAndRender()
     }
     RLDEBUG("    Render:  - rendering done");
 
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
         if (qquick_window_timing)
             qDebug("window Time: sinceLast=%d, sync=%d, first render=%d, after final swap=%d",
                    sinceLastTime,
@@ -885,10 +884,10 @@ void QSGThreadedRenderLoop::polishAndSync()
     if (!anyoneShowing())
         return;
 
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
     QElapsedTimer timer;
-    int polishTime;
-    int waitTime;
+    int polishTime = 0;
+    int waitTime = 0;
     if (qquick_window_timing)
         timer.start();
 #endif
@@ -899,7 +898,7 @@ void QSGThreadedRenderLoop::polishAndSync()
         QQuickWindowPrivate *d = QQuickWindowPrivate::get(w.window);
         d->polishItems();
     }
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
     if (qquick_window_timing)
         polishTime = timer.elapsed();
 #endif
@@ -916,7 +915,7 @@ void QSGThreadedRenderLoop::polishAndSync()
 
     QCoreApplication::postEvent(m_thread, event);
     RLDEBUG("GUI:  - wait for sync...");
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
     if (qquick_window_timing)
         waitTime = timer.elapsed();
 #endif
@@ -925,7 +924,7 @@ void QSGThreadedRenderLoop::polishAndSync()
     m_thread->mutex.unlock();
     RLDEBUG("GUI:  - unlocked after sync...");
 
-#ifdef QQUICK_WINDOW_TIMING
+#ifndef QSG_NO_WINDOW_TIMING
     if (qquick_window_timing)
         qDebug(" - polish=%d, wait=%d, sync=%d", polishTime, waitTime - polishTime, int(timer.elapsed() - waitTime));
 #endif
diff --git a/src/quick/scenegraph/util/qsgtexture.cpp b/src/quick/scenegraph/util/qsgtexture.cpp
index 16cc46113d..c6a5672469 100644
--- a/src/quick/scenegraph/util/qsgtexture.cpp
+++ b/src/quick/scenegraph/util/qsgtexture.cpp
@@ -65,6 +65,12 @@
 #include <QHash>
 #endif
 
+#ifndef QSG_NO_RENDERER_TIMING
+static bool qsg_render_timing = !qgetenv("QML_RENDERER_TIMING").isEmpty();
+static QElapsedTimer qsg_renderer_timer;
+#endif
+
+
 QT_BEGIN_NAMESPACE
 
 inline static bool isPowerOfTwo(int x)
@@ -596,14 +602,30 @@ void QSGPlainTexture::bind()
 
     m_dirty_texture = false;
 
+#ifndef QSG_NO_RENDERER_TIMING
+    if (qsg_render_timing)
+        qsg_renderer_timer.start();
+#endif
 
     if (m_image.isNull()) {
-        if (m_texture_id && m_owns_texture)
+        if (m_texture_id && m_owns_texture) {
             glDeleteTextures(1, &m_texture_id);
+#ifndef QSG_NO_RENDERER_TIMING
+            if (qsg_render_timing) {
+                printf("   - texture deleted in %dms (size: %dx%d)\n",
+                       (int) qsg_renderer_timer.elapsed(),
+                       m_texture_size.width(),
+                       m_texture_size.height());
+            }
+#endif
+        }
         m_texture_id = 0;
         m_texture_size = QSize();
         m_has_mipmaps = false;
         m_has_alpha = false;
+
+
+
         return;
     }
 
@@ -611,6 +633,12 @@ void QSGPlainTexture::bind()
         glGenTextures(1, &m_texture_id);
     glBindTexture(GL_TEXTURE_2D, m_texture_id);
 
+#ifndef QSG_NO_RENDERER_TIMING
+    int bindTime = 0;
+    if (qsg_render_timing)
+        bindTime = qsg_renderer_timer.elapsed();
+#endif
+
     // ### TODO: check for out-of-memory situations...
     int w = m_image.width();
     int h = m_image.height();
@@ -619,21 +647,68 @@ void QSGPlainTexture::bind()
                  ? m_image
                  : m_image.convertToFormat(QImage::Format_ARGB32_Premultiplied);
 
+#ifndef QSG_NO_RENDERER_TIMING
+    int convertTime = 0;
+    if (qsg_render_timing)
+        convertTime = qsg_renderer_timer.elapsed();
+#endif
+
     updateBindOptions(m_dirty_bind_options);
 
 #ifdef QT_OPENGL_ES
         qsg_swizzleBGRAToRGBA(&tmp);
+#ifndef QSG_NO_RENDERER_TIMING
+    int swizzleTime = 0;
+    if (qsg_render_timing)
+        swizzleTime = qsg_renderer_timer.elapsed();
+#endif
         glTexImage2D(GL_TEXTURE_2D, 0, GL_RGBA, w, h, 0, GL_RGBA, GL_UNSIGNED_BYTE, tmp.constBits());
 #else
         glTexImage2D(GL_TEXTURE_2D, 0, GL_RGBA, w, h, 0, GL_BGRA, GL_UNSIGNED_BYTE, tmp.constBits());
 #endif
 
+#ifndef QSG_NO_RENDERER_TIMING
+    int uploadTime = 0;
+    if (qsg_render_timing)
+        uploadTime = qsg_renderer_timer.elapsed();
+#endif
+
+
     if (m_has_mipmaps) {
         QOpenGLContext *ctx = QOpenGLContext::currentContext();
         ctx->functions()->glGenerateMipmap(GL_TEXTURE_2D);
         m_mipmaps_generated = true;
     }
 
+#ifndef QSG_NO_RENDERER_TIMING
+    int mipmapTime = 0;
+    if (qsg_render_timing) {
+        mipmapTime = qsg_renderer_timer.elapsed();
+
+#ifdef QT_OPENGL_ES
+        printf("   - plaintexture(%dx%d) bind=%d, convert=%d, swizzle=%d, upload=%d, mipmap=%d, total=%d\n",
+               m_texture_size.width(), m_texture_size.height(),
+               bindTime,
+               convertTime - bindTime,
+               swizzleTime - convertTime,
+               uploadTime - swizzleTime,
+               mipmapTime - uploadTime,
+               (int) qsg_renderer_timer.elapsed());
+#else
+        printf("   - plaintexture(%dx%d): bind=%d, convert=%d, upload=%d, mipmap=%d, total=%d\n",
+               m_texture_size.width(), m_texture_size.height(),
+               bindTime,
+               convertTime - bindTime,
+               uploadTime - convertTime,
+               mipmapTime - uploadTime,
+               (int) qsg_renderer_timer.elapsed());
+#endif
+
+    }
+
+#endif
+
+
     m_texture_size = QSize(w, h);
     m_texture_rect = QRectF(0, 0, 1, 1);