Periodically flush profiling data to client.

This reduces memory usage as the data can be deleted once it is sent.
It also reduces the time it takes to transmit the data when profiling
is stopped. It does incur a runtime cost as the sending now takes place
while the application is running. The decision to periodically flush or
not is left to the client, who can specify a flush interval when
starting profiling.

Usage of the flushing feature also relaxes the guarantees regarding the
sorting of events before they are sent. Events with higher timestamps
are now allowed to arrive before events with lower timestamps. Any
clients implementing the flushing need to take this into account. This
will eventually allow us to do away with the server-side ordering
altogether.

Task-number: QTBUG-39756
Change-Id: Idaf4931dc17f224c2bd492078b99e88b1405234e
Reviewed-by: Simon Hausmann <simon.hausmann@theqtcompany.com>

src/qml/debugger/qqmlprofiler.cpp

@@ -110,7 +110,10 @@ qint64 QQmlProfilerAdapter::sendMessages(qint64 until, QList<QByteArray> &messag
 
 void QQmlProfilerAdapter::receiveData(const QVector<QQmlProfilerData> &new_data)
 {
-    data = new_data;
+    if (data.isEmpty())
+        data = new_data;
+    else
+        data.append(new_data);
     service->dataReady(this);
 }
 
@@ -131,16 +134,12 @@ void QQmlProfiler::stopProfiling()
 {
     featuresEnabled = false;
     reportData();
-    m_data.clear();
 }
 
 void QQmlProfiler::reportData()
 {
-    QVector<QQmlProfilerData> result;
-    result.reserve(m_data.size());
-    for (int i = 0; i < m_data.size(); ++i)
-        result.append(m_data[i]);
-    emit dataReady(result);
+    emit dataReady(m_data);
+    m_data.clear();
 }
 
 QT_END_NAMESPACE

src/qml/debugger/qqmlprofiler_p.h

@@ -175,7 +175,7 @@ signals:
 
 protected:
     QElapsedTimer m_timer;
-    QVarLengthArray<QQmlProfilerData> m_data;
+    QVector<QQmlProfilerData> m_data;
 };
 
 class QQmlProfilerAdapter : public QQmlAbstractProfilerAdapter {

src/qml/debugger/qqmlprofilerservice.cpp

@@ -48,7 +48,8 @@ QT_BEGIN_NAMESPACE
 Q_GLOBAL_STATIC(QQmlProfilerService, profilerInstance)
 
 QQmlProfilerService::QQmlProfilerService()
-    : QQmlConfigurableDebugService<QQmlDebugService>(QStringLiteral("CanvasFrameRate"), 1)
+    : QQmlConfigurableDebugService<QQmlDebugService>(QStringLiteral("CanvasFrameRate"), 1),
+      m_waitingForStop(false)
 {
     m_timer.start();
 }
@@ -242,6 +243,8 @@ void QQmlProfilerService::startProfiling(QQmlEngine *engine, quint64 features)
             if (!profiler->isRunning())
                 profiler->startProfiling(features);
         }
+
+        emit startFlushTimer();
     }
 
     emit messageToClient(name(), message);
@@ -273,6 +276,9 @@ void QQmlProfilerService::stopProfiling(QQmlEngine *engine)
         }
     }
 
+    if (stopping.isEmpty())
+        return;
+
     foreach (QQmlAbstractProfilerAdapter *profiler, m_globalProfilers) {
         if (!profiler->isRunning())
             continue;
@@ -284,6 +290,9 @@ void QQmlProfilerService::stopProfiling(QQmlEngine *engine)
         }
     }
 
+    emit stopFlushTimer();
+    m_waitingForStop = true;
+
     foreach (QQmlAbstractProfilerAdapter *profiler, reporting)
         profiler->reportData();
 
@@ -299,16 +308,19 @@ void QQmlProfilerService::sendMessages()
     QList<QByteArray> messages;
 
     QByteArray data;
-    QQmlDebugStream traceEnd(&data, QIODevice::WriteOnly);
-    traceEnd << m_timer.nsecsElapsed() << (int)Event << (int)EndTrace;
 
