Add categorized logging of delete later machinery

A QT_MESSAGE_PATTERN including %{backtrace depth=4} should give
the call site of the QScopedScopeLevelCounter.

Task-number: QTBUG-120124
Change-Id: Ie477994882bde9168c931479102017ad5fde426a
Reviewed-by: Fabian Kosmale <fabian.kosmale@qt.io>

src/corelib/kernel/qcoreapplication.cpp

@@ -111,6 +111,10 @@
 
 QT_BEGIN_NAMESPACE
 
+#ifndef QT_NO_QOBJECT
+Q_LOGGING_CATEGORY(lcDeleteLater, "qt.core.qobject.deletelater")
+#endif
+
 using namespace Qt::StringLiterals;
 
 Q_TRACE_PREFIX(qtcore,
@@ -1494,6 +1498,8 @@ void QCoreApplicationPrivate::execCleanup()
 {
     threadData.loadRelaxed()->quitNow = false;
     in_exec = false;
+
+    qCDebug(lcDeleteLater) << "Sending deferred delete events as part of exec cleanup";
     QCoreApplication::sendPostedEvents(nullptr, QEvent::DeferredDelete);
 }
 
@@ -1856,16 +1862,37 @@ void QCoreApplicationPrivate::sendPostedEvents(QObject *receiver, int event_type
             //    events posted by the current event loop; or
             // 3) if the event was posted before the outermost event loop.
 
-            const int eventLoopLevel = static_cast<QDeferredDeleteEvent *>(pe.event)->loopLevel();
-            const int eventScopeLevel = static_cast<QDeferredDeleteEvent *>(pe.event)->scopeLevel();
+            const auto *event = static_cast<QDeferredDeleteEvent *>(pe.event);
+            qCDebug(lcDeleteLater) << "Processing deferred delete event for" << pe.receiver
+                << "with loop level" << event->loopLevel() << "and scope level" << event->scopeLevel();
+
+            qCDebug(lcDeleteLater) << "Checking" << data->thread << "with loop level"
+                << data->loopLevel << "and scope level" << data->scopeLevel;
+
+            bool allowDeferredDelete = false;
+            if (event->loopLevel() == 0 && data->loopLevel > 0) {
+                qCDebug(lcDeleteLater) << "Event was posted outside outermost event loop"
+                    << "and current thread has an event loop running.";
+                allowDeferredDelete = true;
+            } else {
+                const int totalEventLevel = event->loopLevel() + event->scopeLevel();
+                const int totalThreadLevel = data->loopLevel + data->scopeLevel;
+
+                if (totalEventLevel > totalThreadLevel) {
+                    qCDebug(lcDeleteLater) << "Combined levels of event" << totalEventLevel
+                        << "is higher than thread" << totalThreadLevel;
+                    allowDeferredDelete = true;
+                } else if (event_type == QEvent::DeferredDelete && totalEventLevel == totalThreadLevel) {
+                    qCDebug(lcDeleteLater) << "Explicit send of DeferredDelete and"
+                        << "levels of event" << totalEventLevel
+                        << "is same as thread" << totalThreadLevel;
+                    allowDeferredDelete = true;
+                }
+            }
 
-            const bool postedBeforeOutermostLoop = eventLoopLevel == 0;
-            const bool allowDeferredDelete =
-                (eventLoopLevel + eventScopeLevel > data->loopLevel + data->scopeLevel
-                 || (postedBeforeOutermostLoop && data->loopLevel > 0)
-                 || (event_type == QEvent::DeferredDelete
-                     && eventLoopLevel + eventScopeLevel == data->loopLevel + data->scopeLevel));
             if (!allowDeferredDelete) {
+                qCDebug(lcDeleteLater) << "Failed conditions for deferred delete. Deferring again";
+
                 // cannot send deferred delete
                 if (!event_type && !receiver) {
                     // we must copy it first; we want to re-post the event
@@ -1882,6 +1909,8 @@ void QCoreApplicationPrivate::sendPostedEvents(QObject *receiver, int event_type
                     data->postEventList.addEvent(pe_copy);
                 }
                 continue;
+            } else {
+                qCDebug(lcDeleteLater) << "Sending deferred delete to" << pe.receiver;
             }
         }
 

src/corelib/kernel/qcoreapplication_p.h

@@ -25,6 +25,7 @@
 #include "QtCore/qsettings.h"
 #endif
 #ifndef QT_NO_QOBJECT
+#include <qloggingcategory.h>
 #include "private/qobject_p.h"
 #include "private/qlocking_p.h"
 #endif
@@ -35,6 +36,10 @@
 
 QT_BEGIN_NAMESPACE
 
+#ifndef QT_NO_QOBJECT
+Q_DECLARE_LOGGING_CATEGORY(lcDeleteLater)
+#endif
+
 typedef QList<QTranslator*> QTranslatorList;
 
 class QAbstractEventDispatcher;

src/corelib/kernel/qeventloop.cpp

@@ -151,6 +151,9 @@ int QEventLoop::exec(ProcessEventsFlags flags)
             auto threadData = d->threadData.loadRelaxed();
             ++threadData->loopLevel;
             threadData->eventLoops.push(d->q_func());
+            qCDebug(lcDeleteLater) << "Increased" << threadData->thread
+                      << "loop level to" << threadData->loopLevel
+                      << "with leaf loop now" << threadData->eventLoops.last();
 
             locker.unlock();
         }
@@ -169,6 +172,12 @@ int QEventLoop::exec(ProcessEventsFlags flags)
             Q_UNUSED(eventLoop); // --release warning
             d->inExec = false;
             --threadData->loopLevel;
+
+            qCDebug(lcDeleteLater) << "Decreased" << threadData->thread
+                      << "loop level to" << threadData->loopLevel
+                      << "with leaf loop now" << (threadData->eventLoops.isEmpty()
+                        ? nullptr : threadData->eventLoops.last());
+
         }
     };
     LoopReference ref(d, locker);

