Make tracing a runtime option

- Moved most of the code QSystemInformationService (private class
  for now)
- Tracing can be enabled by setting QT3D_TRACE_ENABLED or
  calling QSystemInformationService::setTraceEnabled(bool)
- Introduced QTaskLogger class to easy logging (RAII)

Change-Id: I2a3e08e4371fcee3e9ef3cf575725f13f57d1a94
Reviewed-by: Paul Lemire <paul.lemire@kdab.com>

5 files changed, 333 insertions, 28 deletions

diff --git a/src/core/services/nullservices_p.h b/src/core/services/nullservices_p.h
index 30dc2d543..6b2d1b029 100644
--- a/src/core/services/nullservices_p.h
+++ b/src/core/services/nullservices_p.h
@@ -54,25 +54,11 @@
 #include <Qt3DCore/qt3dcore_global.h>
 
 #include <Qt3DCore/private/qopenglinformationservice_p.h>
-#include <Qt3DCore/private/qsysteminformationservice_p.h>
 
 QT_BEGIN_NAMESPACE
 
 namespace Qt3DCore {
 
-class NullSystemInformationService : public QSystemInformationService
-{
-public:
-    NullSystemInformationService()
-        : QSystemInformationService(QStringLiteral("Null System Information Service"))
-    {}
-    ~NullSystemInformationService() {}
-
-    QStringList aspectNames() const final { return QStringList(); }
-    int threadPoolThreadCount() const final { return 0; }
-};
-
-
 class NullOpenGLInformationService : public QOpenGLInformationService
 {
 public:
diff --git a/src/core/services/qservicelocator.cpp b/src/core/services/qservicelocator.cpp
index bdcb4a521..5df33dae9 100644
--- a/src/core/services/qservicelocator.cpp
+++ b/src/core/services/qservicelocator.cpp
@@ -46,6 +46,7 @@
 #include <Qt3DCore/private/qdownloadhelperservice_p.h>
 #include <Qt3DCore/private/qeventfilterservice_p.h>
 #include <Qt3DCore/private/qtickclockservice_p.h>
+#include <Qt3DCore/private/qsysteminformationservice_p.h>
 
 
 QT_BEGIN_NAMESPACE
@@ -94,7 +95,7 @@ public:
 
     QHash<int, QAbstractServiceProvider *> m_services;
 
-    NullSystemInformationService m_nullSystemInfo;
+    QSystemInformationService m_systemInfo;
     NullOpenGLInformationService m_nullOpenGLInfo;
     QTickClockService m_defaultFrameAdvanceService;
     QEventFilterService m_eventFilterService;
@@ -196,7 +197,7 @@ int QServiceLocator::serviceCount() const
 QSystemInformationService *QServiceLocator::systemInformation()
 {
     Q_D(QServiceLocator);
-    return static_cast<QSystemInformationService *>(d->m_services.value(SystemInformation, &d->m_nullSystemInfo));
+    return static_cast<QSystemInformationService *>(d->m_services.value(SystemInformation, &d->m_systemInfo));
 }
 
 /*
diff --git a/src/core/services/qsysteminformationservice.cpp b/src/core/services/qsysteminformationservice.cpp
index f11e0c3d1..6a8cbee04 100644
--- a/src/core/services/qsysteminformationservice.cpp
+++ b/src/core/services/qsysteminformationservice.cpp
@@ -40,10 +40,206 @@
 #include "qsysteminformationservice_p.h"
 #include "qsysteminformationservice_p_p.h"
 
+#ifdef Q_OS_ANDROID
+#include <QtCore/QStandardPaths>
+#endif
+
+#include <QtCore/QThreadPool>
+#include <QtCore/QCoreApplication>
+#include <QtCore/QFile>
+#include <QtCore/QDateTime>
+#include <QtCore/QCoreApplication>
+
 QT_BEGIN_NAMESPACE
 
+namespace  {
+
+struct FrameHeader
+{
+    FrameHeader()
+        : frameId(0)
+        , jobCount(0)
+        , frameType(WorkerJob)
+    {
+    }
+
+    enum FrameType {
+        WorkerJob = 0,
+        Submission
+    };
+
+    quint32 frameId;
+    quint16 jobCount;
+    quint16 frameType; // Submission or worker job
+};
+
+}
 namespace Qt3DCore {
 
+QSystemInformationServicePrivate::QSystemInformationServicePrivate(const QString &description)
+    : QAbstractServiceProviderPrivate(QServiceLocator::SystemInformation, description)
+    , m_submissionStorage(nullptr)
+    , m_frameId(0)
+{
+    m_traceEnabled = qEnvironmentVariableIsSet("QT3D_TRACE_ENABLED");
+    if (m_traceEnabled)
+        m_jobsStatTimer.start();
+}
+
+QSystemInformationServicePrivate::~QSystemInformationServicePrivate() = default;
+
+QSystemInformationServicePrivate *QSystemInformationServicePrivate::get(QSystemInformationService *q)
+{
+    return q->d_func();
+}
+
+// Called by the jobs
+void QSystemInformationServicePrivate::addJobLogStatsEntry(QSystemInformationServicePrivate::JobRunStats &stats)
+{
+    if (!m_traceEnabled)
+        return;
+
+    if (!m_jobStatsCached.hasLocalData()) {
+        auto jobVector = new QVector<JobRunStats>;
+        m_jobStatsCached.setLocalData(jobVector);
+        QMutexLocker lock(&m_localStoragesMutex);
+        m_localStorages.push_back(jobVector);
+    }
+    m_jobStatsCached.localData()->push_back(stats);
+}
+
+// Called from Submission thread (which can be main thread in Manual drive mode)
+void QSystemInformationServicePrivate::addSubmissionLogStatsEntry(QSystemInformationServicePrivate::JobRunStats &stats)
+{
+    if (!m_traceEnabled)
+        return;
+
+    QMutexLocker lock(&m_localStoragesMutex);
+    if (!m_jobStatsCached.hasLocalData()) {
+        m_submissionStorage = new QVector<JobRunStats>;
+        m_jobStatsCached.setLocalData(m_submissionStorage);
+    }
+
+    // Handle the case where submission thread is also the main thread (Scene/Manual drive modes with no RenderThread)
+    if (m_submissionStorage == nullptr && m_jobStatsCached.hasLocalData())
+        m_submissionStorage = new QVector<JobRunStats>;
+
+    // When having no submission thread this can be null
+    m_submissionStorage->push_back(stats);
+}
+
+// Called after jobs have been executed (MainThread QAspectJobManager::enqueueJobs)
+void QSystemInformationServicePrivate::writeFrameJobLogStats()
+{
+    if (!m_traceEnabled)
+        return;
+
+    using JobRunStats = QSystemInformationServicePrivate::JobRunStats;
+
+    if (!m_traceFile) {
+        const QString fileName = QStringLiteral("trace_") + QCoreApplication::applicationName() + QDateTime::currentDateTime().toString(QStringLiteral("_ddd_dd_MM_yy-hh_mm_ss_"))+ QSysInfo::productType() + QStringLiteral("_") + QSysInfo::buildAbi() + QStringLiteral(".qt3d");
+#ifdef Q_OS_ANDROID
+        m_traceFile.reset(new QFile(QStandardPaths::writableLocation(QStandardPaths::DownloadLocation) + QStringLiteral("/") + fileName));
+#else
+        // TODO fix for iOS
+        m_traceFile.reset(new QFile(fileName));
+#endif
+        if (!m_traceFile->open(QFile::WriteOnly|QFile::Truncate))
+            qCritical("Failed to open trace file");
+    }
+
+    // Write Aspect + Job threads
+    {
+        FrameHeader header;
+        header.frameId = m_frameId;
+        header.jobCount = 0;
+
+        for (const QVector<JobRunStats> *storage : qAsConst(m_localStorages))
+            header.jobCount += storage->size();
+
+        m_traceFile->write(reinterpret_cast<char *>(&header), sizeof(FrameHeader));
+
+        for (QVector<JobRunStats> *storage : qAsConst(m_localStorages)) {
+            for (const JobRunStats &stat : *storage)
+                m_traceFile->write(reinterpret_cast<const char *>(&stat), sizeof(JobRunStats));
+            storage->clear();
+        }
+    }
+
+    // Write submission thread
+    {
+        QMutexLocker lock(&m_localStoragesMutex);
+        const int submissionJobSize = m_submissionStorage != nullptr ? m_submissionStorage->size() : 0;
+        if (submissionJobSize > 0) {
+            FrameHeader header;
+            header.frameId = m_frameId;
+            header.jobCount = submissionJobSize;
+            header.frameType = FrameHeader::Submission;
+
+            m_traceFile->write(reinterpret_cast<char *>(&header), sizeof(FrameHeader));
+
+            for (const JobRunStats &stat : *m_submissionStorage)
+                m_traceFile->write(reinterpret_cast<const char *>(&stat), sizeof(JobRunStats));
+            m_submissionStorage->clear();
+        }
+    }
+
+    m_traceFile->flush();
+    ++m_frameId;
+}
+
+
+QTaskLogger::QTaskLogger(QSystemInformationService *service, const JobId &jobId, Type type)
+    : m_service(service && service->isTraceEnabled() ? service : nullptr)
+    , m_type(type)
+{
+    m_stats.jobId = jobId;
+    if (m_service) {
+        m_stats.startTime = QSystemInformationServicePrivate::get(m_service)->m_jobsStatTimer.nsecsElapsed();
+        m_stats.threadId = reinterpret_cast<quint64>(QThread::currentThreadId());
+    }
+}
+
+QTaskLogger::QTaskLogger(QSystemInformationService *service,
+                         const quint32 jobType,
+                         const quint32 instance,
+                         QTaskLogger::Type type)
+    : m_service(service && service->isTraceEnabled() ? service : nullptr)
+    , m_type(type)
+{
+    m_stats.jobId.typeAndInstance[0] = jobType;
+    m_stats.jobId.typeAndInstance[1] = instance;
+    if (m_service) {
+        m_stats.startTime = QSystemInformationServicePrivate::get(m_service)->m_jobsStatTimer.nsecsElapsed();
+        m_stats.threadId = reinterpret_cast<quint64>(QThread::currentThreadId());
+    }
+}
+
+QTaskLogger::~QTaskLogger() {
+    if (m_service) {
+        auto dservice = QSystemInformationServicePrivate::get(m_service);
+        if (m_stats.endTime == 0L)
+            m_stats.endTime = dservice->m_jobsStatTimer.nsecsElapsed();
+        switch (m_type) {
+        case AspectJob: dservice->addJobLogStatsEntry(m_stats); break;
+        case Submission: dservice->addSubmissionLogStatsEntry(m_stats); break;
+        }
+    }
+}
+
+void QTaskLogger::end(qint64 t)
+{
+    m_stats.endTime = t > 0 || !m_service ? t : QSystemInformationServicePrivate::get(m_service)->m_jobsStatTimer.nsecsElapsed();
+}
+
+qint64 QTaskLogger::restart()
+{
+    if (m_service)
+        m_stats.startTime = QSystemInformationServicePrivate::get(m_service)->m_jobsStatTimer.nsecsElapsed();
+    return m_stats.startTime;
+}
+
+
 /* !\internal
     \class Qt3DCore::QSystemInformationService
     \inmodule Qt3DCore
@@ -58,6 +254,12 @@ namespace Qt3DCore {
     the new service. This constructor is protected so only subclasses can
     instantiate a QSystemInformationService object.
 */
+
+QSystemInformationService::QSystemInformationService()
+    : QAbstractServiceProvider(*new QSystemInformationServicePrivate(QLatin1String("Default System Information Service")))
+{
+}
+
 QSystemInformationService::QSystemInformationService(const QString &description)
     : QAbstractServiceProvider(*new QSystemInformationServicePrivate(description))
 {
@@ -71,19 +273,52 @@ QSystemInformationService::QSystemInformationService(QSystemInformationServicePr
 {
 }
 
+bool QSystemInformationService::isTraceEnabled() const
+{
+    Q_D(const QSystemInformationService);
+    return d->m_traceEnabled;
+}
+
+void QSystemInformationService::setTraceEnabled(bool traceEnabled)
+{
+    Q_D(QSystemInformationService);
+    if (d->m_traceEnabled != traceEnabled) {
+        d->m_traceEnabled = traceEnabled;
+        emit traceEnabledChanged(d->m_traceEnabled);
+        if (d->m_traceEnabled) {
+            if (!d->m_jobsStatTimer.isValid())
+                d->m_jobsStatTimer.start();
+        } else {
+            d->m_traceFile.reset();
+        }
+    }
+}
+
 /*
     \fn QStringList Qt3DCore::QSystemInformationService::aspectNames() const
 
-    Subclasses should override this function and return a string list containing the
-    names of all registered aspects.
+    Returns a string list containing the names of all registered aspects.
 */
+QStringList QSystemInformationService::aspectNames() const
+{
+    return {};
+}
 
 /*
     \fn int Qt3DCore::QSystemInformationService::threadPoolThreadCount() const
 
-    Subclasses should override this function and return the number of threads in the
-    Qt3D task manager's threadpool.
+    Returns the maximum number of threads in the Qt3D task manager's threadpool.
 */
+int QSystemInformationService::threadPoolThreadCount() const
+{
+    return QThreadPool::globalInstance()->maxThreadCount();
+}
+
+void QSystemInformationService::writePreviousFrameTraces()
+{
+    Q_D(QSystemInformationService);
+    d->writeFrameJobLogStats();
+}
 
 }
 
diff --git a/src/core/services/qsysteminformationservice_p.h b/src/core/services/qsysteminformationservice_p.h
index a8a83701b..6fc1579bc 100644
--- a/src/core/services/qsysteminformationservice_p.h
+++ b/src/core/services/qsysteminformationservice_p.h
@@ -61,16 +61,29 @@ QT_BEGIN_NAMESPACE
 namespace Qt3DCore {
 
 class QSystemInformationServicePrivate;
+struct JobRunStats;
 
 class Q_3DCORESHARED_EXPORT QSystemInformationService : public QAbstractServiceProvider
 {
     Q_OBJECT
+    Q_PROPERTY(bool traceEnabled READ isTraceEnabled WRITE setTraceEnabled NOTIFY traceEnabledChanged)
 public:
-    virtual QStringList aspectNames() const = 0;
-    virtual int threadPoolThreadCount() const = 0;
+    QSystemInformationService();
+
+    bool isTraceEnabled() const;
+    void setTraceEnabled(bool traceEnabled);
+
+    QStringList aspectNames() const;
+    int threadPoolThreadCount() const;
+
+    void writePreviousFrameTraces();
+
+signals:
+    void traceEnabledChanged(bool traceEnabled);
 
 protected:
-    QSystemInformationService(const QString &description = QString());
+    Q_DECLARE_PRIVATE(QSystemInformationService)
+    QSystemInformationService(const QString &description);
     QSystemInformationService(QSystemInformationServicePrivate &dd);
 };
 
diff --git a/src/core/services/qsysteminformationservice_p_p.h b/src/core/services/qsysteminformationservice_p_p.h
index e3ce9fe49..75a6e98e7 100644
--- a/src/core/services/qsysteminformationservice_p_p.h
+++ b/src/core/services/qsysteminformationservice_p_p.h
@@ -51,21 +51,91 @@
 // We mean it.
 //
 
-#include <Qt3DCore/qt3dcore_global.h>
+#include <QtCore/QThreadStorage>
+#include <QtCore/QElapsedTimer>
+#include <QtCore/QFile>
+#include <QtCore/QMutex>
 
+#include <Qt3DCore/qt3dcore_global.h>
+#include <Qt3DCore/private/qt3dcore_global_p.h>
 #include <Qt3DCore/private/qabstractserviceprovider_p.h>
 #include <Qt3DCore/private/qservicelocator_p.h>
+#include <Qt3DCore/private/qsysteminformationservice_p.h>
 
 QT_BEGIN_NAMESPACE
 
 namespace Qt3DCore {
 
-class QSystemInformationServicePrivate : public QAbstractServiceProviderPrivate
+union Q_3DCORE_PRIVATE_EXPORT JobId
+{
+    JobId() : id(0L) { }
+    JobId(quint32 t, quint32 i) { typeAndInstance[0] = t; typeAndInstance[1] = i; }
+
+    quint32 typeAndInstance[2];
+    quint64 id;
+};
+
+class Q_3DCORE_PRIVATE_EXPORT QSystemInformationServicePrivate : public QAbstractServiceProviderPrivate
 {
 public:
-    QSystemInformationServicePrivate(const QString &description)
-        : QAbstractServiceProviderPrivate(QServiceLocator::SystemInformation, description)
-    {}
+    struct JobRunStats
+    {
+        JobRunStats() { jobId.id = 0; startTime = 0L; endTime = 0L; }
+
+        qint64 startTime;
+        qint64 endTime;
+        JobId jobId; // QAspectJob subclasses should properly populate the jobId
+        quint64 threadId;
+    };
+
+    QSystemInformationServicePrivate(const QString &description);
+    ~QSystemInformationServicePrivate();
+
+    static QSystemInformationServicePrivate *get(QSystemInformationService *q);
+
+    // Aspects + Job threads
+    void addJobLogStatsEntry(JobRunStats &stats);
+
+    // Submission thread
+    void addSubmissionLogStatsEntry(JobRunStats &stats);
+
+    void writeFrameJobLogStats();
+
+    bool m_traceEnabled;
+
+    QElapsedTimer m_jobsStatTimer;
+    QThreadStorage<QVector<JobRunStats> *> m_jobStatsCached;
+
+    QVector<QVector<JobRunStats> *> m_localStorages;
+    QVector<JobRunStats> *m_submissionStorage;
+
+    QMutex m_localStoragesMutex;
+
+    QScopedPointer<QFile> m_traceFile;
+    quint32 m_frameId;
+
+    Q_DECLARE_PUBLIC(QSystemInformationService)
+};
+
+class Q_3DCORE_PRIVATE_EXPORT QTaskLogger {
+public:
+    enum Type {
+        AspectJob,
+        Submission
+    };
+
+    QTaskLogger(QSystemInformationService *service, const JobId &jobId, Type type);
+    QTaskLogger(QSystemInformationService *service, const quint32 jobType, const quint32 instance, Type type = Submission);
+
+    ~QTaskLogger();
+
+    void end(qint64 t = 0L);
+    qint64 restart();
+
+private:
+    QSystemInformationService *m_service;
+    QSystemInformationServicePrivate::JobRunStats m_stats;
+    Type m_type;
 };
 
 }