perf_tests: Always capture trace events and flush incrementally

Previously, the trace event buffer was cleared after *all* tests
completed. In order to avoid allocating a ton of space to hold
traces, this patch factors the trace event recording so that the
buffer is processed and reset at the end of each test trial.

This patch also prepares for the future where trace events will be
processed at the end of each trial to compute additional metrics.

Bug: dawn:208
Change-Id: If2ed193ee47794c666df9f0b369ec1ce660b177f
Reviewed-on: https://dawn-review.googlesource.com/c/dawn/+/12780
Commit-Queue: Austin Eng <enga@chromium.org>
Reviewed-by: Corentin Wallez <cwallez@chromium.org>

src/tests/perf_tests/DawnPerfTest.cpp

@@ -29,6 +29,38 @@ namespace {
     constexpr double kMicroSecondsPerSecond = 1e6;
     constexpr double kNanoSecondsPerSecond = 1e9;
 
+    void DumpTraceEventsToJSONFile(
+        const std::vector<DawnPerfTestPlatform::TraceEvent>& traceEventBuffer,
+        const char* traceFile) {
+        std::ofstream outFile;
+        outFile.open(traceFile, std::ios_base::app);
+
+        Json::StreamWriterBuilder builder;
+        std::unique_ptr<Json::StreamWriter> writer(builder.newStreamWriter());
+
+        for (const DawnPerfTestPlatform::TraceEvent& traceEvent : traceEventBuffer) {
+            Json::Value value(Json::objectValue);
+
+            const Json::LargestInt microseconds =
+                static_cast<Json::LargestInt>(traceEvent.timestamp * 1000.0 * 1000.0);
+
+            char phase[2] = {traceEvent.phase, '\0'};
+
+            value["name"] = traceEvent.name;
+            value["cat"] = traceEvent.categoryName;
+            value["ph"] = &phase[0];
+            value["id"] = traceEvent.id;
+            value["ts"] = microseconds;
+            value["pid"] = "Dawn";
+
+            outFile << ", ";
+            writer->write(value, &outFile);
+            outFile.flush();
+        }
+
+        outFile.close();
+    }
+
 }  // namespace
 
 void InitDawnPerfTestEnvironment(int argc, char** argv) {
@@ -83,12 +115,36 @@ DawnPerfTestEnvironment::~DawnPerfTestEnvironment() = default;
 void DawnPerfTestEnvironment::SetUp() {
     DawnTestEnvironment::SetUp();
 
-    mPlatform = std::make_unique<DawnPerfTestPlatform>(IsTracingEnabled());
+    mPlatform = std::make_unique<DawnPerfTestPlatform>();
     mInstance->SetPlatform(mPlatform.get());
+
+    // Begin writing the trace event array.
+    if (mTraceFile != nullptr) {
+        std::ofstream outFile;
+        outFile.open(mTraceFile);
+        outFile << "{ \"traceEvents\": [";
+        outFile << "{}";  // Dummy object so trace events can always prepend a comma
+        outFile.flush();
+        outFile.close();
+    }
 }
 
 void DawnPerfTestEnvironment::TearDown() {
-    DumpTraceEventsToJSONFile();
+    // End writing the trace event array.
+    if (mTraceFile != nullptr) {
+        std::vector<DawnPerfTestPlatform::TraceEvent> traceEventBuffer =
+            mPlatform->AcquireTraceEventBuffer();
+
+        // Write remaining trace events.
+        DumpTraceEventsToJSONFile(traceEventBuffer, mTraceFile);
+
+        std::ofstream outFile;
+        outFile.open(mTraceFile, std::ios_base::app);
+        outFile << "]}";
+        outFile << std::endl;
+        outFile.close();
+    }
+
     DawnTestEnvironment::TearDown();
 }
 
@@ -100,48 +156,8 @@ unsigned int DawnPerfTestEnvironment::OverrideStepsToRun() const {
     return mOverrideStepsToRun;
 }
 
-bool DawnPerfTestEnvironment::IsTracingEnabled() const {
+const char* DawnPerfTestEnvironment::GetTraceFile() const {
-    return mTraceFile != nullptr;
+    return mTraceFile;
-}
-
-void DawnPerfTestEnvironment::DumpTraceEventsToJSONFile() const {
-    if (!IsTracingEnabled()) {
-        return;
-    }
-
-    Json::Value eventsValue(Json::arrayValue);
-
-    const std::vector<DawnPerfTestPlatform::TraceEvent>& traceEventBuffer =
-        mPlatform->GetTraceEventBuffer();
-
-    for (const DawnPerfTestPlatform::TraceEvent& traceEvent : traceEventBuffer) {
-        Json::Value value(Json::objectValue);
-
-        const Json::LargestInt microseconds =
-            static_cast<Json::LargestInt>(traceEvent.timestamp * 1000.0 * 1000.0);
-
-        char phase[2] = {traceEvent.phase, '\0'};
-
-        value["name"] = traceEvent.name;
-        value["cat"] = traceEvent.categoryName;
-        value["ph"] = &phase[0];
-        value["id"] = traceEvent.id;
-        value["ts"] = microseconds;
-        value["pid"] = "Dawn";
-
-        eventsValue.append(value);
-    }
-
-    Json::Value root(Json::objectValue);
-    root["traceEvents"] = eventsValue;
-
-    std::ofstream outFile;
-    outFile.open(mTraceFile);
-
-    Json::StyledStreamWriter styledWrite;
-    styledWrite.write(outFile, root);
-
-    outFile.close();
 }
 
 DawnPerfTestBase::DawnPerfTestBase(DawnTestBase* test,
@@ -196,7 +212,7 @@ void DawnPerfTestBase::RunTest() {
         for (unsigned int trial = 0; trial < kNumTrials; ++trial) {
             TRACE_EVENT0(platform, "dawn.perf_test", "Trial");
             DoRunLoop(kMaximumRunTimeSeconds);
-            PrintResults();
+            OutputResults();
         }
     }
     platform->EnableTraceEventRecording(false);
@@ -242,7 +258,7 @@ void DawnPerfTestBase::DoRunLoop(double maxRunTime) {
     mTimer->Stop();
 }
 
-void DawnPerfTestBase::PrintResults() {
+void DawnPerfTestBase::OutputResults() {
     double elapsedTimeSeconds[2] = {
         mTimer->GetElapsedTime(),
         mGPUTimeNs * 1e-9,
@@ -269,6 +285,19 @@ void DawnPerfTestBase::PrintResults() {
             PrintResult(clockNames[i], nanoSecPerIteration, "ns", true);
         }
     }
+
+    DawnPerfTestPlatform* platform =
+        reinterpret_cast<DawnPerfTestPlatform*>(gTestEnv->GetInstance()->GetPlatform());
+
+    std::vector<DawnPerfTestPlatform::TraceEvent> traceEventBuffer =
+        platform->AcquireTraceEventBuffer();
+
+    // TODO(enga): Process traces to extract time of command recording, validation, etc.
+
+    const char* traceFile = gTestEnv->GetTraceFile();
+    if (traceFile != nullptr) {
+        DumpTraceEventsToJSONFile(traceEventBuffer, traceFile);
+    }
 }
 
 void DawnPerfTestBase::PrintResult(const std::string& trace,

src/tests/perf_tests/DawnPerfTest.h

@@ -36,12 +36,11 @@ class DawnPerfTestEnvironment : public DawnTestEnvironment {
     bool IsCalibrating() const;
     unsigned int OverrideStepsToRun() const;
 
-    // Returns whether tracing is enabled.
+    // Returns the path to the trace file, or nullptr if traces should
-    bool IsTracingEnabled() const;
+    // not be written to a json file.
+    const char* GetTraceFile() const;
 
   private:
-    void DumpTraceEventsToJSONFile() const;
-
     // Only run calibration which allows the perf test runner to save time.
     bool mIsCalibrating = false;
 
@@ -85,7 +84,7 @@ class DawnPerfTestBase {
 
   private:
     void DoRunLoop(double maxRunTime);
-    void PrintResults();
+    void OutputResults();
 
     virtual void Step() = 0;
 

src/tests/perf_tests/DawnPerfTestPlatform.cpp

@@ -33,20 +33,18 @@ namespace {
 
 }  // anonymous namespace
 
-DawnPerfTestPlatform::DawnPerfTestPlatform(bool enableTracing)
+DawnPerfTestPlatform::DawnPerfTestPlatform()
-    : dawn_platform::Platform(), mEnableTracing(enableTracing), mTimer(utils::CreateTimer()) {
+    : dawn_platform::Platform(), mTimer(utils::CreateTimer()) {
 }
 
 DawnPerfTestPlatform::~DawnPerfTestPlatform() = default;
 
 const unsigned char* DawnPerfTestPlatform::GetTraceCategoryEnabledFlag(const char* name) {
-    if (mEnableTracing) {
     for (const TraceCategory& category : gTraceCategories) {
         if (strcmp(category.name, name) == 0) {
             return &category.enabled;
         }
     }
-    }
 
     constexpr static unsigned char kZero = 0;
     return &kZero;
@@ -70,7 +68,7 @@ uint64_t DawnPerfTestPlatform::AddTraceEvent(char phase,
                                              const unsigned char* argTypes,
                                              const uint64_t* argValues,
                                              unsigned char flags) {
-    if (!mEnableTracing || !mRecordTraceEvents) {
+    if (!mRecordTraceEvents) {
         return 0;
     }
 
@@ -88,7 +86,8 @@ void DawnPerfTestPlatform::EnableTraceEventRecording(bool enable) {
     mRecordTraceEvents = enable;
 }
 
-const std::vector<DawnPerfTestPlatform::TraceEvent>& DawnPerfTestPlatform::GetTraceEventBuffer()
+std::vector<DawnPerfTestPlatform::TraceEvent> DawnPerfTestPlatform::AcquireTraceEventBuffer() {
-    const {
+    std::vector<DawnPerfTestPlatform::TraceEvent> buffer = mTraceEventBuffer;
-    return mTraceEventBuffer;
+    mTraceEventBuffer.clear();
+    return buffer;
 }

src/tests/perf_tests/DawnPerfTestPlatform.h

@@ -51,11 +51,11 @@ class DawnPerfTestPlatform : public dawn_platform::Platform {
         double timestamp = 0;
     };
 
-    explicit DawnPerfTestPlatform(bool enableTracing);
+    DawnPerfTestPlatform();
     ~DawnPerfTestPlatform() override;
 
     void EnableTraceEventRecording(bool enable);
-    const std::vector<TraceEvent>& GetTraceEventBuffer() const;
+    std::vector<TraceEvent> AcquireTraceEventBuffer();
 
   private:
     const unsigned char* GetTraceCategoryEnabledFlag(const char* name) override;
@@ -73,7 +73,6 @@ class DawnPerfTestPlatform : public dawn_platform::Platform {
                            const uint64_t* argValues,
                            unsigned char flags) override;
 
-    bool mEnableTracing = false;
     bool mRecordTraceEvents = false;
     std::unique_ptr<utils::Timer> mTimer;