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>

7 files changed, 26 insertions, 215 deletions

diff --git a/src/core/jobs/qaspectjob_p.h b/src/core/jobs/qaspectjob_p.h
index b16c3cad2..ddad09c86 100644
--- a/src/core/jobs/qaspectjob_p.h
+++ b/src/core/jobs/qaspectjob_p.h
@@ -54,6 +54,7 @@
 #include <QtCore/QWeakPointer>
 
 #include <Qt3DCore/private/qt3dcore_global_p.h>
+#include <Qt3DCore/private/qsysteminformationservice_p_p.h>
 #include <Qt3DCore/qt3dcore-config.h>
 
 QT_BEGIN_NAMESPACE
@@ -63,47 +64,6 @@ namespace Qt3DCore {
 class QAspectJob;
 class QAspectManager;
 
-#if QT_CONFIG(qt3d_profile_jobs)
-struct FrameHeader
-{
-    FrameHeader()
-        : frameId(0)
-        , jobCount(0)
-        , frameType(WorkerJob)
-    {
-    }
-
-    enum FrameType {
-        WorkerJob = 0,
-        Submission
-    };
-
-    quint32 frameId;
-    quint16 jobCount;
-    quint16 frameType; // Submission or worker job
-};
-
-union JobId
-{
-    quint32 typeAndInstance[2];
-    quint64 id;
-};
-
-struct JobRunStats
-{
-    JobRunStats()
-    {
-        jobId.id = 0;
-    }
-
-    qint64 startTime;
-    qint64 endTime;
-    JobId jobId;
-    // QAspectJob subclasses should properly populate the jobId
-    quint64 threadId;
-};
-#endif
-
 class Q_3DCORE_PRIVATE_EXPORT QAspectJobPrivate
 {
 public:
@@ -115,29 +75,16 @@ public:
     virtual void postFrame(QAspectManager *aspectManager);
 
     QVector<QWeakPointer<QAspectJob> > m_dependencies;
-#if QT_CONFIG(qt3d_profile_jobs)
-    JobRunStats m_stats;
-#endif
+    JobId m_jobId;
 };
-
 } // Qt3D
 
-#if QT_CONFIG(qt3d_profile_jobs)
-
-#include <Qt3DCore/private/qaspectjob_p.h>
-
 #define SET_JOB_RUN_STAT_TYPE(job, type, instance) \
-    Qt3DCore::QAspectJobPrivate::get(job)->m_stats.jobId.typeAndInstance[0] = type; \
-    Qt3DCore::QAspectJobPrivate::get(job)->m_stats.jobId.typeAndInstance[1] = instance;
-
-#else
-
-#define SET_JOB_RUN_STAT_TYPE(job, type, instance) \
-    Q_UNUSED(job) \
-    Q_UNUSED(type) \
-    Q_UNUSED(instance)
-
-#endif
+    { \
+        auto &jobId = Qt3DCore::QAspectJobPrivate::get(job)->m_jobId; \
+        jobId.typeAndInstance[0] = type; \
+        jobId.typeAndInstance[1] = instance; \
+    }
 
 QT_END_NAMESPACE
 
diff --git a/src/core/jobs/qaspectjobmanager.cpp b/src/core/jobs/qaspectjobmanager.cpp
index 91394924f..be7942359 100644
--- a/src/core/jobs/qaspectjobmanager.cpp
+++ b/src/core/jobs/qaspectjobmanager.cpp
@@ -44,7 +44,7 @@
 #include <QtCore/QDebug>
 #include <QtCore/QThread>
 #include <QtCore/QFuture>
-
+#include <Qt3DCore/private/qaspectmanager_p.h>
 #include <Qt3DCore/private/qthreadpooler_p.h>
 #include <Qt3DCore/private/task_p.h>
 
