Amber script documentation for new TIMED_EXECUTION flag for RUN (#1048)

Amber script documentation and backend implementation for new TIMED_EXECUTION  flag for RUN

I have added the implementation in Amber which also includes the vk query backend implementation

crbug.com/361315331

---------

Co-authored-by: Peter McNeeley <[email protected]>

.gitignore

@@ -29,3 +29,9 @@ third_party/robin-hood-hashing
 # C-Lion
 .idea/
 cmake-build-*/
+
+### Clangd cached index files
+/.cache
+
+### The 'compile_commands' file can be generated at root
+compile_commands.json

CMakeLists.txt

@@ -26,6 +26,7 @@ endif()
 project(amber)
 enable_testing()
 
+set(CMAKE_EXPORT_COMPILE_COMMANDS ON)
 set(CMAKE_RUNTIME_OUTPUT_DIRECTORY ${PROJECT_BINARY_DIR})
 set(CMAKE_POSITION_INDEPENDENT_CODE ON)
 

docs/amber_script.md

@@ -989,18 +989,22 @@ value for `START_IDX` is 0. The default value for `COUNT` is the item count of
 vertex buffer minus the `START_IDX`. The same applies to `START_INSTANCE`
 (default 0) and `INSTANCE_COUNT` (default 1).
 
+The `TIMED_EXECUTION` is an optional flag that can be passed to the run command.
+This will cause Amber to insert device specific counters to time the execution
+of this pipeline command.
+
 ```groovy
 # Run the given |pipeline_name| which must be a `compute` pipeline. The
 # pipeline will be run with the given number of workgroups in the |x|, |y|, |z|
 # dimensions. Each of the x, y and z values must be a uint32.
-RUN {pipeline_name} _x_ _y_ _z_
+RUN [TIMED_EXECUTION] {pipeline_name} _x_ _y_ _z_
 ```
 
 ```groovy
 # Run the given |pipeline_name| which must be a `graphics` pipeline. The
 # rectangle at |x|, |y|, |width|x|height| will be rendered. Ignores VERTEX_DATA
 # and INDEX_DATA on the given pipeline.
-RUN {pipeline_name} \
+RUN [TIMED_EXECUTION] {pipeline_name} \
   DRAW_RECT POS _x_in_pixels_ _y_in_pixels_ \
   SIZE _width_in_pixels_ _height_in_pixels_
 ```
@@ -1010,7 +1014,7 @@ RUN {pipeline_name} \
 # grid at |x|, |y|, |width|x|height|, |columns|x|rows| will be rendered.
 # Ignores VERTEX_DATA and INDEX_DATA on the given pipeline.
 # For columns, rows of (5, 4) a total of 5*4=20 rectangles will be drawn.
-RUN {pipeline_name} \
+RUN [TIMED_EXECUTION] {pipeline_name} \
   DRAW_GRID POS _x_in_pixels_ _y_in_pixels_ \
   SIZE _width_in_pixels_ _height_in_pixels_ \
   CELLS _columns_of_cells_ _rows_of_cells_
@@ -1024,7 +1028,7 @@ RUN {pipeline_name} \
 # will be processed. The draw is instanced if |inst_count_value| is greater
 # than one. In case of instanced draw |inst_value| controls the starting
 # instance ID.
-RUN {pipeline_name} DRAW_ARRAY AS {topology} \
+RUN [TIMED_EXECUTION] {pipeline_name} DRAW_ARRAY AS {topology} \
     [ START_IDX _value_ (default 0) ] \
     [ COUNT _count_value_ (default vertex_buffer size - start_idx) ] \
     [ START_INSTANCE _inst_value_ (default 0) ] \
@@ -1040,7 +1044,7 @@ RUN {pipeline_name} DRAW_ARRAY AS {topology} \
 # will be processed. The draw is instanced if |inst_count_value| is greater
 # than one. In case of instanced draw |inst_value| controls the starting
 # instance ID.
-RUN {pipeline_name} DRAW_ARRAY AS {topology} INDEXED \
+RUN [TIMED_EXECUTION] {pipeline_name} DRAW_ARRAY AS {topology} INDEXED \
     [ START_IDX _value_ (default 0) ] \
     [ COUNT _count_value_ (default index_buffer size - start_idx) ] \
     [ START_INSTANCE _inst_value_ (default 0) ] \
@@ -1058,7 +1062,7 @@ RUN {pipeline_name} DRAW_ARRAY AS {topology} INDEXED \
 #
 # The pipeline will be run with the given ray tracing dimensions |x|, |y|, |z|.
 # Each of the x, y and z values must be a uint32.
-RUN {pipeline_name} \
+RUN [TIMED_EXECUTION] {pipeline_name} \
     RAYGEN {ray_gen_sbt_name} \
     [MISS {miss_sbt_name}] \
     [HIT {hit_sbt_name}] \

include/amber/amber.h

@@ -101,6 +101,9 @@ class Delegate {
   virtual amber::Result LoadBufferData(const std::string file_name,
                                        BufferDataFileType file_type,
                                        amber::BufferInfo* buffer) const = 0;
+
+  /// Mechanism for gathering timing from 'TIME_EXECUTION'
+  virtual void ReportExecutionTiming(double time_in_ms) = 0;
 };
 
 /// Stores configuration options for Amber.

samples/amber.cc

@@ -23,6 +23,7 @@
 #include <fstream>
 #include <iomanip>
 #include <iostream>
+#include <ostream>
 #include <set>
 #include <string>
 #include <utility>
@@ -67,6 +68,7 @@ struct Options {
   bool log_graphics_calls = false;
   bool log_graphics_calls_time = false;
   bool log_execute_calls = false;
+  bool log_execution_timing = false;
   bool disable_spirv_validation = false;
   bool enable_pipeline_runtime_layer = false;
   std::string shader_filename;
@@ -103,6 +105,7 @@ const char kUsage[] = R"(Usage: amber [options] SCRIPT [SCRIPTS...]
   --log-graphics-calls      -- Log graphics API calls (only for Vulkan so far).
   --log-graphics-calls-time -- Log timing of graphics API calls timing (Vulkan only).
   --log-execute-calls       -- Log each execute call before run.
+  --log-execution-timing    -- Log timing results from each command with the 'TIMED_EXECUTION' flag.
   --disable-spirv-val       -- Disable SPIR-V validation.
   --enable-runtime-layer    -- Enable pipeline runtime layer.
   -h                        -- This help text.
@@ -278,6 +281,8 @@ bool ParseArgs(const std::vector<std::string>& args, Options* opts) {
       opts->log_graphics_calls = true;
     } else if (arg == "--log-graphics-calls-time") {
       opts->log_graphics_calls_time = true;
+    } else if (arg == "--log-execution-timing") {
+      opts->log_execution_timing = true;
     } else if (arg == "--log-execute-calls") {
       opts->log_execute_calls = true;
     } else if (arg == "--disable-spirv-val") {
@@ -361,6 +366,16 @@ class SampleDelegate : public amber::Delegate {
     }
   }
 
+  void ReportExecutionTiming(double time_in_ms) override {
+    reported_execution_timing.push_back(time_in_ms);
+  }
+
+  std::vector<double> GetAndClearExecutionTiming() {
+    auto returning = reported_execution_timing;
+    reported_execution_timing.clear();
+    return returning;
+  }
+
   uint64_t GetTimestampNs() const override {
     return timestamp::SampleGetTimestampNs();
   }
@@ -400,6 +415,7 @@ class SampleDelegate : public amber::Delegate {
   bool log_graphics_calls_time_ = false;
   bool log_execute_calls_ = false;
   std::string path_ = "";
+  std::vector<double> reported_execution_timing;
 };
 
 std::string disassemble(const std::string& env,
@@ -519,7 +535,7 @@ int main(int argc, const char** argv) {
       recipe->SetFenceTimeout(static_cast<uint32_t>(options.fence_timeout));
 
     recipe->SetPipelineRuntimeLayerEnabled(
-      options.enable_pipeline_runtime_layer);
+        options.enable_pipeline_runtime_layer);
 
     recipe_data.emplace_back();
     recipe_data.back().file = file;
@@ -621,12 +637,34 @@ int main(int argc, const char** argv) {
     amber::Amber am(&delegate);
     result = am.Execute(recipe, &amber_options);
     if (!result.IsSuccess()) {
-      std::cerr << file << ": " << result.Error() << std::endl;
+      std::cerr << file << ": " << result.Error() << "\n";
       failures.push_back(file);
       // Note, we continue after failure to allow dumping the buffers which may
       // give clues as to the failure.
     }
 
+    auto execution_timing = delegate.GetAndClearExecutionTiming();
+    if (result.IsSuccess() && options.log_execution_timing &&
+        !execution_timing.empty()) {
+      std::cout << "Execution timing (in script-order):" << "\n";
+      std::cout << "    ";
+      bool is_first_iter = true;
+      for (auto& timing : execution_timing) {
+        if (!is_first_iter) {
+          std::cout << ", ";
+        }
+        is_first_iter = false;
+        std::cout << timing;
+      }
+      std::cout << "\n";
+      std::sort(execution_timing.begin(), execution_timing.end());
+      auto report_median =
+          (execution_timing[execution_timing.size() / 2] +
+           execution_timing[(execution_timing.size() - 1) / 2]) /
+          2;
+      std::cout << "Execution time median = " << report_median << " ms" << "\n";
+    }
+
     // Dump the shader assembly
     if (!options.shader_filename.empty()) {
 #if AMBER_ENABLE_SPIRV_TOOLS

src/CMakeLists.txt

@@ -153,6 +153,7 @@ if (${AMBER_ENABLE_TESTS})
     amberscript/parser_raytracing_test.cc
     amberscript/parser_repeat_test.cc
     amberscript/parser_run_test.cc
+    amberscript/parser_run_timed_execution_test.cc
     amberscript/parser_sampler_test.cc
     amberscript/parser_set_test.cc
     amberscript/parser_shader_opt_test.cc

src/amber.cc

@@ -132,11 +132,10 @@ Result CreateEngineAndCheckRequirements(const Recipe* recipe,
 
   // Engine initialization checks requirements.  Current backends don't do
   // much else.  Refactor this if they end up doing to much here.
-  Result r =
-      engine->Initialize(opts->config, delegate, script->GetRequiredFeatures(),
-                         script->GetRequiredProperties(),
-                         script->GetRequiredInstanceExtensions(),
-                         script->GetRequiredDeviceExtensions());
+  Result r = engine->Initialize(
+      opts->config, delegate, script->GetRequiredFeatures(),
+      script->GetRequiredProperties(), script->GetRequiredInstanceExtensions(),
+      script->GetRequiredDeviceExtensions());
   if (!r.IsSuccess())
     return r;
 

src/amberscript/parser.cc

@@ -2706,6 +2706,14 @@ Result Parser::ParseBufferInitializerFile(Buffer* buffer) {
 
 Result Parser::ParseRun() {
   auto token = tokenizer_->NextToken();
+
+  // Timed execution option for this specific run.
+  bool is_timed_execution = false;
+  if (token->AsString() == "TIMED_EXECUTION") {
+    token = tokenizer_->NextToken();
+    is_timed_execution = true;
+  }
+
   if (!token->IsIdentifier())
     return Result("missing pipeline name for RUN command");
 
@@ -2718,6 +2726,9 @@ Result Parser::ParseRun() {
   if (pipeline->IsRayTracing()) {
     auto cmd = MakeUnique<RayTracingCommand>(pipeline);
     cmd->SetLine(line);
+    if (is_timed_execution) {
+      cmd->SetTimedExecution();
+    }
 
     while (true) {
       if (tokenizer_->PeekNextToken()->IsInteger())
@@ -2791,6 +2802,9 @@ Result Parser::ParseRun() {
     auto cmd = MakeUnique<ComputeCommand>(pipeline);
     cmd->SetLine(line);
     cmd->SetX(token->AsUint32());
+    if (is_timed_execution) {
+      cmd->SetTimedExecution();
+    }
 
     token = tokenizer_->NextToken();
     if (!token->IsInteger()) {
@@ -2840,6 +2854,9 @@ Result Parser::ParseRun() {
         MakeUnique<DrawRectCommand>(pipeline, *pipeline->GetPipelineData());
     cmd->SetLine(line);
     cmd->EnableOrtho();
+    if (is_timed_execution) {
+      cmd->SetTimedExecution();
+    }
 
     Result r = token->ConvertToDouble();
     if (!r.IsSuccess())
@@ -2909,6 +2926,9 @@ Result Parser::ParseRun() {
     auto cmd =
         MakeUnique<DrawGridCommand>(pipeline, *pipeline->GetPipelineData());
     cmd->SetLine(line);
+    if (is_timed_execution) {
+      cmd->SetTimedExecution();
+    }
 
     Result r = token->ConvertToDouble();
     if (!r.IsSuccess())
@@ -3082,6 +3102,9 @@ Result Parser::ParseRun() {
     cmd->SetVertexCount(count);
     cmd->SetInstanceCount(instance_count);
     cmd->SetFirstInstance(start_instance);
+    if (is_timed_execution) {
+      cmd->SetTimedExecution();
+    }
 
     if (indexed)
       cmd->EnableIndexed();

src/amberscript/parser_buffer_test.cc

@@ -31,10 +31,12 @@ class DummyDelegate : public amber::Delegate {
   bool LogExecuteCalls() const override { return false; }
   void SetLogExecuteCalls(bool) {}
   bool LogGraphicsCallsTime() const override { return false; }
+
   void SetLogGraphicsCallsTime(bool) {}
   uint64_t GetTimestampNs() const override { return 0; }
   void SetScriptPath(std::string) {}
 
+  void ReportExecutionTiming(double) override {}
   amber::Result LoadBufferData(const std::string,
                                amber::BufferDataFileType type,
                                amber::BufferInfo* buffer) const override {

src/amberscript/parser_run_test.cc

@@ -48,6 +48,7 @@ RUN my_pipeline 2 4 5
   EXPECT_EQ(2U, cmd->AsCompute()->GetX());
   EXPECT_EQ(4U, cmd->AsCompute()->GetY());
   EXPECT_EQ(5U, cmd->AsCompute()->GetZ());
+  EXPECT_FALSE(cmd->AsCompute()->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunWithoutPipeline) {
@@ -218,6 +219,7 @@ RUN my_pipeline DRAW_RECT POS 2 4 SIZE 10 20)";
   EXPECT_FLOAT_EQ(4.f, cmd->AsDrawRect()->GetY());
   EXPECT_FLOAT_EQ(10.f, cmd->AsDrawRect()->GetWidth());
   EXPECT_FLOAT_EQ(20.f, cmd->AsDrawRect()->GetHeight());
+  EXPECT_FALSE(cmd->AsDrawRect()->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawRectWithComputePipelineInvalid) {
@@ -519,6 +521,7 @@ RUN my_pipeline DRAW_GRID POS 2 4 SIZE 10 20 CELLS 4 5)";
   EXPECT_FLOAT_EQ(20.f, cmd->AsDrawGrid()->GetHeight());
   EXPECT_EQ(4u, cmd->AsDrawGrid()->GetColumns());
   EXPECT_EQ(5u, cmd->AsDrawGrid()->GetRows());
+  EXPECT_FALSE(cmd->AsDrawGrid()->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawGridWithComputePipelineInvalid) {
@@ -887,6 +890,7 @@ RUN my_pipeline DRAW_ARRAY AS TRIANGLE_LIST START_IDX 1 COUNT 2)";
   EXPECT_EQ(Topology::kTriangleList, cmd->GetTopology());
   EXPECT_EQ(1U, cmd->GetFirstVertexIndex());
   EXPECT_EQ(2U, cmd->GetVertexCount());
+  EXPECT_FALSE(cmd->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawArraysInstanced) {
@@ -926,6 +930,7 @@ RUN my_pipeline DRAW_ARRAY AS TRIANGLE_LIST START_IDX 1 COUNT 2 START_INSTANCE 2
   EXPECT_EQ(Topology::kTriangleList, cmd->GetTopology());
   EXPECT_EQ(1U, cmd->GetFirstVertexIndex());
   EXPECT_EQ(2U, cmd->GetVertexCount());
+  EXPECT_FALSE(cmd->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawArraysCountOmitted) {
@@ -966,6 +971,7 @@ RUN my_pipeline DRAW_ARRAY AS TRIANGLE_LIST START_IDX 1)";
   EXPECT_EQ(1U, cmd->GetFirstVertexIndex());
   // There are 3 elements in the vertex buffer, but we start at element 1.
   EXPECT_EQ(2U, cmd->GetVertexCount());
+  EXPECT_FALSE(cmd->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawArraysStartIdxAndCountOmitted) {
@@ -1006,6 +1012,7 @@ RUN my_pipeline DRAW_ARRAY AS TRIANGLE_LIST)";
   EXPECT_EQ(static_cast<uint32_t>(0U), cmd->GetFirstVertexIndex());
   // There are 3 elements in the vertex buffer.
   EXPECT_EQ(3U, cmd->GetVertexCount());
+  EXPECT_FALSE(cmd->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawArraysIndexed) {
@@ -1052,6 +1059,7 @@ RUN my_pipeline DRAW_ARRAY AS TRIANGLE_LIST INDEXED)";
   EXPECT_EQ(static_cast<uint32_t>(0U), cmd->GetFirstVertexIndex());
   // There are 3 elements in the vertex buffer.
   EXPECT_EQ(3U, cmd->GetVertexCount());
+  EXPECT_FALSE(cmd->IsTimedExecution());
 }
 
 TEST_F(AmberScriptParserTest, RunDrawArraysIndexedMissingIndexData) {