src/corelib/kernel/qobject.cpp

@@ -1430,6 +1430,7 @@ bool QObject::event(QEvent *e)
         break;
 
     case QEvent::DeferredDelete:
+        qCDebug(lcDeleteLater) << "Deferred deleting" << this;
         delete this;
         break;
 
@@ -2450,8 +2451,10 @@ void QObject::deleteLater()
     // as long as we're not guarding every access to the bit field.
 
     Q_D(QObject);
-    if (d->deleteLaterCalled)
+    if (d->deleteLaterCalled) {
+        qCDebug(lcDeleteLater) << "Skipping deleteLater for already deferred object" << this;
         return;
+    }
 
     d->deleteLaterCalled = true;
 
@@ -2477,9 +2480,15 @@ void QObject::deleteLater()
         // non-conformant code path, and our best guess is that the scope level
         // should be 1. (Loop level 0 is special: it means that no event loops
         // are running.)
-        if (scopeLevel == 0 && loopLevel != 0)
+        if (scopeLevel == 0 && loopLevel != 0) {
+            qCDebug(lcDeleteLater) << "Delete later called with scope level 0"
+                << "but loop level is > 0. Assuming scope is 1";
             scopeLevel = 1;
         }
+    }
+
+    qCDebug(lcDeleteLater) << "Posting deferred delete for" << this
+        << "with loop level" << loopLevel << "and scope level" << scopeLevel;
 
     eventListLocker.unlock();
     QCoreApplication::postEvent(this,

src/corelib/thread/qthread.cpp

@@ -147,6 +147,21 @@ void QAdoptedThread::run()
     qFatal("QAdoptedThread::run(): Internal error, this implementation should never be called.");
 }
 
+QScopedScopeLevelCounter::QScopedScopeLevelCounter(QThreadData *threadData)
+    : threadData(threadData)
+{
+    ++threadData->scopeLevel;
+    qCDebug(lcDeleteLater) << "Increased" << threadData->thread
+                      << "scope level to" << threadData->scopeLevel;
+}
+
+QScopedScopeLevelCounter::~QScopedScopeLevelCounter()
+{
+    --threadData->scopeLevel;
+    qCDebug(lcDeleteLater) << "Decreased" << threadData->thread
+                      << "scope level to" << threadData->scopeLevel;
+}
+
 /*
   QThreadPrivate
 */

src/corelib/thread/qthread_p.h

@@ -334,11 +334,8 @@ class QScopedScopeLevelCounter
 {
     QThreadData *threadData;
 public:
-    inline QScopedScopeLevelCounter(QThreadData *threadData)
-        : threadData(threadData)
-    { ++threadData->scopeLevel; }
-    inline ~QScopedScopeLevelCounter()
-    { --threadData->scopeLevel; }
+    QScopedScopeLevelCounter(QThreadData *threadData);
+    ~QScopedScopeLevelCounter();
 };
 
 // thread wrapper for the main() thread

src/corelib/thread/qthread_unix.cpp

@@ -347,6 +347,7 @@ void QThreadPrivate::finish(void *arg)
         void *data = &d->data->tls;
         locker.unlock();
         emit thr->finished(QThread::QPrivateSignal());
+        qCDebug(lcDeleteLater) << "Sending deferred delete events as part of finishing thread" << thr;
         QCoreApplication::sendPostedEvents(nullptr, QEvent::DeferredDelete);
         QThreadStorageData::finish((void **)data);
         locker.relock();

src/corelib/thread/qthread_win.cpp

@@ -316,6 +316,7 @@ void QThreadPrivate::finish(void *arg, bool lockAnyway) noexcept
     if (lockAnyway)
         locker.unlock();
     emit thr->finished(QThread::QPrivateSignal());
+    qCDebug(lcDeleteLater) << "Sending deferred delete events as part of finishing thread" << thr;
     QCoreApplicationPrivate::sendPostedEvents(nullptr, QEvent::DeferredDelete, d->data);
     QThreadStorageData::finish(tls_data);
     if (lockAnyway)