@@ -52,9 +52,10 @@ QT_BEGIN_NAMESPACE
 
 namespace Qt3DCore {
 
-QAspectJobManager::QAspectJobManager(QObject *parent)
+QAspectJobManager::QAspectJobManager(QAspectManager *parent)
     : QAbstractAspectJobManager(parent)
     , m_threadPooler(new QThreadPooler(this))
+    , m_aspectManager(parent)
 {
 }
 
@@ -69,12 +70,16 @@ void QAspectJobManager::initialize()
 // Adds all Aspect Jobs to be processed for a frame
 void QAspectJobManager::enqueueJobs(const QVector<QAspectJobPtr> &jobQueue)
 {
+    auto systemService = m_aspectManager ? m_aspectManager->serviceLocator()->systemInformation() : nullptr;
+    if (systemService)
+        systemService->writePreviousFrameTraces();
+
     // Convert QJobs to Tasks
     QHash<QAspectJob *, AspectTaskRunnable *> tasksMap;
     QVector<RunnableInterface *> taskList;
     taskList.reserve(jobQueue.size());
     for (const QAspectJobPtr &job : jobQueue) {
-        AspectTaskRunnable *task = new AspectTaskRunnable();
+        AspectTaskRunnable *task = new AspectTaskRunnable(systemService);
         task->m_job = job;
         tasksMap.insert(job.data(), task);
 
@@ -99,9 +104,6 @@ void QAspectJobManager::enqueueJobs(const QVector<QAspectJobPtr> &jobQueue)
         taskDepender->m_dependerCount += dependerCount;
     }
 
-#if QT_CONFIG(qt3d_profile_jobs)
-    QThreadPooler::writeFrameJobLogStats();
-#endif
     m_threadPooler->mapDependables(taskList);
 }
 
diff --git a/src/core/jobs/qaspectjobmanager_p.h b/src/core/jobs/qaspectjobmanager_p.h
index 77e535491..acbd0263e 100644
--- a/src/core/jobs/qaspectjobmanager_p.h
+++ b/src/core/jobs/qaspectjobmanager_p.h
@@ -63,12 +63,13 @@ namespace Qt3DCore {
 
 class QThreadPooler;
 class DependencyHandler;
+class QAspectManager;
 
 class Q_3DCORE_PRIVATE_EXPORT QAspectJobManager : public QAbstractAspectJobManager
 {
     Q_OBJECT
 public:
-    explicit QAspectJobManager(QObject *parent = 0);
+    explicit QAspectJobManager(QAspectManager *parent = nullptr);
     ~QAspectJobManager();
 
     void initialize() override;
@@ -81,6 +82,7 @@ public:
 
 private:
     QThreadPooler *m_threadPooler;
+    QAspectManager *m_aspectManager;
 };
 
 } // namespace Qt3DCore
diff --git a/src/core/jobs/qthreadpooler.cpp b/src/core/jobs/qthreadpooler.cpp
index 3ab321542..f5c50062a 100644
--- a/src/core/jobs/qthreadpooler.cpp
+++ b/src/core/jobs/qthreadpooler.cpp
@@ -40,27 +40,10 @@
 #include "qthreadpooler_p.h"
 #include <QtCore/QDebug>
 
-#if QT_CONFIG(qt3d_profile_jobs)
-
-#ifdef Q_OS_ANDROID
-#include <QtCore/QStandardPaths>
-#endif
-
-#include <QtCore/QCoreApplication>
-#include <QtCore/QFile>
-#include <QtCore/QThreadStorage>
-#include <QtCore/QDateTime>
-#include <QtCore/QCoreApplication>
-#endif
-
 QT_BEGIN_NAMESPACE
 
 namespace Qt3DCore {
 
-#if QT_CONFIG(qt3d_profile_jobs)
-QElapsedTimer QThreadPooler::m_jobsStatTimer;
-#endif
-
 QThreadPooler::QThreadPooler(QObject *parent)
     : QObject(parent)
     , m_futureInterface(nullptr)
@@ -76,12 +59,8 @@ QThreadPooler::QThreadPooler(QObject *parent)
             m_threadPool->setMaxThreadCount(maxThreadCountValue);
     }
 
-
     // Ensures that threads will never be recycled
     m_threadPool->setExpiryTimeout(-1);
-#if QT_CONFIG(qt3d_profile_jobs)
-    QThreadPooler::m_jobsStatTimer.start();
-#endif
 }
 
 QThreadPooler::~QThreadPooler()
