QmlProfiler: Change total time and recursion display in statistics

The total time taken for a program should be the sum of durations of
events on the bottom of the stack. This is also what the flame graph
model does, and it results in useful percentages for total and self
times.

Recursion still has to be accounted for when showing the total time of
a specific event type, but we mark events with recursive calls and
show the time and percentage of recursion in the tooltip. As we already
showed binding loops on bindings and signal handlers before, this
integrates nicely.

Change-Id: Id4654e314bf86ce8bd06ceaaf93a67187c629adc
Reviewed-by: Christian Kandeler <christian.kandeler@qt.io>
Reviewed-by: Ulf Hermann <ulf.hermann@qt.io>

src/plugins/qmlprofiler/qmlprofilerstatisticsmodel.cpp

@@ -52,16 +52,27 @@ public:
     int modelId;
 
     QList<RangeType> acceptedTypes;
-    QSet<int> eventsInBindingLoop;
     QHash<int, QString> notes;
 
     QStack<QmlEvent> callStack;
     QStack<QmlEvent> compileStack;
-    qint64 qmlTime = 0;
-    qint64 lastEndTime = 0;
     QHash <int, QVector<qint64> > durations;
 };
 
+double QmlProfilerStatisticsModel::durationPercent(int typeId) const
+{
+    const QmlEventStats &global = d->data[-1];
+    const QmlEventStats &stats = d->data[typeId];
+    return double(stats.duration - stats.durationRecursive) / double(global.duration) * 100l;
+}
+
+double QmlProfilerStatisticsModel::durationSelfPercent(int typeId) const
+{
+    const QmlEventStats &global = d->data[-1];
+    const QmlEventStats &stats = d->data[typeId];
+    return double(stats.durationSelf) / double(global.duration) * 100l;
+}
+
 QmlProfilerStatisticsModel::QmlProfilerStatisticsModel(QmlProfilerModelManager *modelManager,
                                                QObject *parent) :
     QObject(parent), d(new QmlProfilerStatisticsModelPrivate)
