Job Traces: add support for Submission frames

We now have worker frames for jobs and submission frames for render command
submissions.
Since both can happen concurrently, slightly adjusted what needed to be.

Change-Id: I355bb6540090b4f569d38f4989dc9911dc381974
Reviewed-by: Sean Harmer <sean.harmer@kdab.com>

5 files changed, 83 insertions, 35 deletions

diff --git a/src/core/jobs/qaspectjob_p.h b/src/core/jobs/qaspectjob_p.h
index d66e6594c..1069ba0b9 100644
--- a/src/core/jobs/qaspectjob_p.h
+++ b/src/core/jobs/qaspectjob_p.h
@@ -63,8 +63,21 @@ class QAspectJob;
 #ifdef QT3D_JOBS_RUN_STATS
 struct FrameHeader
 {
+    FrameHeader()
+        : frameId(0)
+        , jobCount(0)
+        , frameType(WorkerJob)
+    {
+    }
+
+    enum FrameType {
+        WorkerJob = 0,
+        Submission
+    };
+
     quint32 frameId;
-    quint32 jobCount;
+    quint16 jobCount;
+    quint16 frameType; // Submission or worker job
 };
 
 union JobId
diff --git a/src/core/jobs/qaspectjobmanager.cpp b/src/core/jobs/qaspectjobmanager.cpp
index 2a8006b10..f2a71412d 100644
--- a/src/core/jobs/qaspectjobmanager.cpp
+++ b/src/core/jobs/qaspectjobmanager.cpp
@@ -103,7 +103,6 @@ void QAspectJobManager::enqueueJobs(const QVector<QAspectJobPtr> &jobQueue)
     m_dependencyHandler->addDependencies(qMove(dependencyList));
 #ifdef QT3D_JOBS_RUN_STATS
     QThreadPooler::writeFrameJobLogStats();
-    QThreadPooler::starNewFrameJobLogsStats();
 #endif
     m_threadPooler->mapDependables(taskList);
 }
diff --git a/src/core/jobs/qthreadpooler.cpp b/src/core/jobs/qthreadpooler.cpp
index c49930f5a..35e2df2a1 100644
--- a/src/core/jobs/qthreadpooler.cpp
+++ b/src/core/jobs/qthreadpooler.cpp
@@ -174,6 +174,8 @@ int QThreadPooler::maxThreadCount() const
 QThreadStorage<QVector<JobRunStats> *> jobStatsCached;
 
 QVector<QVector<JobRunStats> *> localStorages;
+QVector<JobRunStats> *submissionStorage = nullptr;
+
 QMutex localStoragesMutex;
 
 // Called by the jobs
@@ -188,14 +190,7 @@ void QThreadPooler::addJobLogStatsEntry(JobRunStats &stats)
     jobStatsCached.localData()->push_back(stats);
 }
 
-// Called before jobs are executed (AspectThread)
-void QThreadPooler::starNewFrameJobLogsStats()
-{
-    for (QVector<JobRunStats> *storage : qAsConst(localStorages))
-        storage->clear();
-}
-
-// Called after jobs have been executed
+// Called after jobs have been executed (AspectThread QAspectJobManager::enqueueJobs)
 void QThreadPooler::writeFrameJobLogStats()
 {
     static QScopedPointer<QFile> traceFile;
@@ -206,25 +201,57 @@ void QThreadPooler::writeFrameJobLogStats()
             qCritical("Failed to open trace file");
     }
 
-    FrameHeader header;
-    header.frameId = frameId;
-    header.jobCount = 0;
+    // 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 (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();
+        }
+    }
 