@@ -194,102 +173,6 @@ int QThreadPooler::maxThreadCount() const
     return m_threadPool->maxThreadCount();
 }
 
-#if QT_CONFIG(qt3d_profile_jobs)
-
-QThreadStorage<QVector<JobRunStats> *> jobStatsCached;
-
-QVector<QVector<JobRunStats> *> localStorages;
-QVector<JobRunStats> *submissionStorage = nullptr;
-
-QMutex localStoragesMutex;
-
-// Called by the jobs
-void QThreadPooler::addJobLogStatsEntry(JobRunStats &stats)
-{
-    if (!jobStatsCached.hasLocalData()) {
-        auto jobVector = new QVector<JobRunStats>;
-        jobStatsCached.setLocalData(jobVector);
-        QMutexLocker lock(&localStoragesMutex);
-        localStorages.push_back(jobVector);
-    }
-    jobStatsCached.localData()->push_back(stats);
-}
-
-// Called after jobs have been executed (MainThread QAspectJobManager::enqueueJobs)
-void QThreadPooler::writeFrameJobLogStats()
-{
-    static QScopedPointer<QFile> traceFile;
-    static quint32 frameId = 0;
-    if (!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
-        traceFile.reset(new QFile(QStandardPaths::writableLocation(QStandardPaths::DownloadLocation) + QStringLiteral("/") + fileName));
-#else
-        traceFile.reset(new QFile(fileName));
-#endif
-        if (!traceFile->open(QFile::WriteOnly|QFile::Truncate))
-            qCritical("Failed to open trace file");
-    }
-
-    // Write Aspect + Job threads
-    {
-        FrameHeader header;
-        header.frameId = frameId;
-        header.jobCount = 0;
-
-        for (const QVector<JobRunStats> *storage : qAsConst(localStorages))
-            header.jobCount += storage->size();
-
-        traceFile->write(reinterpret_cast<char *>(&header), sizeof(FrameHeader));
-
-        for (QVector<JobRunStats> *storage : qAsConst(localStorages)) {
-            for (const JobRunStats &stat : *storage)
-                traceFile->write(reinterpret_cast<const char *>(&stat), sizeof(JobRunStats));
-            storage->clear();
-        }
-    }
-
-    // Write submission thread
-    {
-        QMutexLocker lock(&localStoragesMutex);
-        const int submissionJobSize = submissionStorage != nullptr ? submissionStorage->size() : 0;
-        if (submissionJobSize > 0) {
-            FrameHeader header;
-            header.frameId = frameId;
-            header.jobCount = submissionJobSize;
-            header.frameType = FrameHeader::Submission;
-
-            traceFile->write(reinterpret_cast<char *>(&header), sizeof(FrameHeader));
-
-            for (const JobRunStats &stat : *submissionStorage)
-                traceFile->write(reinterpret_cast<const char *>(&stat), sizeof(JobRunStats));
-            submissionStorage->clear();
-        }
-    }
-
-    traceFile->flush();
-    ++frameId;
-}
-
-// Called from Submission thread (which can be main thread in Manual drive mode)
-void QThreadPooler::addSubmissionLogStatsEntry(JobRunStats &stats)
-{
-    QMutexLocker lock(&localStoragesMutex);
-    if (!jobStatsCached.hasLocalData()) {
-        submissionStorage = new QVector<JobRunStats>;
-        jobStatsCached.setLocalData(submissionStorage);
-    }
-
-    // Handle the case where submission thread is also the main thread (Scene/Manual drive modes with no RenderThread)
-    if (submissionStorage == nullptr && jobStatsCached.hasLocalData())
-        submissionStorage = new QVector<JobRunStats>;
-
-    // When having no submission thread this can be null
-    submissionStorage->push_back(stats);
-}
-
-#endif
-
 } // namespace Qt3DCore
 
 QT_END_NAMESPACE
