Improve polish loop detection and diagnostics

The existing warning was pretty much useless since it would only warn
after having looped INT_MAX times. In addition, it didn't actually
detect if polish() was called from within updatePolish().

Instead, the counting is changed to be strictly more correct:

The counter is now only increased when polish() is called within the
updatePolish(). It will reset back to 1 if that does not occur.
Effectively, the counter will reflect how many consecutive polish loops
we have processed.

This patch will show diagnostics after having reached 1000 consecutive
polish loops. It will only warn for the next 5 items in order to not be
too verbose...(most likely they will be the same 5 items).

If the counter reaches 100,000, we break out of the loop:
This might be important for e.g. CI runs so that the process can actually
terminate in order to get some useful diagnostics.

Note that the item that calls polish() within updatePolish() doesn't
have to be the same item as updatePolish() was called on. We also want
to track these since there might be several items working in tandem to
create the loop.

With this change it will now give the following output:

  main.qml:10:5: QML Row: possible QQuickItem::polish() loop
  main.qml:10:5: QML Row: Row called polish() inside updatePolish() of Row

(This is when Row called polish() from within its own updatePolish())

Fixes: QTBUG-40220
Task-number: QTBUG-83856
Pick-to: 5.12
Pick-to: 5.15
Change-Id: Ib8a7242908082c70d8cf71efbbe1fa148dbfada0
Reviewed-by: Shawn Rutledge <shawn.rutledge@qt.io>

2 files changed, 164 insertions, 7 deletions

diff --git a/src/quick/items/qquickwindow.cpp b/src/quick/items/qquickwindow.cpp
index 18ee4bb948..330bf4a59f 100644
--- a/src/quick/items/qquickwindow.cpp
+++ b/src/quick/items/qquickwindow.cpp
@@ -73,6 +73,8 @@
 #include <QtCore/QLibraryInfo>
 #include <QtCore/QRunnable>
 #include <QtQml/qqmlincubator.h>
+#include <QtQml/qqmlinfo.h>
+#include <QtQml/private/qqmlmetatype_p.h>
 
 #include <QtQuick/private/qquickpixmapcache_p.h>
 
@@ -311,6 +313,79 @@ static bool transformDirtyOnItemOrAncestor(const QQuickItem *item)
 }
 #endif
 