-    QSet<QQmlEngine *> seen;
-    foreach (QQmlAbstractProfilerAdapter *profiler, m_startTimes) {
-        for (QMultiHash<QQmlEngine *, QQmlAbstractProfilerAdapter *>::iterator i(m_engineProfilers.begin());
-                i != m_engineProfilers.end(); ++i) {
-            if (i.value() == profiler && !seen.contains(i.key())) {
-                seen << i.key();
-                traceEnd << idForObject(i.key());
+    if (m_waitingForStop) {
+        QQmlDebugStream traceEnd(&data, QIODevice::WriteOnly);
+        traceEnd << m_timer.nsecsElapsed() << (int)Event << (int)EndTrace;
+
+        QSet<QQmlEngine *> seen;
+        foreach (QQmlAbstractProfilerAdapter *profiler, m_startTimes) {
+            for (QMultiHash<QQmlEngine *, QQmlAbstractProfilerAdapter *>::iterator i(m_engineProfilers.begin());
+                    i != m_engineProfilers.end(); ++i) {
+                if (i.value() == profiler && !seen.contains(i.key())) {
+                    seen << i.key();
+                    traceEnd << idForObject(i.key());
+                }
             }
         }
     }
@@ -325,15 +337,26 @@ void QQmlProfilerService::sendMessages()
         }
     }
 
-    //indicate completion
-    messages << data;
-    data.clear();
+    if (m_waitingForStop) {
+        //indicate completion
+        messages << data;
+        data.clear();
 
-    QQmlDebugStream ds(&data, QIODevice::WriteOnly);
-    ds << (qint64)-1 << (int)Complete;
-    messages << data;
+        QQmlDebugStream ds(&data, QIODevice::WriteOnly);
+        ds << (qint64)-1 << (int)Complete;
+        messages << data;
+        m_waitingForStop = false;
+    }
 
     emit messagesToClient(name(), messages);
+
+    // Restart flushing if any profilers are still running
+    foreach (const QQmlAbstractProfilerAdapter *profiler, m_engineProfilers) {
+        if (profiler->isRunning()) {
+            emit startFlushTimer();
+            break;
+        }
+    }
 }
 
 void QQmlProfilerService::stateAboutToBeChanged(QQmlDebugService::State newState)
@@ -360,11 +383,25 @@ void QQmlProfilerService::messageReceived(const QByteArray &message)
     int engineId = -1;
     quint64 features = std::numeric_limits<quint64>::max();
     bool enabled;
+    uint flushInterval = 0;
     stream >> enabled;
     if (!stream.atEnd())
         stream >> engineId;
     if (!stream.atEnd())
         stream >> features;
+    if (!stream.atEnd()) {
+        stream >> flushInterval;
+        m_flushTimer.setInterval(flushInterval);
+        if (flushInterval > 0) {
+            connect(&m_flushTimer, SIGNAL(timeout()), this, SLOT(flush()));
+            connect(this, SIGNAL(startFlushTimer()), &m_flushTimer, SLOT(start()));
+            connect(this, SIGNAL(stopFlushTimer()), &m_flushTimer, SLOT(stop()));
+        } else {
+            disconnect(&m_flushTimer, SIGNAL(timeout()), this, SLOT(flush()));
+            disconnect(this, SIGNAL(startFlushTimer()), &m_flushTimer, SLOT(start()));
+            disconnect(this, SIGNAL(stopFlushTimer()), &m_flushTimer, SLOT(stop()));
+        }
+    }
 
     // If engineId == -1 objectForId() and then the cast will return 0.
     if (enabled)
@@ -375,4 +412,23 @@ void QQmlProfilerService::messageReceived(const QByteArray &message)
     stopWaiting();
 }
 
+void QQmlProfilerService::flush()
+{
+    QMutexLocker lock(&m_configMutex);
+
+    foreach (QQmlAbstractProfilerAdapter *profiler, m_engineProfilers) {
+        if (profiler->isRunning()) {
+            m_startTimes.insert(-1, profiler);
+            profiler->reportData();
+        }
+    }
+
+    foreach (QQmlAbstractProfilerAdapter *profiler, m_globalProfilers) {
+        if (profiler->isRunning()) {
+            m_startTimes.insert(-1, profiler);
+            profiler->reportData();
+        }
+    }
+}
+
 QT_END_NAMESPACE

src/qml/debugger/qqmlprofilerservice_p.h

@@ -57,6 +57,7 @@
 #include <QtCore/qvector.h>
 #include <QtCore/qstringbuilder.h>
 #include <QtCore/qwaitcondition.h>
+#include <QtCore/qtimer.h>
 
 #include <limits>
 
@@ -90,6 +91,13 @@ public:
 
     void dataReady(QQmlAbstractProfilerAdapter *profiler);
 
+signals:
+    void startFlushTimer();
+    void stopFlushTimer();
+
+private slots:
+    void flush();
+
 protected:
     virtual void stateAboutToBeChanged(State state);
     virtual void messageReceived(const QByteArray &);
