Perf/frame pacing diagnostics

src/rive_view.cpp

@@ -16,6 +16,7 @@
 #include <QNetworkRequest>
 #include <QQuickWindow>
 #include <QSGSimpleTextureNode>
+#include <QScreen>
 #include <QStyleHints>
 #include <QTouchEvent>
 
@@ -451,8 +452,16 @@ void RiveView::itemChange(ItemChange change, const ItemChangeData& data)
 void RiveView::onBeforeSynchronizing()
 {
     // Keep requesting updates as long as the animation is live.
+    //
+    // The update() must run on the GUI thread: beforeSynchronizing fires on
+    // the render thread, and a render-thread update() only works for items
+    // rendered directly by the window pass. An item grabbed by a layer
+    // (Texture.sourceItem / ShaderEffectSource) — possibly culled from the
+    // window pass entirely — relies on the layer's live-update tracking,
+    // which only observes GUI-thread dirtying. Queued invoke costs one frame
+    // of latency and makes both paths correct.
     if (m_playing && !m_settled)
-        update();
+        QMetaObject::invokeMethod(this, &QQuickItem::update, Qt::QueuedConnection);
 }
 
 void RiveView::onSceneGraphInvalidated()
@@ -1203,6 +1212,22 @@ QSGNode* RiveView::updatePaintNode(QSGNode* oldNode, UpdatePaintNodeData*)
         return nullptr;
     }
 
+    // Frame driving normally hooks up in itemChange(ItemSceneChange), but an
+    // item used as a Texture.sourceItem / ShaderEffectSource has no visual
+    // parent, so that change never fires — the animation froze on its first
+    // frame when rendered into a Quick3D material. By the time we're painting
+    // a layer, window() is valid: connect lazily here (UniqueConnection makes
+    // the tree-parented path a no-op).
+    if (connect(win, &QQuickWindow::beforeSynchronizing, this,
+                &RiveView::onBeforeSynchronizing,
+                static_cast<Qt::ConnectionType>(Qt::DirectConnection | Qt::UniqueConnection)))
+    {
+        qCDebug(lcRiveView) << "frame driver connected at paint time (layer/sourceItem path)";
+    }
+    connect(win, &QQuickWindow::sceneGraphInvalidated, this,
+            &RiveView::onSceneGraphInvalidated,
+            static_cast<Qt::ConnectionType>(Qt::DirectConnection | Qt::UniqueConnection));
+
     if (!m_backend)
     {
         QString err;
@@ -1262,13 +1287,49 @@ QSGNode* RiveView::updatePaintNode(QSGNode* oldNode, UpdatePaintNodeData*)
         didSeek = true;
     }
 
+    // One-shot per instance: what drives this view's animation. Names the
+    // failure mode when a layered instance paints but never moves.
+    if (!m_advanceStateLogged)
+    {
+        m_advanceStateLogged = true;
+        qCDebug(lcRiveView) << "advance state:" << m_source.toString()
+                            << "sm=" << (m_stateMachine != nullptr)
+                            << "anim=" << (m_animation != nullptr)
+                            << "playing=" << m_playing << "settled=" << m_settled;
+    }
+
     // Advance the SM (if any) or the raw artboard. Skipped on a frame where
     // we just seeked, so the scrubbed position isn't immediately stepped past.
     if (!didSeek && m_playing && !m_settled)
     {
         const qint64 nowNs = m_frameTimer.nsecsElapsed();
         const qint64 deltaNs = nowNs - m_lastAdvanceNs;
         m_lastAdvanceNs = nowNs;
+
+        // Frame-pacing spike detector: while continuously playing, the
+        // interval between frames should sit at the display period. Log
+        // intervals 1.6x-5x the running average (above 5x is a hide/show or
+        // pause gap, not jank) with timestamps so hitches can be correlated
+        // against host-app log activity. Debug level — can fire 1-2x/sec on
+        // displays whose pacing occasionally slips a vsync; enable with
+        // QT_LOGGING_RULES="rive.view.debug=true" when investigating jank.
+        if (m_paceLastNs > 0)
+        {
+            const qreal paceDelta = static_cast<qreal>(nowNs - m_paceLastNs);
+            if (m_paceEmaNs > 0)
+            {
+                if (paceDelta > m_paceEmaNs * 1.6 && paceDelta < m_paceEmaNs * 5)
+                    qCDebug(lcRiveView).nospace()
+                        << "frame pacing spike: " << paceDelta / 1e6
+                        << " ms (typical " << m_paceEmaNs / 1e6 << " ms)";
+                m_paceEmaNs = m_paceEmaNs * 0.9 + paceDelta * 0.1;
+            }
+            else
+            {
+                m_paceEmaNs = paceDelta;
+            }
+        }
+        m_paceLastNs = nowNs;
         const float delta = std::min(static_cast<float>(deltaNs) * 1e-9f, 0.25f) *
                             static_cast<float>(m_speed);
         bool needsMore = true;
@@ -1291,13 +1352,33 @@ QSGNode* RiveView::updatePaintNode(QSGNode* oldNode, UpdatePaintNodeData*)
         // Track the playhead so a bound scrubber follows along during playback.
         publishCurrentFrame();
         if (!needsMore)
+        {
             m_settled = true;
+            if (!m_settleLogged)
+            {
+                m_settleLogged = true;
+                qCDebug(lcRiveView) << "settled:" << m_source.toString()
+                                    << "(advance reported no more work)";
+            }
+        }
     }
 
     const qreal dpr = win->effectiveDevicePixelRatio();
     const QSize pixelSize(static_cast<int>(std::ceil(itemSize.width() * dpr)),
                           static_cast<int>(std::ceil(itemSize.height() * dpr)));
 