+/*!
+ *  \internal
+
+    A "polish loop" can occur inside QQuickWindowPrivate::polishItems(). It is when an item calls
+    polish() on an(other?) item from updatePolish(). If this anomaly happens repeatedly and without
+    interruption (of a well-behaved updatePolish() that doesn't call polish()), it is a strong
+    indication that we are heading towards an infinite polish loop. A polish loop is not a bug in
+    Qt Quick - it is a bug caused by ill-behaved items put in the scene.
+
+    We can detect this sequence of polish loops easily, since the
+    QQuickWindowPrivate::itemsToPolish is basically a stack: polish() will push to it, and
+    polishItems() will pop from it.
+    Therefore if updatePolish() calls polish(), the immediate next item polishItems() processes is
+    the item that was polished by the previous call to updatePolish().
+    We therefore just need to count the number of polish loops we detected in _sequence_.
+*/
+struct PolishLoopDetector
+{
+    PolishLoopDetector(const QVector<QQuickItem*> &itemsToPolish)
+        : itemsToPolish(itemsToPolish)
+    {
+    }
+
+    /*
+     * returns true when it detected a likely infinite loop
+     * (suggests it should abort the polish loop)
+     **/
+    bool check(QQuickItem *item, int itemsRemainingBeforeUpdatePolish)
+    {
+        if (itemsToPolish.count() > itemsRemainingBeforeUpdatePolish) {
+            // Detected potential polish loop.
+            ++numPolishLoopsInSequence;
+            if (numPolishLoopsInSequence >= 1000) {
+                // Start to warn about polish loop after 1000 consecutive polish loops
+                if (numPolishLoopsInSequence == 100000) {
+                    // We have looped 100,000 times without actually reducing the list of items to
+                    // polish, give up for now.
+                    // This is not a fix, just a remedy so that the application can be somewhat
+                    // responsive.
+                    numPolishLoopsInSequence = 0;
+                    return true;
+                } else if (numPolishLoopsInSequence < 1005) {
+                    // Show the 5 next items involved in the polish loop.
+                    // (most likely they will be the same 5 items...)
+                    QQuickItem *guiltyItem = itemsToPolish.last();
+                    qmlWarning(item) << "possible QQuickItem::polish() loop";
+
+                    auto typeAndObjectName = [](QQuickItem *item) {
+                        QString typeName = QQmlMetaType::prettyTypeName(item);
+                        QString objName = item->objectName();
+                        if (!objName.isNull())
+                            return QLatin1String("%1(%2)").arg(typeName, objName);
+                        return typeName;
+                    };
+
+                    qmlWarning(guiltyItem) << typeAndObjectName(guiltyItem)
+                               << " called polish() inside updatePolish() of " << typeAndObjectName(item);
+
+                    if (numPolishLoopsInSequence == 1004)
+                        // Enough warnings. Reset counter in order to speed things up and re-detect
+                        // more loops
+                        numPolishLoopsInSequence = 0;
+                }
+            }
+        } else {
+            numPolishLoopsInSequence = 0;
+        }
+        return false;
+    }
+    const QVector<QQuickItem*> &itemsToPolish;      // Just a ref to the one in polishItems()
+    int numPolishLoopsInSequence = 0;
+};
+
 void QQuickWindowPrivate::polishItems()
 {
     // An item can trigger polish on another item, or itself for that matter,
@@ -318,20 +393,21 @@ void QQuickWindowPrivate::polishItems()
     // iterate through the set, we must continue pulling items out until it
     // is empty.
     // In the case where polish is called from updatePolish() either directly
-    // or indirectly, we use a recursionSafeguard to print a warning to
-    // the user.
-    int recursionSafeguard = INT_MAX;
-    while (!itemsToPolish.isEmpty() && --recursionSafeguard > 0) {
+    // or indirectly, we use a PolishLoopDetector to determine if a warning should
+    // be printed to the user.
+
+    PolishLoopDetector polishLoopDetector(itemsToPolish);
+    while (!itemsToPolish.isEmpty()) {
         QQuickItem *item = itemsToPolish.takeLast();
         QQuickItemPrivate *itemPrivate = QQuickItemPrivate::get(item);
         itemPrivate->polishScheduled = false;
+        const int itemsRemaining = itemsToPolish.count();
         itemPrivate->updatePolish();
         item->updatePolish();
+        if (polishLoopDetector.check(item, itemsRemaining) == true)
+            break;
     }
 
-    if (recursionSafeguard == 0)
-        qWarning("QQuickWindow: possible QQuickItem::polish() loop");
-
 #if QT_CONFIG(im)
     if (QQuickItem *focusItem = q_func()->activeFocusItem()) {
         // If the current focus item, or any of its anchestors, has changed location
diff --git a/tests/auto/quick/qquickitem/tst_qquickitem.cpp b/tests/auto/quick/qquickitem/tst_qquickitem.cpp
index 137162099f..abb5142304 100644
--- a/tests/auto/quick/qquickitem/tst_qquickitem.cpp
+++ b/tests/auto/quick/qquickitem/tst_qquickitem.cpp
@@ -44,6 +44,7 @@
 #include "../shared/viewtestutil.h"
 #include <QSignalSpy>
 #include <QTranslator>
+#include <QtCore/qregularexpression.h>
 
 #ifdef TEST_QTBUG_60123
 #include <QWidget>
@@ -122,10 +123,15 @@ public:
     }
 
     bool wasPolished;
+    int repolishLoopCount = 0;
 
 protected:
     virtual void updatePolish() {
         wasPolished = true;
+        if (repolishLoopCount > 0) {
+            --repolishLoopCount;
+            polish();
+        }
     }
 
 public slots:
@@ -210,6 +216,8 @@ private slots:
 
     void setParentCalledInOnWindowChanged();
     void receivesLanguageChangeEvent();
+    void polishLoopDetection_data();
+    void polishLoopDetection();
 
 private:
 
@@ -1441,6 +1449,79 @@ void tst_qquickitem::polishOnCompleted()
     QTRY_VERIFY(item->wasPolished);
 }
 
+struct PolishItemSpan {
+    int itemCount;      // Number of items...
+    int repolishCount;  // ...repolishing 'repolishCount' times
+};
+
+/*
+ * For instance, two consecutive spans {99,0} and {1,2000} } instructs to
+ * construct 99 items with no repolish, and 1 item with 2000 repolishes (in that sibling order)
+ */
+typedef QVector<PolishItemSpan> PolishItemSpans;
+
+Q_DECLARE_METATYPE(PolishItemSpan)
+Q_DECLARE_METATYPE(PolishItemSpans)
+
+void tst_qquickitem::polishLoopDetection_data()
+{
+    QTest::addColumn<PolishItemSpans>("listOfItemsToPolish");
+    QTest::addColumn<int>("expectedNumberOfWarnings");
+
+    QTest::newRow("test1.100") <<   PolishItemSpans({ {1, 100} }) << 0;
+    QTest::newRow("test1.1002") <<  PolishItemSpans({ {1, 1002} }) << 3;
+    QTest::newRow("test1.2020") <<  PolishItemSpans({ {1, 2020} }) << 10;
+
+    QTest::newRow("test5.1") <<    PolishItemSpans({ {5, 1} }) << 0;
+    QTest::newRow("test5.10") <<   PolishItemSpans({ {5, 10} }) << 0;
+    QTest::newRow("test5.100") <<  PolishItemSpans({ {5, 100} }) << 0;
+    QTest::newRow("test5.1000") << PolishItemSpans({ {5, 1000} }) << 5;
+
+    QTest::newRow("test1000.1") <<  PolishItemSpans({ {1000,1} }) << 0;
+    QTest::newRow("test2000.1") <<  PolishItemSpans({ {2000,1} }) << 0;
+
+    QTest::newRow("test99.0-1.1100") << PolishItemSpans({ {99,0},{1,1100} }) << 5;
+    QTest::newRow("test98.0-2.1100") << PolishItemSpans({ {98,0},{2,1100} }) << 5+5;
+
+    // reverse the two above
+    QTest::newRow("test1.1100-99.0") << PolishItemSpans({ {1,1100},{99,0} }) << 5;
+    QTest::newRow("test2.1100-98.0") << PolishItemSpans({ {2,1100},{98,0} }) << 5+5;
+}
+
+void tst_qquickitem::polishLoopDetection()
+{
+    QFETCH(PolishItemSpans, listOfItemsToPolish);
+    QFETCH(int, expectedNumberOfWarnings);
+
+    QQuickWindow window;
+    window.resize(200, 200);
+    window.show();
+
+    TestPolishItem *item = nullptr;
+    int count = 0;
+    for (PolishItemSpan s : listOfItemsToPolish) {
+        for (int i = 0; i < s.itemCount; ++i) {
+            item = new TestPolishItem(window.contentItem());
+            item->setSize(QSizeF(200, 100));
+            item->repolishLoopCount = s.repolishCount;
+            item->setObjectName(QString::fromLatin1("obj%1").arg(count++));
+        }
+    }
+
+    for (int i = 0; i < expectedNumberOfWarnings; ++i) {
+        QTest::ignoreMessage(QtWarningMsg, QRegularExpression(".*possible QQuickItem..polish.. loop.*"));
+        QTest::ignoreMessage(QtWarningMsg, QRegularExpression(".*TestPolishItem.* called polish.. inside updatePolish.. of TestPolishItem.*"));
+    }
+
+    QList<QQuickItem*> items = window.contentItem()->childItems();
+    for (int i = 0; i < items.count(); ++i) {
+        static_cast<TestPolishItem*>(items.at(i))->doPolish();
+    }
+    item = static_cast<TestPolishItem*>(items.first());
+    // item is the last item, so we wait until the last item reached 0
+    QVERIFY(QTest::qWaitFor([=](){return item->repolishLoopCount == 0 && item->wasPolished;}));
+}
+
 void tst_qquickitem::wheelEvent_data()
 {
     QTest::addColumn<bool>("visible");