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>

1 files changed, 239 insertions, 4 deletions

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();
+}
 
 }