Record and dump trace events in the perf tests

Trace data can be used to build additional metrics which measure
validation costs, GPU time, etc. It will also be helpful to store in
the test output for later analysis.

This CL also adds jsoncpp as a DEP so we can dump trace file json
output.

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

.gitignore

@@ -15,6 +15,7 @@ third_party/glm/
 third_party/glslang/
 third_party/googletest/
 third_party/jinja2/
+third_party/jsoncpp/
 third_party/llvm-build
 third_party/markupsafe/
 third_party/shaderc/

BUILD.gn

@@ -987,9 +987,11 @@ test("dawn_perf_tests") {
   configs += [ "${dawn_root}/src/common:dawn_internal" ]
 
   deps = [
+    ":dawn_platform",
     ":dawn_utils",
     ":libdawn_native",
     ":libdawn_wire",
+    "${dawn_jsoncpp_dir}:jsoncpp",
     "${dawn_root}/src/common",
     "${dawn_root}/src/dawn:dawncpp",
     "${dawn_root}/src/dawn:libdawn_proc",
@@ -1003,6 +1005,8 @@ test("dawn_perf_tests") {
     "src/tests/perf_tests/BufferUploadPerf.cpp",
     "src/tests/perf_tests/DawnPerfTest.cpp",
     "src/tests/perf_tests/DawnPerfTest.h",
+    "src/tests/perf_tests/DawnPerfTestPlatform.cpp",
+    "src/tests/perf_tests/DawnPerfTestPlatform.h",
   ]
 
   libs = []

DEPS

@@ -72,6 +72,17 @@ deps = {
     'condition': 'dawn_standalone',
   },
 
+  # jsoncpp for perf tests trace events
+  'third_party/jsoncpp': {
+    'url': '{chromium_git}/chromium/src/third_party/jsoncpp@571788934b5ee8643d53e5d054534abbe6006168',
+    'condition': 'dawn_standalone',
+  },
+
+  'third_party/jsoncpp/source': {
+    'url' : '{chromium_git}/external/github.com/open-source-parsers/jsoncpp@645250b6690785be60ab6780ce4b58698d884d11',
+    'condition': 'dawn_standalone',
+  },
+
   # GLFW for tests and samples
   'third_party/glfw': {
     'url': '{chromium_git}/external/github.com/glfw/glfw@2de2589f910b1a85905f425be4d32f33cec092df',

build_overrides/dawn.gni

@@ -27,6 +27,7 @@ dawn_standalone = true
 dawn_jinja2_dir = "//third_party/jinja2"
 dawn_glfw_dir = "//third_party/glfw"
 dawn_googletest_dir = "//third_party/googletest"
+dawn_jsoncpp_dir = "//third_party/jsoncpp"
 dawn_shaderc_dir = "//third_party/shaderc"
 dawn_spirv_tools_dir = "//third_party/SPIRV-Tools"
 dawn_spirv_cross_dir = "//third_party/spirv-cross"

scripts/dawn_overrides_with_defaults.gni

@@ -41,6 +41,10 @@ if (!defined(dawn_googletest_dir)) {
   dawn_googletest_dir = "//third_party/googletest"
 }
 
+if (!defined(dawn_jsoncpp_dir)) {
+  dawn_jsoncpp_dir = "//third_party/jsoncpp"
+}
+
 if (!defined(dawn_shaderc_dir)) {
   dawn_shaderc_dir = "//third_party/shaderc"
 }

src/dawn_platform/tracing/EventTracer.h

@@ -26,6 +26,8 @@ namespace dawn_platform {
         using TraceEventHandle = uint64_t;
 
         const unsigned char* GetTraceCategoryEnabledFlag(Platform* platform, const char* name);
+
+        // TODO(enga): Simplify this API.
         TraceEventHandle AddTraceEvent(Platform* platform,
                                        char phase,
                                        const unsigned char* categoryGroupEnabled,

src/tests/DawnTest.cpp

@@ -129,10 +129,11 @@ DawnTestEnvironment::DawnTestEnvironment(int argc, char** argv) {
             continue;
         }
 
-        if (strstr(argv[i], "--adapter-vendor-id") != nullptr) {
-            const char* value = strchr(argv[i], '=');
-            if (value != nullptr) {
-                mVendorIdFilter = strtoul(value + 1, nullptr, 16);
+        constexpr const char kVendorIdFilterArg[] = "--adapter-vendor-id=";
+        if (strstr(argv[i], kVendorIdFilterArg) == argv[i]) {
+            const char* vendorIdFilter = argv[i] + strlen(kVendorIdFilterArg);
+            if (vendorIdFilter[0] != '\0') {
+                mVendorIdFilter = strtoul(vendorIdFilter, nullptr, 16);
                 // Set filter flag if vendor id is non-zero.
                 mHasVendorIdFilter = mVendorIdFilter != 0;
             }

src/tests/DawnTest.h

@@ -129,6 +129,9 @@ class DawnTestEnvironment : public testing::Environment {
     bool HasVendorIdFilter() const;
     uint32_t GetVendorIdFilter() const;
 
+  protected:
+    std::unique_ptr<dawn_native::Instance> mInstance;
+
   private:
     void DiscoverOpenGLAdapter();
 
@@ -137,7 +140,6 @@ class DawnTestEnvironment : public testing::Environment {
     bool mBeginCaptureOnStartup = false;
     bool mHasVendorIdFilter = false;
     uint32_t mVendorIdFilter = 0;
-    std::unique_ptr<dawn_native::Instance> mInstance;
 };
 
 class DawnTestBase {

src/tests/perf_tests/DawnPerfTest.cpp

@@ -14,8 +14,14 @@
 
 #include "tests/perf_tests/DawnPerfTest.h"
 
+#include "dawn_platform/tracing/TraceEvent.h"
+#include "tests/perf_tests/DawnPerfTestPlatform.h"
 #include "utils/Timer.h"
 
+#include <json/value.h>
+#include <json/writer.h>
+#include <fstream>
+
 namespace {
 
     DawnPerfTestEnvironment* gTestEnv = nullptr;
@@ -39,20 +45,33 @@ DawnPerfTestEnvironment::DawnPerfTestEnvironment(int argc, char** argv)
             continue;
         }
 
-        if (strstr(argv[i], "--override-steps=") == argv[i]) {
-            const char* value = strchr(argv[i], '=');
-            if (value != nullptr) {
-                mOverrideStepsToRun = strtoul(value + 1, nullptr, 0);
+        constexpr const char kOverrideStepsArg[] = "--override-steps=";
+        if (strstr(argv[i], kOverrideStepsArg) == argv[i]) {
+            const char* overrideSteps = argv[i] + strlen(kOverrideStepsArg);
+            if (overrideSteps[0] != '\0') {
+                mOverrideStepsToRun = strtoul(overrideSteps, nullptr, 0);
+            }
+            continue;
+        }
+
+        constexpr const char kTraceFileArg[] = "--trace-file=";
+        if (strstr(argv[i], kTraceFileArg) == argv[i]) {
+            const char* traceFile = argv[i] + strlen(kTraceFileArg);
+            if (traceFile[0] != '\0') {
+                mTraceFile = traceFile;
             }
             continue;
         }
 
         if (strcmp("-h", argv[i]) == 0 || strcmp("--help", argv[i]) == 0) {
-            std::cout << "Additional flags:"
-                      << " [--calibration] [--override-steps=x]\n"
+            std::cout
+                << "Additional flags:"
+                << " [--calibration] [--override-steps=x] [--enable-tracing] [--trace-file=file]\n"
                 << "  --calibration: Only run calibration. Calibration allows the perf test"
                    " runner script to save some time.\n"
                 << " --override-steps: Set a fixed number of steps to run for each test\n"
+                << " --enable-tracing: Enable tracing of Dawn's internals.\n"
+                << " --trace-file: The file to dump trace results.\n"
                 << std::endl;
             continue;
         }
@@ -63,6 +82,14 @@ DawnPerfTestEnvironment::~DawnPerfTestEnvironment() = default;
 
 void DawnPerfTestEnvironment::SetUp() {
     DawnTestEnvironment::SetUp();
+
+    mPlatform = std::make_unique<DawnPerfTestPlatform>(IsTracingEnabled());
+    mInstance->SetPlatform(mPlatform.get());
+}
+
+void DawnPerfTestEnvironment::TearDown() {
+    DumpTraceEventsToJSONFile();
+    DawnTestEnvironment::TearDown();
 }
 
 bool DawnPerfTestEnvironment::IsCalibrating() const {
@@ -73,6 +100,49 @@ unsigned int DawnPerfTestEnvironment::OverrideStepsToRun() const {
     return mOverrideStepsToRun;
 }
 
+bool DawnPerfTestEnvironment::IsTracingEnabled() const {
+    return mTraceFile != nullptr;
+}
+
+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["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,
                                    unsigned int iterationsPerStep,
                                    unsigned int maxStepsInFlight)
@@ -113,13 +183,27 @@ void DawnPerfTestBase::RunTest() {
     // Do another warmup run. Seems to consistently improve results.
     DoRunLoop(kMaximumRunTimeSeconds);
 
+    DawnPerfTestPlatform* platform =
+        reinterpret_cast<DawnPerfTestPlatform*>(gTestEnv->GetInstance()->GetPlatform());
+    const char* testName = ::testing::UnitTest::GetInstance()->current_test_info()->name();
+
+    // Only enable trace event recording in this section.
+    // We don't care about trace events during warmup and calibration.
+    platform->EnableTraceEventRecording(true);
+    {
+        TRACE_EVENT0(platform, "dawn.perf_test", testName);
         for (unsigned int trial = 0; trial < kNumTrials; ++trial) {
+            TRACE_EVENT0(platform, "dawn.perf_test", "Trial");
             DoRunLoop(kMaximumRunTimeSeconds);
             PrintResults();
         }
     }
+    platform->EnableTraceEventRecording(false);
+}
 
 void DawnPerfTestBase::DoRunLoop(double maxRunTime) {
+    dawn_platform::Platform* platform = gTestEnv->GetInstance()->GetPlatform();
+
     mNumStepsPerformed = 0;
     mRunning = true;
 
@@ -135,6 +219,7 @@ void DawnPerfTestBase::DoRunLoop(double maxRunTime) {
         while (signaledFenceValue - fence.GetCompletedValue() >= mMaxStepsInFlight) {
             mTest->WaitABit();
         }
+        TRACE_EVENT0(platform, "dawn.perf_test", "Step");
         Step();
         mTest->queue.Signal(fence, ++signaledFenceValue);
 

src/tests/perf_tests/DawnPerfTest.h

@@ -21,6 +21,8 @@ namespace utils {
     class Timer;
 }
 
+class DawnPerfTestPlatform;
+
 void InitDawnPerfTestEnvironment(int argc, char** argv);
 
 class DawnPerfTestEnvironment : public DawnTestEnvironment {
@@ -29,16 +31,26 @@ class DawnPerfTestEnvironment : public DawnTestEnvironment {
     ~DawnPerfTestEnvironment();
 
     void SetUp() override;
+    void TearDown() override;
 
     bool IsCalibrating() const;
     unsigned int OverrideStepsToRun() const;
 
+    // Returns whether tracing is enabled.
+    bool IsTracingEnabled() const;
+
   private:
+    void DumpTraceEventsToJSONFile() const;
+
     // Only run calibration which allows the perf test runner to save time.
     bool mIsCalibrating = false;
 
     // If non-zero, overrides the number of steps.
     unsigned int mOverrideStepsToRun = 0;
+
+    const char* mTraceFile = nullptr;
+
+    std::unique_ptr<DawnPerfTestPlatform> mPlatform;
 };
 
 class DawnPerfTestBase {

src/tests/perf_tests/DawnPerfTestPlatform.cpp

@@ -0,0 +1,94 @@
+// Copyright 2019 The Dawn Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "tests/perf_tests/DawnPerfTestPlatform.h"
+
+#include "dawn_platform/tracing/TraceEvent.h"
+#include "tests/perf_tests/DawnPerfTest.h"
+#include "utils/Timer.h"
+
+namespace {
+
+    struct TraceCategory {
+        unsigned char enabled;
+        const char* name;
+    };
+
+    constexpr TraceCategory gTraceCategories[2] = {
+        // TODO(enga): Remove the use of this macro, but keep it disabled by default in Chromium.
+        {1, TRACE_DISABLED_BY_DEFAULT("gpu.dawn")},
+        {1, "dawn.perf_test"},
+    };
+
+}  // anonymous namespace
+
+DawnPerfTestPlatform::DawnPerfTestPlatform(bool enableTracing)
+    : dawn_platform::Platform(), mEnableTracing(enableTracing), 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;
+}
+
+double DawnPerfTestPlatform::MonotonicallyIncreasingTime() {
+    // Move the time origin to the first call to this function, to avoid generating
+    // unnecessarily large timestamps.
+    static double origin = mTimer->GetAbsoluteTime();
+    return mTimer->GetAbsoluteTime() - origin;
+}
+
+// TODO(enga): Simplify this API.
+uint64_t DawnPerfTestPlatform::AddTraceEvent(char phase,
+                                             const unsigned char* categoryGroupEnabled,
+                                             const char* name,
+                                             uint64_t id,
+                                             double timestamp,
+                                             int numArgs,
+                                             const char** argNames,
+                                             const unsigned char* argTypes,
+                                             const uint64_t* argValues,
+                                             unsigned char flags) {
+    if (!mEnableTracing || !mRecordTraceEvents) {
+        return 0;
+    }
+
+    // Discover the category name based on categoryGroupEnabled.  This flag comes from the first
+    // parameter of TraceCategory, and corresponds to one of the entries in gTraceCategories.
+    static_assert(offsetof(TraceCategory, enabled) == 0,
+                  "|enabled| must be the first field of the TraceCategory class.");
+    const TraceCategory* category = reinterpret_cast<const TraceCategory*>(categoryGroupEnabled);
+
+    mTraceEventBuffer.emplace_back(phase, category->name, name, timestamp);
+    return static_cast<uint64_t>(mTraceEventBuffer.size());
+}
+
+void DawnPerfTestPlatform::EnableTraceEventRecording(bool enable) {
+    mRecordTraceEvents = enable;
+}
+
+const std::vector<DawnPerfTestPlatform::TraceEvent>& DawnPerfTestPlatform::GetTraceEventBuffer()
+    const {
+    return mTraceEventBuffer;
+}

src/tests/perf_tests/DawnPerfTestPlatform.h

@@ -0,0 +1,75 @@
+// Copyright 2019 The Dawn Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#ifndef TESTS_PERFTESTS_DAWNPERFTESTPLATFORM_H_
+#define TESTS_PERFTESTS_DAWNPERFTESTPLATFORM_H_
+
+#include <dawn_platform/DawnPlatform.h>
+
+#include <memory>
+#include <vector>
+
+namespace utils {
+    class Timer;
+}
+
+class DawnPerfTestPlatform : public dawn_platform::Platform {
+  public:
+    // These are trace events according to Google's "Trace Event Format".
+    // See https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU
+    // Only a subset of the properties are implemented.
+    struct TraceEvent final {
+        TraceEvent() {
+        }
+        TraceEvent(char phaseIn, const char* categoryNameIn, const char* nameIn, double timestampIn)
+            : phase(phaseIn), categoryName(categoryNameIn), name(nameIn), timestamp(timestampIn) {
+        }
+
+        char phase = 0;
+        const char* categoryName = nullptr;
+        const char* name = nullptr;
+        double timestamp = 0;
+    };
+
+    explicit DawnPerfTestPlatform(bool enableTracing);
+    ~DawnPerfTestPlatform() override;
+
+    void EnableTraceEventRecording(bool enable);
+    const std::vector<TraceEvent>& GetTraceEventBuffer() const;
+
+  private:
+    const unsigned char* GetTraceCategoryEnabledFlag(const char* name) override;
+
+    double MonotonicallyIncreasingTime() override;
+
+    uint64_t AddTraceEvent(char phase,
+                           const unsigned char* categoryGroupEnabled,
+                           const char* name,
+                           uint64_t id,
+                           double timestamp,
+                           int numArgs,
+                           const char** argNames,
+                           const unsigned char* argTypes,
+                           const uint64_t* argValues,
+                           unsigned char flags) override;
+
+    bool mEnableTracing = false;
+    bool mRecordTraceEvents = false;
+    std::unique_ptr<utils::Timer> mTimer;
+
+    // Trace event record.
+    std::vector<TraceEvent> mTraceEventBuffer;
+};
+
+#endif  // TESTS_PERFTESTS_DAWNPERFTESTPLATFORM_H_