+    // Perf diagnostics, logged once per target size: the render-target pixel
+    // count and refresh rate are the environment multipliers behind
+    // platform CPU differences (Retina 2x dpr = 4x pixels; ProMotion 120Hz =
+    // 2x frames), so surface them where a report can quote them.
+    if (pixelSize != m_lastLoggedPixelSize)
+    {
+        m_lastLoggedPixelSize = pixelSize;
+        const QScreen* screen = win->screen();
+        qCInfo(lcRiveView) << "render target" << pixelSize << "dpr" << dpr
+                           << "refresh" << (screen ? screen->refreshRate() : 0.0) << "Hz";
+    }
+
     QSGTexture* tex = m_backend->ensureTexture(pixelSize);
     if (!tex)
     {

src/rive_view.h

@@ -368,6 +368,18 @@ private slots:
     QElapsedTimer m_frameTimer;
     qint64 m_lastAdvanceNs = 0;
 
+    // Frame-pacing diagnostics (render thread only). EMA of the interval
+    // between updatePaintNode calls while playing; spikes are logged so rare
+    // jank can be caught in the act and correlated with host-app activity.
+    qint64 m_paceLastNs = 0;
+    qreal m_paceEmaNs = 0;
+    // Per-instance dedup for the render-target log (a static shared across
+    // instances re-triggers every frame when two views have different sizes).
+    QSize m_lastLoggedPixelSize;
+    // One-shot diagnostics for layered/sourceItem debugging.
+    bool m_advanceStateLogged = false;
+    bool m_settleLogged = false;
+
     // Drag detection (mouse only). When a mouse button is pressed we
     // capture the position and mark `pending`. Once the cursor moves
     // beyond Qt's startDragDistance threshold we fire dragStart on the

tests/render/CMakeLists.txt

@@ -20,3 +20,15 @@ set_source_files_properties(tst_render_smoke.cpp
 add_test(NAME Render.decodeImageUploadsTexture COMMAND tst_render_smoke decodeImageUploadsTexture)
 add_test(NAME Render.rendersNonBlankFrame COMMAND tst_render_smoke rendersNonBlankFrame)
 add_test(NAME Render.matchesGoldenSnapshot COMMAND tst_render_smoke matchesGoldenSnapshot)
+qt_add_executable(tst_color_probe tst_color_probe.cpp)
+target_link_libraries(tst_color_probe PRIVATE
+    Qt6::Test Qt6::Quick Qt6::Gui Qt6::GuiPrivate
+    rive_qt rive riveqt_test_helpers)
+target_include_directories(tst_color_probe PRIVATE
+    ${CMAKE_SOURCE_DIR}/src
+    ${CMAKE_SOURCE_DIR}/src/rive
+    ${CMAKE_SOURCE_DIR}/src/backends)
+target_compile_features(tst_color_probe PRIVATE cxx_std_20)
+set_source_files_properties(tst_color_probe.cpp
+    TARGET_DIRECTORY tst_color_probe
+    PROPERTIES COMPILE_OPTIONS "$<IF:$<CXX_COMPILER_ID:MSVC>,/GR-,-fno-rtti>")

tests/render/tst_color_probe.cpp

@@ -0,0 +1,113 @@
+// TEMPORARY diagnostic probe — renders an arbitrary .riv (RIVE_PROBE_FILE env
+// var) through the real Metal backend over black and over white backgrounds,
+// then prints the dominant rendered colors. Used to determine whether a
+// perceived color shift ("mustard yellow") is baked into the render output
+// (value shift or alpha bleed) or happens display-side. Not part of the gate.
+
+#include <QGuiApplication>
+#include <QImage>
+#include <QMap>
+#include <QQuickWindow>
+#include <QSGRendererInterface>
+#include <QSignalSpy>
+#include <QTest>
+
+#include "rive_view.h"
+
+namespace {
+constexpr int kW = 780;  // 3.25:1, the hero's authored ratio
+constexpr int kH = 240;
+
+QImage renderOver(const QColor& bg, const QString& rivPath, int* loadFailures)
+{
+    QQuickWindow window;
+    window.resize(kW, kH);
+    window.setColor(bg);
+
+    auto* rv = new RiveView(window.contentItem());
+    rv->setWidth(kW);
+    rv->setHeight(kH);
+    rv->setFit(RiveView::Fit::Cover);
+    QSignalSpy failSpy(rv, &RiveView::loadFailed);
+    rv->setSource(QUrl::fromLocalFile(rivPath));
+    rv->setPlaying(true);
+
+    window.create();
+
+    QImage img;
+    for (int i = 0; i < 120; ++i)
+    {
+        QTest::qWait(16);
+        const QImage grabbed = window.grabWindow();
+        if (!grabbed.isNull())
+        {
+            img = grabbed;
+            // Wait until the riv actually painted (more than bg present).
+            QMap<QRgb, int> colors;
+            for (int y = 0; y < img.height(); y += 8)
+                for (int x = 0; x < img.width(); x += 8)
+                    colors[img.pixel(x, y)]++;
+            if (colors.size() > 3)
+                break;
+        }
+    }
+    if (loadFailures)
+        *loadFailures = failSpy.count();
+    return img;
+}
+
+void printTopColors(const char* label, const QImage& img)
+{
+    QMap<QRgb, int> counts;
+    for (int y = 0; y < img.height(); y += 4)
+        for (int x = 0; x < img.width(); x += 4)
+            counts[img.pixel(x, y)]++;
+    // Sort descending by count.
+    QList<QPair<int, QRgb>> sorted;
+    for (auto it = counts.constBegin(); it != counts.constEnd(); ++it)
+        sorted.append({it.value(), it.key()});
+    std::sort(sorted.begin(), sorted.end(),
+              [](const auto& a, const auto& b) { return a.first > b.first; });
+    qInfo("=== %s (%dx%d) top colors ===", label, img.width(), img.height());
+    for (int i = 0; i < qMin(6, static_cast<int>(sorted.size())); ++i)
+    {
+        const QRgb c = sorted[i].second;
+        qInfo("  #%02X%02X%02X  x%d", qRed(c), qGreen(c), qBlue(c), sorted[i].first);
+    }
+}
+} // namespace
+
+class TstColorProbe : public QObject
+{
+    Q_OBJECT
+
+private slots:
+    void initTestCase()
+    {
+        QQuickWindow::setGraphicsApi(QSGRendererInterface::Metal);
+    }
+
+    void probeColors()
+    {
+        const QString rivPath = qEnvironmentVariable("RIVE_PROBE_FILE");
+        if (rivPath.isEmpty())
+            QSKIP("set RIVE_PROBE_FILE to a .riv path");
+
+        int fail = 0;
+        const QImage overBlack = renderOver(Qt::black, rivPath, &fail);
+        if (overBlack.isNull())
+            QSKIP("offscreen Metal grab unavailable");
+        if (fail > 0)
+            QSKIP("riv failed to load");
+        printTopColors("over BLACK", overBlack);
+
+        const QImage overWhite = renderOver(Qt::white, rivPath, &fail);
+        printTopColors("over WHITE", overWhite);
+
+        qInfo("If the same content color differs between the two runs, the riv");
+        qInfo("has sub-100%% opacity and the window background bleeds through.");
+    }
+};
+
+QTEST_MAIN(TstColorProbe)
+#include "tst_color_probe.moc"