@@ -101,6 +109,8 @@ private:
     void removeProfilerFromStartTimes(const QQmlAbstractProfilerAdapter *profiler);
 
     QElapsedTimer m_timer;
+    QTimer m_flushTimer;
+    bool m_waitingForStop;
 
     QList<QQmlAbstractProfilerAdapter *> m_globalProfilers;
     QMultiHash<QQmlEngine *, QQmlAbstractProfilerAdapter *> m_engineProfilers;

src/qml/debugger/qv4profileradapter.cpp

@@ -70,16 +70,34 @@ qint64 QV4ProfilerAdapter::appendMemoryEvents(qint64 until, QList<QByteArray> &m
     return memory_data.length() == memoryPos ? -1 : memory_data[memoryPos].timestamp;
 }
 
+qint64 QV4ProfilerAdapter::finalizeMessages(qint64 until, QList<QByteArray> &messages,
+                                            qint64 callNext)
+{
+    if (callNext == -1) {
+        data.clear();
+        dataPos = 0;
+    }
+
+    qint64 memoryNext = appendMemoryEvents(until, messages);
+
+    if (memoryNext == -1) {
+        memory_data.clear();
+        memoryPos = 0;
+        return callNext;
+    }
+
+    return callNext == -1 ? memoryNext : qMin(callNext, memoryNext);
+}
+
 qint64 QV4ProfilerAdapter::sendMessages(qint64 until, QList<QByteArray> &messages)
 {
     QByteArray message;
     while (true) {
         while (!stack.isEmpty() && (dataPos == data.length() ||
                                     stack.top() <= data[dataPos].start)) {
-            if (stack.top() > until) {
-                qint64 memoryNext = appendMemoryEvents(until, messages);
-                return memoryNext == -1 ? stack.top() : qMin(stack.top(), memoryNext);
-            }
+            if (stack.top() > until)
+                return finalizeMessages(until, messages, stack.top());
+
             appendMemoryEvents(stack.top(), messages);
             QQmlDebugStream d(&message, QIODevice::WriteOnly);
             d << stack.pop() << RangeEnd << Javascript;
@@ -87,10 +105,9 @@ qint64 QV4ProfilerAdapter::sendMessages(qint64 until, QList<QByteArray> &message
         }
         while (dataPos != data.length() && (stack.empty() || data[dataPos].start < stack.top())) {
             const QV4::Profiling::FunctionCallProperties &props = data[dataPos];
-            if (props.start > until) {
-                qint64 memory_next = appendMemoryEvents(until, messages);
-                return memory_next == -1 ? props.start : qMin(props.start, memory_next);
-            }
+            if (props.start > until)
+                return finalizeMessages(until, messages, props.start);
+
             appendMemoryEvents(props.start, messages);
 
             QQmlDebugStream d_start(&message, QIODevice::WriteOnly);
@@ -110,7 +127,7 @@ qint64 QV4ProfilerAdapter::sendMessages(qint64 until, QList<QByteArray> &message
             ++dataPos;
         }
         if (stack.empty() && dataPos == data.length())
-            return appendMemoryEvents(until, messages);
+            return finalizeMessages(until, messages, -1);
     }
 }
 
@@ -118,10 +135,19 @@ void QV4ProfilerAdapter::receiveData(
         const QVector<QV4::Profiling::FunctionCallProperties> &new_data,
         const QVector<QV4::Profiling::MemoryAllocationProperties> &new_memory_data)
 {
-    data = new_data;
-    memory_data = new_memory_data;
-    dataPos = memoryPos = 0;
-    stack.clear();
+    // In rare cases it could be that another flush or stop event is processed while data from
+    // the previous one is still pending. In that case we just append the data.
+
+    if (data.isEmpty())
+        data = new_data;
+    else
+        data.append(new_data);
+
+    if (memory_data.isEmpty())
+        memory_data = new_memory_data;
+    else
+        memory_data.append(new_memory_data);
+
     service->dataReady(this);
 }
 

src/qml/debugger/qv4profileradapter_p.h

@@ -73,6 +73,7 @@ private:
     int memoryPos;
     QStack<qint64> stack;
     qint64 appendMemoryEvents(qint64 until, QList<QByteArray> &messages);
+    qint64 finalizeMessages(qint64 until, QList<QByteArray> &messages, qint64 callNext);
 };
 
 QT_END_NAMESPACE

src/qml/jsruntime/qv4profiling.cpp

@@ -84,14 +84,13 @@ void Profiler::reportData()
         resolved.insert(std::upper_bound(resolved.begin(), resolved.end(), props, comp), props);
     }
     emit dataReady(resolved, m_memory_data);
