QmlMessageTrace: detect and combine repeated sections of backtraces

If there are multiple tracepoints, it happens quite often that the
most recent backtrace contains the backtrace that we already captured
in handling the previous tracepoint.  If the time difference is small
enough and we find such a duplicated sequence of methods, don't repeat
the Message output in the trace QML: pick up where the previous trace
left off.

Change-Id: I32f47430ab44fd7570569e0f347784d23197a3bc
Reviewed-by: Shawn Rutledge <shawn.rutledge@qt.io>

3 files changed, 47 insertions, 8 deletions

diff --git a/imports/Diagrams/UmlSequence/Message.qml b/imports/Diagrams/UmlSequence/Message.qml
index 92b441f..5b0ca94 100644
--- a/imports/Diagrams/UmlSequence/Message.qml
+++ b/imports/Diagrams/UmlSequence/Message.qml
@@ -47,13 +47,14 @@ MouseArea {
     property string params
     property string fromMethod
     property string backtrace
+    property bool inferredFromBacktrace: false
+    property bool toSelf: from && from === to
+    property bool backwards: from && to ? from.x > to.x : false
+    property real timestamp: 0
     width: 100
     height: 30
     hoverEnabled: true
     z: 1
-    property bool toSelf: from && from === to
-    property bool backwards: from && to ? from.x > to.x : false
-    property real timestamp: 0
     Text {
         x: -root.x
         text: root.timestamp
@@ -77,7 +78,7 @@ MouseArea {
     }
     Text {
         id: methodLabel
-        font.bold: true
+        font.bold: !root.inferredFromBacktrace
         anchors.horizontalCenter: parent.horizontalCenter
         anchors.verticalCenter: parent.verticalCenter
     }
diff --git a/src/trace/qmlmessagetrace.cpp b/src/trace/qmlmessagetrace.cpp
index fe6e72d..477ca48 100644
--- a/src/trace/qmlmessagetrace.cpp
+++ b/src/trace/qmlmessagetrace.cpp
@@ -148,6 +148,8 @@ QRegularExpression QmlMessageTrace::m_regexObjectFormatted(QStringLiteral(
 QRegularExpression QmlMessageTrace::m_regexPointer(QStringLiteral(
     "0[xX]([0-9a-fA-F]+)"));
 
+static const double BacktraceContinuationTimeLimit = 0.01;
+
 int QmlMessageTrace::m_refCount(0);
 
 static QString pointerHash(void* ptr)
@@ -330,6 +332,7 @@ void QmlMessageTrace::logBacktrace(QStringList trace)
     if (trace.length() < 2)
         return;
     Message m;
+    m.inferredFromBacktrace = true;
     m.timestamp = m_previousTimestamp;
     m.callerPointer = nullptr;
     m.calleePointer = nullptr;
@@ -424,12 +427,45 @@ void QmlMessageTrace::log(QtMsgType type, const QMessageLogContext &context, con
             addObjectInstance(nullptr, m.callerClass);
         }
         MT_DEBUG("   caller %p %s :: %s from %s\n", m.callerPointer, qPrintable(m.callerClass), qPrintable(m.callerMethod), qPrintable(callerClassAndMethod));
-        // TODO deduce where we are in the message trace from caller method
 
+        // find out if the backtrace leading up to the current method call
+        // is a continuation of m_previousBacktrace
         QStringList leadingBacktrace = m.backtrace;
-        leadingBacktrace.removeFirst();
+        MT_DEBUG("   backtrace %s\n", qPrintable(leadingBacktrace.join('|')));
+        MT_DEBUG("   previous  %s\n", qPrintable(m_previousBacktrace.join('|')));
+        MT_DEBUG("   time diff  %lf\n", m.timestamp - m_previousTimestamp);
+        if (m.timestamp - m_previousTimestamp < BacktraceContinuationTimeLimit && !m_previousBacktrace.isEmpty()) {
+            int idx = leadingBacktrace.indexOf(m_previousBacktrace.first());
+            bool isContinuation = (idx >= 0);
+            for ( int i = idx, j = 0;
+                  isContinuation && i < leadingBacktrace.length() && j < m_previousBacktrace.length();
+                  ++i, ++j) {
+                if (leadingBacktrace.at(i) != m_previousBacktrace.at(j)) {
+                    int iWas = i;
+                    while (++i < leadingBacktrace.length() && leadingBacktrace.at(i) != m_previousBacktrace.at(j)) { };
+                    if (i == leadingBacktrace.length()) {
+                        i = iWas;
+#ifdef MT_DEBUG_ENABLED
+                        int jWas = j;
+#endif
+                        while (++j < m_previousBacktrace.length() && leadingBacktrace.at(i) != m_previousBacktrace.at(j)) { };
+                        if (j == m_previousBacktrace.length()) {
+                            MT_DEBUG("   mismatch at %d:%d: %s != %s\n", iWas, jWas, qPrintable(leadingBacktrace.at(iWas)), qPrintable(m_previousBacktrace.at(jWas)));
+                            isContinuation = false;
+                        }
+                    }
+                }
+            }
+            if (isContinuation) {
+                MT_DEBUG("   truncating previously-seen backtrace after index %d\n", idx);
+                leadingBacktrace = leadingBacktrace.mid(0, idx);
+            } else {
+                MT_DEBUG("   nothing in common between backtraces");
+            }
+        }
 
         m_previousTimestamp = m.timestamp;
+        m_previousBacktrace = m.backtrace;
 
         logBacktrace(leadingBacktrace);
     }
@@ -495,9 +531,9 @@ QString QmlMessageTrace::Message::toQml() const
     QString callerId = callerPointer ? pointerHash(callerPointer) : QStringLiteral("ufo_") + callerClass;
     return QStringLiteral(
             "    Message { \n        from: %1\n        to: %2\n        method: \"%3\"\n        methodSignature: \"%4\"\n"
-            "        fromMethod: \"%5\"\n        timestamp: %6\n        backtrace: \"%7\"\n        params: \"%8\"\n    }\n")
+            "        fromMethod: \"%5\"\n        timestamp: %6\n        backtrace: \"%7\"\n        params: \"%8\"\n        inferredFromBacktrace: %9\n    }\n")
             .arg(callerId).arg(pointerHash(calleePointer)).arg(calleeMethod).arg(calleeSignature)
-            .arg(callerMethod).arg(timestamp).arg(backtrace.join(QStringLiteral("\\n"))).arg(params);
+            .arg(callerMethod).arg(timestamp).arg(backtrace.join(QStringLiteral("\\n"))).arg(params).arg(inferredFromBacktrace ? "true" : "false");
 }
 
 QT_END_NAMESPACE
diff --git a/src/trace/qmlmessagetrace_p.h b/src/trace/qmlmessagetrace_p.h
index 737b20d..ba4625b 100644
--- a/src/trace/qmlmessagetrace_p.h
+++ b/src/trace/qmlmessagetrace_p.h
@@ -84,6 +84,7 @@ private:
 private:
     struct Message {
         double timestamp;
+        bool inferredFromBacktrace = false;
         QtMsgType type;
         void *callerPointer;
         QString callerClass;
@@ -105,6 +106,7 @@ private:
     static int m_refCount;
 
     QList<Message> m_messages;
+    QStringList m_previousBacktrace;
     double m_previousTimestamp;
 
     QHash<QString, QString> m_tracedObjectsById;