diff --git a/src/core/jobs/qthreadpooler_p.h b/src/core/jobs/qthreadpooler_p.h
index 3e17cbd6d..1970641b8 100644
--- a/src/core/jobs/qthreadpooler_p.h
+++ b/src/core/jobs/qthreadpooler_p.h
@@ -60,10 +60,6 @@
 #include <Qt3DCore/private/qaspectjob_p.h>
 #include <Qt3DCore/private/task_p.h>
 
-#if QT_CONFIG(qt3d_profile_jobs)
-#include <QtCore/QElapsedTimer>
-#endif
-
 QT_BEGIN_NAMESPACE
 
 namespace Qt3DCore {
@@ -81,17 +77,6 @@ public:
     QFuture<void> future();
 
     int maxThreadCount() const;
-#if QT_CONFIG(qt3d_profile_jobs)
-    static QElapsedTimer m_jobsStatTimer;
-
-    // Aspects + Job threads
-    static void addJobLogStatsEntry(JobRunStats &stats);
-    static void writeFrameJobLogStats();
-
-    // Submission thread
-    static void addSubmissionLogStatsEntry(JobRunStats &stats);
-
-#endif
 
 private:
     void enqueueTasks(const QVector<RunnableInterface *> &tasks);
diff --git a/src/core/jobs/task.cpp b/src/core/jobs/task.cpp
index 7c3ebf6eb..1dd5712c9 100644
--- a/src/core/jobs/task.cpp
+++ b/src/core/jobs/task.cpp
@@ -44,6 +44,7 @@
 #include <QtCore/QMutexLocker>
 
 #include <Qt3DCore/private/qthreadpooler_p.h>
+#include <Qt3DCore/private/qsysteminformationservice_p_p.h>
 
 QT_BEGIN_NAMESPACE
 
@@ -55,8 +56,9 @@ RunnableInterface::~RunnableInterface()
 
 // Aspect task
 
-AspectTaskRunnable::AspectTaskRunnable()
-    : m_pooler(nullptr)
+AspectTaskRunnable::AspectTaskRunnable(QSystemInformationService *service)
+    : m_service(service)
+    , m_pooler(nullptr)
     , m_id(0)
     , m_reserved(false)
 {
@@ -69,21 +71,9 @@ AspectTaskRunnable::~AspectTaskRunnable()
 void AspectTaskRunnable::run()
 {
     if (m_job) {
-#if QT_CONFIG(qt3d_profile_jobs)
         QAspectJobPrivate *jobD = QAspectJobPrivate::get(m_job.data());
-        if (m_pooler) {
-            jobD->m_stats.startTime = QThreadPooler::m_jobsStatTimer.nsecsElapsed();
-            jobD->m_stats.threadId = reinterpret_cast<quint64>(QThread::currentThreadId());
-        }
-#endif
+        QTaskLogger logger(m_pooler ? m_service : nullptr, jobD->m_jobId, QTaskLogger::AspectJob);
         m_job->run();
-#if QT_CONFIG(qt3d_profile_jobs)
-        if (m_pooler) {
-            jobD->m_stats.endTime = QThreadPooler::m_jobsStatTimer.nsecsElapsed();
-            // Add current job's stats to log output
-            QThreadPooler::addJobLogStatsEntry(jobD->m_stats);
-        }
-#endif
     }
 
     // We could have an append sub task or something in here
diff --git a/src/core/jobs/task_p.h b/src/core/jobs/task_p.h
index c81882719..ff411539f 100644
--- a/src/core/jobs/task_p.h
+++ b/src/core/jobs/task_p.h
@@ -65,6 +65,7 @@ namespace Qt3DCore {
 class JobRunner;
 class DependencyHandler;
 class QThreadPooler;
+class QSystemInformationService;
 
 class RunnableInterface : public QRunnable
 {
@@ -92,7 +93,7 @@ public:
 class AspectTaskRunnable : public RunnableInterface
 {
 public:
-    AspectTaskRunnable();
+    AspectTaskRunnable(QSystemInformationService *service);
     ~AspectTaskRunnable();
 
     void run() override;
@@ -113,6 +114,7 @@ public:
     int m_dependerCount = 0;
 
 private:
+    QSystemInformationService *m_service;
     QThreadPooler *m_pooler;
     int m_id; // For testing purposes for now
     bool m_reserved;