+    m_data.clear();
+    m_memory_data.clear();
 }
 
 void Profiler::startProfiling(quint64 features)
 {
     if (featuresEnabled == 0) {
-        m_data.clear();
-        m_memory_data.clear();
-
         if (features & (1 << FeatureMemoryAllocation)) {
             qint64 timestamp = m_timer.nsecsElapsed();
             MemoryAllocationProperties heap = {timestamp,

src/quick/util/qquickprofiler.cpp

@@ -113,10 +113,15 @@ void QQuickProfilerData::toByteArrays(QList<QByteArray> &messages) const
 qint64 QQuickProfiler::sendMessages(qint64 until, QList<QByteArray> &messages)
 {
     QMutexLocker lock(&m_dataMutex);
-    while (next < m_data.size() && m_data[next].time <= until) {
-        m_data[next++].toByteArrays(messages);
+    while (next < m_data.size()) {
+        if (m_data[next].time <= until)
+            m_data[next++].toByteArrays(messages);
+        else
+            return m_data[next].time;
     }
-    return next < m_data.size() ? m_data[next].time : -1;
+    m_data.clear();
+    next = 0;
+    return -1;
 }
 
 void QQuickProfiler::initialize()
@@ -196,17 +201,12 @@ void QQuickProfiler::stopProfilingImpl()
     {
         QMutexLocker lock(&m_dataMutex);
         featuresEnabled = 0;
-        next = 0;
     }
     service->dataReady(this);
 }
 
 void QQuickProfiler::reportDataImpl()
 {
-    {
-        QMutexLocker lock(&m_dataMutex);
-        next = 0;
-    }
     service->dataReady(this);
 }
 

tests/auto/qml/debugger/qqmlprofilerservice/data/timer.qml

@@ -0,0 +1,14 @@
+import QtQuick 2.0
+
+Rectangle {
+    width: 100
+    height: 62
+
+    Timer {
+        running: true
+        repeat: true
+        interval: 50
+        onTriggered: height = (2 * height) % 99;
+    }
+}
+

tests/auto/qml/debugger/qqmlprofilerservice/qqmlprofilerservice.pro

@@ -21,4 +21,5 @@ OTHER_FILES += \
     data/scenegraphTest.qml \
     data/TestImage_2x2.png \
     data/signalSourceLocation.qml \
-    data/javascript.qml
+    data/javascript.qml \
+    data/timer.qml

tests/auto/qml/debugger/qqmlprofilerservice/tst_qqmlprofilerservice.cpp

@@ -145,10 +145,12 @@ public:
     QVector<QQmlProfilerData> asynchronousMessages;
     QVector<QQmlProfilerData> pixmapMessages;
 
-    void setTraceState(bool enabled) {
+    void setTraceState(bool enabled, quint32 flushInterval = 0) {
         QByteArray message;
         QDataStream stream(&message, QIODevice::WriteOnly);
         stream << enabled;
+        if (enabled && flushInterval)
+            stream << -1 << std::numeric_limits<quint64>::max() << flushInterval;
         sendMessage(message);
     }
 
@@ -213,6 +215,7 @@ private slots:
     void controlFromJS();
     void signalSourceLocation();
     void javascript();
+    void flushInterval();
 };
 
 #define VERIFY(type, position, expected, checks) QVERIFY(verify(type, position, expected, checks))
@@ -766,6 +769,24 @@ void tst_QQmlProfilerService::javascript()
     VERIFY(MessageListJavaScript, 21, expected, CheckMessageType | CheckDetailType);
 }
 
+void tst_QQmlProfilerService::flushInterval()
+{
+    connect(true, "timer.qml");
+    QVERIFY(m_client);
+    QTRY_COMPARE(m_client->state(), QQmlDebugClient::Enabled);
+
+    m_client->setTraceState(true, 1);
+
+    // Make sure we get multiple messages
+    QTRY_VERIFY(m_client->qmlMessages.length() > 0);
+    QVERIFY(m_client->qmlMessages.length() < 100);
+    QTRY_VERIFY(m_client->qmlMessages.length() > 100);
+
+    m_client->setTraceState(false);
+    checkTraceReceived();
+    checkJsHeap();
+}
+
 QTEST_MAIN(tst_QQmlProfilerService)
 
 #include "tst_qqmlprofilerservice.moc"