From 7a7d54738173185cecf24cd731f32a7d7be6b67b Mon Sep 17 00:00:00 2001 From: Austin Eng Date: Mon, 28 Oct 2019 23:08:17 +0000 Subject: [PATCH] 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 Reviewed-by: Corentin Wallez --- src/tests/perf_tests/DawnPerfTest.cpp | 121 +++++++++++------- src/tests/perf_tests/DawnPerfTest.h | 9 +- src/tests/perf_tests/DawnPerfTestPlatform.cpp | 21 ++- src/tests/perf_tests/DawnPerfTestPlatform.h | 5 +- 4 files changed, 91 insertions(+), 65 deletions(-) diff --git a/src/tests/perf_tests/DawnPerfTest.cpp b/src/tests/perf_tests/DawnPerfTest.cpp index 34e7230819..a49bc7a74d 100644 --- a/src/tests/perf_tests/DawnPerfTest.cpp +++ b/src/tests/perf_tests/DawnPerfTest.cpp @@ -29,6 +29,38 @@ namespace { constexpr double kMicroSecondsPerSecond = 1e6; constexpr double kNanoSecondsPerSecond = 1e9; + void DumpTraceEventsToJSONFile( + const std::vector& traceEventBuffer, + const char* traceFile) { + std::ofstream outFile; + outFile.open(traceFile, std::ios_base::app); + + Json::StreamWriterBuilder builder; + std::unique_ptr writer(builder.newStreamWriter()); + + for (const DawnPerfTestPlatform::TraceEvent& traceEvent : traceEventBuffer) { + Json::Value value(Json::objectValue); + + const Json::LargestInt microseconds = + static_cast(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(IsTracingEnabled()); + mPlatform = std::make_unique(); 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 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 { - return mTraceFile != nullptr; -} - -void DawnPerfTestEnvironment::DumpTraceEventsToJSONFile() const { - if (!IsTracingEnabled()) { - return; - } - - Json::Value eventsValue(Json::arrayValue); - - const std::vector& traceEventBuffer = - mPlatform->GetTraceEventBuffer(); - - for (const DawnPerfTestPlatform::TraceEvent& traceEvent : traceEventBuffer) { - Json::Value value(Json::objectValue); - - const Json::LargestInt microseconds = - static_cast(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(); +const char* DawnPerfTestEnvironment::GetTraceFile() const { + return mTraceFile; } 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(gTestEnv->GetInstance()->GetPlatform()); + + std::vector 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, diff --git a/src/tests/perf_tests/DawnPerfTest.h b/src/tests/perf_tests/DawnPerfTest.h index 2a19d43daa..8d8ee1b307 100644 --- a/src/tests/perf_tests/DawnPerfTest.h +++ b/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. - bool IsTracingEnabled() const; + // Returns the path to the trace file, or nullptr if traces should + // 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; diff --git a/src/tests/perf_tests/DawnPerfTestPlatform.cpp b/src/tests/perf_tests/DawnPerfTestPlatform.cpp index c9f74a5834..880d5e9cf8 100644 --- a/src/tests/perf_tests/DawnPerfTestPlatform.cpp +++ b/src/tests/perf_tests/DawnPerfTestPlatform.cpp @@ -33,18 +33,16 @@ namespace { } // anonymous namespace -DawnPerfTestPlatform::DawnPerfTestPlatform(bool enableTracing) - : dawn_platform::Platform(), mEnableTracing(enableTracing), mTimer(utils::CreateTimer()) { +DawnPerfTestPlatform::DawnPerfTestPlatform() + : 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; - } + for (const TraceCategory& category : gTraceCategories) { + if (strcmp(category.name, name) == 0) { + return &category.enabled; } } @@ -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::GetTraceEventBuffer() - const { - return mTraceEventBuffer; +std::vector DawnPerfTestPlatform::AcquireTraceEventBuffer() { + std::vector buffer = mTraceEventBuffer; + mTraceEventBuffer.clear(); + return buffer; } diff --git a/src/tests/perf_tests/DawnPerfTestPlatform.h b/src/tests/perf_tests/DawnPerfTestPlatform.h index 042ea6bd5f..9baef91f52 100644 --- a/src/tests/perf_tests/DawnPerfTestPlatform.h +++ b/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& GetTraceEventBuffer() const; + std::vector 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 mTimer;