From 672707f76e2dfb7c12c1870adbe2e889ae217fe9 Mon Sep 17 00:00:00 2001 From: Austin Eng Date: Wed, 30 Oct 2019 01:02:03 +0000 Subject: [PATCH] perf_tests: Compute metrics for command validation and recording This CL reads trace events from the tests and computes the total time of validation and command recording. Bug: dawn:208 Change-Id: I551d1e30e60b7d1a839b4fb834ad3608c6cedf63 Reviewed-on: https://dawn-review.googlesource.com/c/dawn/+/12782 Reviewed-by: Kai Ninomiya Commit-Queue: Austin Eng --- src/tests/perf_tests/DawnPerfTest.cpp | 108 ++++++++++++++++++-------- src/tests/perf_tests/DawnPerfTest.h | 4 +- 2 files changed, 80 insertions(+), 32 deletions(-) diff --git a/src/tests/perf_tests/DawnPerfTest.cpp b/src/tests/perf_tests/DawnPerfTest.cpp index c39b4da2cb..279e5b840d 100644 --- a/src/tests/perf_tests/DawnPerfTest.cpp +++ b/src/tests/perf_tests/DawnPerfTest.cpp @@ -21,15 +21,14 @@ #include #include + #include +#include namespace { DawnPerfTestEnvironment* gTestEnv = nullptr; - constexpr double kMicroSecondsPerSecond = 1e6; - constexpr double kNanoSecondsPerSecond = 1e9; - void DumpTraceEventsToJSONFile( const std::vector& traceEventBuffer, const char* traceFile) { @@ -274,40 +273,67 @@ void DawnPerfTestBase::DoRunLoop(double maxRunTime) { } void DawnPerfTestBase::OutputResults() { - double elapsedTimeSeconds[2] = { - mTimer->GetElapsedTime(), - mGPUTimeNs * 1e-9, - }; - - const char* clockNames[2] = { - "wall_time", - "gpu_time", - }; - - // If measured gpu time is non-zero, print that too. - unsigned int clocksToOutput = mGPUTimeNs > 0 ? 2 : 1; - - for (unsigned int i = 0; i < clocksToOutput; ++i) { - double secondsPerStep = elapsedTimeSeconds[i] / static_cast(mNumStepsPerformed); - double secondsPerIteration = secondsPerStep / static_cast(mIterationsPerStep); - - // Give the result a different name to ensure separate graphs if we transition. - if (secondsPerIteration > 1e-3) { - double microSecondsPerIteration = secondsPerIteration * kMicroSecondsPerSecond; - PrintResult(clockNames[i], microSecondsPerIteration, "us", true); - } else { - double nanoSecPerIteration = secondsPerIteration * kNanoSecondsPerSecond; - 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. + struct EventTracker { + double start = std::numeric_limits::max(); + double end = 0; + uint32_t count = 0; + }; + + EventTracker validationTracker = {}; + EventTracker recordingTracker = {}; + + double totalValidationTime = 0; + double totalRecordingTime = 0; + + // Note: We assume END timestamps always come after their corresponding BEGIN timestamps. + // TODO(enga): When Dawn has multiple threads, stratify by thread id. + for (const DawnPerfTestPlatform::TraceEvent& traceEvent : traceEventBuffer) { + EventTracker* tracker = nullptr; + double* totalTime = nullptr; + + switch (traceEvent.category) { + case dawn_platform::TraceCategory::Validation: + tracker = &validationTracker; + totalTime = &totalValidationTime; + break; + case dawn_platform::TraceCategory::Recording: + tracker = &recordingTracker; + totalTime = &totalRecordingTime; + break; + default: + break; + } + + if (tracker == nullptr) { + continue; + } + + if (traceEvent.phase == TRACE_EVENT_PHASE_BEGIN) { + tracker->start = std::min(tracker->start, traceEvent.timestamp); + tracker->count++; + } + + if (traceEvent.phase == TRACE_EVENT_PHASE_END) { + tracker->end = std::max(tracker->end, traceEvent.timestamp); + ASSERT(tracker->count > 0); + tracker->count--; + + if (tracker->count == 0) { + *totalTime += (tracker->end - tracker->start); + *tracker = {}; + } + } + } + + PrintPerIterationResultFromMilliseconds("wall_time", mTimer->GetElapsedTime() * 1e3, true); + PrintPerIterationResultFromMilliseconds("validation_time", totalValidationTime, true); + PrintPerIterationResultFromMilliseconds("recording_time", totalRecordingTime, true); const char* traceFile = gTestEnv->GetTraceFile(); if (traceFile != nullptr) { @@ -315,6 +341,26 @@ void DawnPerfTestBase::OutputResults() { } } +void DawnPerfTestBase::PrintPerIterationResultFromMilliseconds(const std::string& trace, + double valueInMilliseconds, + bool important) const { + if (valueInMilliseconds == 0) { + return; + } + + double millisecondsPerIteration = + valueInMilliseconds / static_cast(mNumStepsPerformed * mIterationsPerStep); + + // Give the result a different name to ensure separate graphs if we transition. + if (millisecondsPerIteration > 1e3) { + PrintResult(trace, millisecondsPerIteration, "ms", important); + } else if (millisecondsPerIteration > 1) { + PrintResult(trace, millisecondsPerIteration * 1e3, "us", important); + } else { + PrintResult(trace, millisecondsPerIteration * 1e6, "ns", important); + } +} + void DawnPerfTestBase::PrintResult(const std::string& trace, double value, const std::string& units, diff --git a/src/tests/perf_tests/DawnPerfTest.h b/src/tests/perf_tests/DawnPerfTest.h index 8d8ee1b307..3107b0585b 100644 --- a/src/tests/perf_tests/DawnPerfTest.h +++ b/src/tests/perf_tests/DawnPerfTest.h @@ -73,6 +73,9 @@ class DawnPerfTestBase { void AbortTest(); void RunTest(); + void PrintPerIterationResultFromMilliseconds(const std::string& trace, + double valueInMilliseconds, + bool important) const; void PrintResult(const std::string& trace, double value, const std::string& units, @@ -94,7 +97,6 @@ class DawnPerfTestBase { const unsigned int mMaxStepsInFlight; unsigned int mStepsToRun = 0; unsigned int mNumStepsPerformed = 0; - uint64_t mGPUTimeNs = 0; // TODO(enga): Measure GPU time with timing queries. std::unique_ptr mTimer; };