-    for (const QVector<JobRunStats> *storage : qAsConst(localStorages)) {
-        for (const JobRunStats &stat : *storage) {
-            traceFile->write(reinterpret_cast<const char *>(&stat), sizeof(JobRunStats));
+    // 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
+void QThreadPooler::addSubmissionLogStatsEntry(JobRunStats &stats)
+{
+    QMutexLocker lock(&localStoragesMutex);
+    if (!jobStatsCached.hasLocalData()) {
+        submissionStorage = new QVector<JobRunStats>;
+        jobStatsCached.setLocalData(submissionStorage);
+    }
+    submissionStorage->push_back(stats);
+}
+
 #endif
 
 } // namespace Qt3DCore
diff --git a/src/core/jobs/qthreadpooler_p.h b/src/core/jobs/qthreadpooler_p.h
index 4b1137318..47b28e639 100644
--- a/src/core/jobs/qthreadpooler_p.h
+++ b/src/core/jobs/qthreadpooler_p.h
@@ -86,9 +86,13 @@ public:
 #ifdef QT3D_JOBS_RUN_STATS
     static QElapsedTimer m_jobsStatTimer;
 
+    // Aspects + Job threads
     static void addJobLogStatsEntry(JobRunStats &stats);
-    static void starNewFrameJobLogsStats();
     static void writeFrameJobLogStats();
+
+    // Submission thread
+    static void addSubmissionLogStatsEntry(JobRunStats &stats);
+
 #endif
 
 private:
diff --git a/src/render/backend/renderer.cpp b/src/render/backend/renderer.cpp
index ac944c411..58cc4c483 100644
--- a/src/render/backend/renderer.cpp
+++ b/src/render/backend/renderer.cpp
@@ -399,9 +399,16 @@ void Renderer::doRender()
     bool submissionSucceeded = false;
     bool hasCleanedQueueAndProceeded = false;
     Renderer::ViewSubmissionResultData submissionData;
+    bool preprocessingComplete = false;
 
     if (isReadyToSubmit()) {
 
+        // Lock the mutex to protect access to m_surface and check if we are still set
+        // to the running state and that we have a valid surface on which to draw
+        // TO DO: Is that still needed given the surface changes
+        QMutexLocker locker(&m_mutex);
+        const QVector<Render::RenderView *> renderViews = m_renderQueue->nextFrameQueue();
+
 #ifdef QT3D_JOBS_RUN_STATS
         // Save start of frame
         JobRunStats submissionStatsPart1;
@@ -414,11 +421,6 @@ void Renderer::doRender()
         submissionStatsPart2.jobId.typeAndInstance[1] = 0;
         submissionStatsPart2.threadId = reinterpret_cast<quint64>(QThread::currentThreadId());
 #endif
-        // Lock the mutex to protect access to m_surface and check if we are still set
-        // to the running state and that we have a valid surface on which to draw
-        // TO DO: Is that still needed given the surface changes
-        QMutexLocker locker(&m_mutex);
-        const QVector<Render::RenderView *> renderViews = m_renderQueue->nextFrameQueue();
 
         if (canRender() && (submissionSucceeded = renderViews.size() > 0) == true) {
             // Clear all dirty flags but Compute so that
@@ -428,7 +430,6 @@ void Renderer::doRender()
                 changesToUnset.setFlag(Renderer::ComputeDirty, false);
             clearDirtyBits(changesToUnset);
 
-            bool preprocessingComplete = false;
             { // Scoped to destroy surfaceLock
                 QSurface *surface = renderViews.first()->surface();
                 SurfaceLocker surfaceLock(surface);
@@ -447,8 +448,10 @@ void Renderer::doRender()
             hasCleanedQueueAndProceeded = true;
 
 #ifdef QT3D_JOBS_RUN_STATS
-            submissionStatsPart2.startTime = QThreadPooler::m_jobsStatTimer.nsecsElapsed();
-            submissionStatsPart1.endTime = submissionStatsPart2.startTime;
+            if (preprocessingComplete) {
+                submissionStatsPart2.startTime = QThreadPooler::m_jobsStatTimer.nsecsElapsed();
+                submissionStatsPart1.endTime = submissionStatsPart2.startTime;
+            }
 #endif
             // Only try to submit the RenderViews if the preprocessing was successful
             // This part of the submission is happening in parallel to the RV building for the next frame
@@ -472,12 +475,14 @@ void Renderer::doRender()
         qDeleteAll(renderViews);
 
 #ifdef QT3D_JOBS_RUN_STATS
-        // Save submission elapsed time
-        submissionStatsPart2.endTime = QThreadPooler::m_jobsStatTimer.nsecsElapsed();
-        // Note this is safe since proceedToNextFrame is the one going to trigger
-        // the write to the file, and this is performed after this step
-        Qt3DCore::QThreadPooler::addJobLogStatsEntry(submissionStatsPart1);
-        Qt3DCore::QThreadPooler::addJobLogStatsEntry(submissionStatsPart2);
+        if (preprocessingComplete) {
+            // Save submission elapsed time
+            submissionStatsPart2.endTime = QThreadPooler::m_jobsStatTimer.nsecsElapsed();
+            // Note this is safe since proceedToNextFrame is the one going to trigger
+            // the write to the file, and this is performed after this step
+            Qt3DCore::QThreadPooler::addSubmissionLogStatsEntry(submissionStatsPart1);
+            Qt3DCore::QThreadPooler::addSubmissionLogStatsEntry(submissionStatsPart2);
+        }
 #endif
     }