@@ -136,12 +147,9 @@ const QHash<int, QString> &QmlProfilerStatisticsModel::getNotes() const
 void QmlProfilerStatisticsModel::clear()
 {
     d->data.clear();
-    d->eventsInBindingLoop.clear();
     d->notes.clear();
     d->callStack.clear();
     d->compileStack.clear();
-    d->qmlTime = 0;
-    d->lastEndTime = 0;
     d->durations.clear();
     if (!d->childrenModel.isNull())
         d->childrenModel->clear();
@@ -206,18 +214,10 @@ void QmlProfilerStatisticsModel::loadEvent(const QmlEvent &event, const QmlEvent
     if (!d->acceptedTypes.contains(type.rangeType()))
         return;
 
+    bool isRecursive = false;
     QStack<QmlEvent> &stack = type.rangeType() == Compiling ? d->compileStack : d->callStack;
     switch (event.rangeStage()) {
     case RangeStart:
-        // binding loop detection: check whether event is already in stack
-        if (type.rangeType() == Binding || type.rangeType() == HandlingSignal) {
-            for (int ii = 0; ii < stack.size(); ++ii) {
-                if (stack.at(ii).typeIndex() == event.typeIndex()) {
-                    d->eventsInBindingLoop.insert(event.typeIndex());
-                    break;
-                }
-            }
-        }
         stack.push(event);
         break;
     case RangeEnd: {
@@ -234,16 +234,21 @@ void QmlProfilerStatisticsModel::loadEvent(const QmlEvent &event, const QmlEvent
         stats->calls++;
         // for median computing
         d->durations[event.typeIndex()].append(duration);
-        // qml time computation
-        if (event.timestamp() > d->lastEndTime) { // assume parent event if starts before last end
-            d->qmlTime += duration;
-            d->lastEndTime = event.timestamp();
-        }
-
         stack.pop();
 
+        // recursion detection: check whether event was already in stack
+        for (int ii = 0; ii < stack.size(); ++ii) {
+            if (stack.at(ii).typeIndex() == event.typeIndex()) {
+                isRecursive = true;
+                stats->durationRecursive += duration;
+                break;
+            }
+        }
+
         if (!stack.isEmpty())
             d->data[stack.top().typeIndex()].durationSelf -= duration;
+        else
+            d->data[-1].duration += duration;
         break;
     }
     default:
@@ -251,9 +256,9 @@ void QmlProfilerStatisticsModel::loadEvent(const QmlEvent &event, const QmlEvent
     }
 
     if (!d->childrenModel.isNull())
-        d->childrenModel->loadEvent(type.rangeType(), event);
+        d->childrenModel->loadEvent(type.rangeType(), event, isRecursive);
     if (!d->parentsModel.isNull())
-        d->parentsModel->loadEvent(type.rangeType(), event);
+        d->parentsModel->loadEvent(type.rangeType(), event, isRecursive);
 }
 
 
@@ -261,39 +266,18 @@ void QmlProfilerStatisticsModel::finalize()
 {
     // post-process: calc mean time, median time, percentoftime
     for (QHash<int, QmlEventStats>::iterator it = d->data.begin(); it != d->data.end(); ++it) {
-        QmlEventStats* stats = &it.value();
-        if (stats->calls > 0)
-            stats->timePerCall = stats->duration / (double)stats->calls;
-
         QVector<qint64> eventDurations = d->durations[it.key()];
         if (!eventDurations.isEmpty()) {
             Utils::sort(eventDurations);
-            stats->medianTime = eventDurations.at(eventDurations.count()/2);
+            it->medianTime = eventDurations.at(eventDurations.count()/2);
         }
-
-        stats->percentOfTime = stats->duration * 100.0 / d->qmlTime;
-        stats->percentSelf = stats->durationSelf * 100.0 / d->qmlTime;
     }
 
-    // set binding loop flag
-    foreach (int typeIndex, d->eventsInBindingLoop)
-        d->data[typeIndex].isBindingLoop = true;
-
     // insert root event
-    QmlEventStats rootEvent;
+    QmlEventStats &rootEvent = d->data[-1];
-    rootEvent.duration = rootEvent.minTime = rootEvent.maxTime = rootEvent.timePerCall
+    rootEvent.minTime = rootEvent.maxTime = rootEvent.medianTime = rootEvent.duration;
-                       = rootEvent.medianTime = d->qmlTime + 1;
+    rootEvent.durationSelf = 0;
-    rootEvent.durationSelf = 1;
     rootEvent.calls = 1;
-    rootEvent.percentOfTime = 100.0;
-    rootEvent.percentSelf = 1.0 / rootEvent.duration;
-
-    d->data.insert(-1, rootEvent);
-
-    if (!d->childrenModel.isNull())
-        d->childrenModel->finalize(d->eventsInBindingLoop);
-    if (!d->parentsModel.isNull())
-        d->parentsModel->finalize(d->eventsInBindingLoop);
 
     emit dataAvailable();
 }
@@ -337,7 +321,8 @@ const QVector<QmlEventType> &QmlProfilerStatisticsRelativesModel::getTypes() con
     return m_modelManager->qmlModel()->eventTypes();
 }
 
-void QmlProfilerStatisticsRelativesModel::loadEvent(RangeType type, const QmlEvent &event)
+void QmlProfilerStatisticsRelativesModel::loadEvent(RangeType type, const QmlEvent &event,
+                                                    bool isRecursive)
 {
     QStack<Frame> &stack = (type == Compiling) ? m_compileStack : m_callStack;
 
@@ -355,13 +340,14 @@ void QmlProfilerStatisticsRelativesModel::loadEvent(RangeType type, const QmlEve
         QmlStatisticsRelativesMap &relativesMap = m_data[selfTypeIndex];
         QmlStatisticsRelativesMap::Iterator it = relativesMap.find(relativeTypeIndex);
         if (it != relativesMap.end()) {
-            it.value().calls++;
+            it->calls++;
-            it.value().duration += event.timestamp() - stack.top().startTime;
+            it->duration += event.timestamp() - stack.top().startTime;
+            it->isRecursive = isRecursive || it->isRecursive;
         } else {
             QmlStatisticsRelativesData relative = {
                 event.timestamp() - stack.top().startTime,
                 1,
-                false
+                isRecursive
             };
             relativesMap.insert(relativeTypeIndex, relative);
         }
@@ -373,18 +359,6 @@ void QmlProfilerStatisticsRelativesModel::loadEvent(RangeType type, const QmlEve
     }
 }
 
-void QmlProfilerStatisticsRelativesModel::finalize(const QSet<int> &eventsInBindingLoop)
-{
-    for (auto map = m_data.begin(), mapEnd = m_data.end(); map != mapEnd; ++map) {
-        auto itemEnd = map->end();
-        foreach (int typeIndex, eventsInBindingLoop) {
-            auto item = map->find(typeIndex);
-            if (item != itemEnd)
-                item->isBindingLoop = true;
-        }
-    }
-}
-
 QmlProfilerStatisticsRelation QmlProfilerStatisticsRelativesModel::relation() const
 {
     return m_relation;

src/plugins/qmlprofiler/qmlprofilerstatisticsmodel.h

@@ -50,22 +50,20 @@ class QmlProfilerStatisticsModel : public QObject
     Q_OBJECT
 public:
     struct QmlEventStats {
-        QmlEventStats() : duration(0), durationSelf(0), calls(0),
+        QmlEventStats() : duration(0), durationSelf(0), durationRecursive(0), calls(0),
-            minTime(std::numeric_limits<qint64>::max()), maxTime(0), timePerCall(0),
+            minTime(std::numeric_limits<qint64>::max()), maxTime(0), medianTime(0) {}
-            percentOfTime(0), percentSelf(0), medianTime(0), isBindingLoop(false) {}
         qint64 duration;
         qint64 durationSelf;
+        qint64 durationRecursive;
         qint64 calls;
         qint64 minTime;
         qint64 maxTime;
-        qint64 timePerCall;
-        double percentOfTime;
-        double percentSelf;
         qint64 medianTime;
-
-        bool isBindingLoop;
     };
 
+    double durationPercent(int typeId) const;
+    double durationSelfPercent(int typeId) const;
+
     QmlProfilerStatisticsModel(QmlProfilerModelManager *modelManager, QObject *parent = 0);
     ~QmlProfilerStatisticsModel();
 
@@ -107,7 +105,7 @@ public:
     struct QmlStatisticsRelativesData {
         qint64 duration;
         qint64 calls;
-        bool isBindingLoop;
+        bool isRecursive;
     };
     typedef QHash <int, QmlStatisticsRelativesData> QmlStatisticsRelativesMap;
 
@@ -122,8 +120,7 @@ public:
     const QmlStatisticsRelativesMap &getData(int typeId) const;
     const QVector<QmlEventType> &getTypes() const;
 
-    void loadEvent(RangeType type, const QmlEvent &event);
+    void loadEvent(RangeType type, const QmlEvent &event, bool isRecursive);
-    void finalize(const QSet<int> &eventsInBindingLoop);
 
     QmlProfilerStatisticsRelation relation() const;
 

src/plugins/qmlprofiler/qmlprofilerstatisticsview.cpp

@@ -233,7 +233,7 @@ QString QmlProfilerStatisticsView::summary(const QVector<int> &typeIds) const
     double sum = 0;
 
     for (int typeId : typeIds) {
-        const double percentage = d->model->getData()[typeId].percentOfTime;
+        const double percentage = d->model->durationPercent(typeId);
         if (percentage > maximum)
             maximum = percentage;
         sum += percentage;
@@ -268,7 +268,7 @@ QStringList QmlProfilerStatisticsView::details(int typeId) const
     return QStringList({
         QmlProfilerStatisticsMainView::nameForType(type.rangeType()),
         data,
-        QString::number(d->model->getData()[typeId].percentOfTime, 'f', 2) + QLatin1Char('%')
+        QString::number(d->model->durationPercent(typeId), 'f', 2) + QLatin1Char('%')
     });
 }
 
@@ -576,9 +576,11 @@ void QmlProfilerStatisticsMainView::updateNotes(int typeIndex)
             if (it != noteList.end()) {
                 item->setBackground(colors()->noteBackground);
                 item->setToolTip(it.value());
-            } else if (stats.isBindingLoop) {
+            } else if (stats.durationRecursive > 0) {
                 item->setBackground(colors()->noteBackground);
-                item->setToolTip(tr("Binding loop detected."));
+                item->setToolTip(tr("%1 / %2% of total in recursive calls")
+                                 .arg(Timeline::formatTime(stats.durationRecursive))
+                                 .arg(stats.durationRecursive * 100l / stats.duration));
             } else if (!item->toolTip().isEmpty()){
                 item->setBackground(colors()->defaultBackground);
                 item->setToolTip(QString());
@@ -611,8 +613,9 @@ void QmlProfilerStatisticsMainView::parseModel()
         }
 
         if (d->m_fieldShown[TimeInPercent]) {
-            newRow << new StatisticsViewItem(QString::number(stats.percentOfTime, 'f', 2)
+            const double percent = d->model->durationPercent(typeIndex);
-                                             + QLatin1String(" %"), stats.percentOfTime);
+            newRow << new StatisticsViewItem(QString::number(percent, 'f', 2)
+                                             + QLatin1String(" %"), percent);
         }
 
         if (d->m_fieldShown[TotalTime]) {
@@ -621,8 +624,9 @@ void QmlProfilerStatisticsMainView::parseModel()
         }
 
         if (d->m_fieldShown[SelfTimeInPercent]) {
-            newRow << new StatisticsViewItem(QString::number(stats.percentSelf, 'f', 2)
+            const double percentSelf = d->model->durationSelfPercent(typeIndex);
-                                             + QLatin1String(" %"), stats.percentSelf);
+            newRow << new StatisticsViewItem(QString::number(percentSelf, 'f', 2)
+                                             + QLatin1String(" %"), percentSelf);
         }
 
         if (d->m_fieldShown[SelfTime]) {
@@ -634,8 +638,9 @@ void QmlProfilerStatisticsMainView::parseModel()
             newRow << new StatisticsViewItem(QString::number(stats.calls), stats.calls);
 
         if (d->m_fieldShown[TimePerCall]) {
-            newRow << new StatisticsViewItem(Timeline::formatTime(stats.timePerCall),
+            const qint64 timePerCall = stats.duration / stats.calls;
-                                             stats.timePerCall);
+            newRow << new StatisticsViewItem(Timeline::formatTime(timePerCall),
+                                             timePerCall);
         }
 
         if (d->m_fieldShown[MedianTime]) {
@@ -909,10 +914,10 @@ void QmlProfilerStatisticsRelativesView::rebuildTree(
         newRow.at(3)->setData(stats.calls);
         newRow.at(4)->setData(type.data());
 
-        if (stats.isBindingLoop) {
+        if (stats.isRecursive) {
             foreach (QStandardItem *item, newRow) {
                 item->setBackground(colors()->noteBackground);
-                item->setToolTip(tr("Part of binding loop."));
+                item->setToolTip(tr("called recursively"));
             }
         }