benchdnn: add more timers to get better profiling information for regular validation runs

tests/benchdnn/common.cpp

@@ -143,10 +143,15 @@ void parse_result(res_t &res, const char *pstr) {
                 + " total:" + std::to_string(res.total) + ")";
     }
 
+    const auto &tct = res.timer_map.get_timer(timer::names::test_case_timer);
+    // Round to integer for nicer input.
+    const int64_t tct_ms = static_cast<int64_t>(tct.ms());
+    std::string tct_str = " (" + std::to_string(tct_ms) + " ms)";
+
     // This is the common format of the repro line ([] - for optional entries):
-    // case_num:status[ (reason)][ (error_stats)] __REPRO: prb_str
+    // case_num:status[ (reason)][ (error_stats)] (time) __REPRO: prb_str
     std::string full_repro = std::to_string(bs.tests) + ":" + std::string(state)
-            + reason + error_stat + " __REPRO: " + pstr;
+            + reason + error_stat + tct_str + " __REPRO: " + pstr;
     if (is_failed) {
         bs.failed++;
         bs.failed_cases.emplace(bs.tests, full_repro);
@@ -427,6 +432,8 @@ std::string locate_file(const std::string &fname) {
                 BENCHDNN_PRINT(50, "file used: %s\n", fullname.c_str());
                 ifs.close();
                 return fullname;
+            } else {
+                BENCHDNN_PRINT(50, "File not found at: %s\n", fullname.c_str());
             }
             ifs.close();
         }

tests/benchdnn/dnnl_common.cpp

@@ -368,7 +368,7 @@ int execute_and_wait(perf_function_t &exec_func, const dnnl_engine_t &engine,
     stream_t stream(engine);
     std::vector<dnnl_exec_arg_t> dnnl_args;
 
-    execute_unmap_args(args, dnnl_args);
+    TIME_EXECUTE(execute_unmap_args(args, dnnl_args));
 
     dnnl_status_t status = dnnl_runtime_error;
     bool run_regular_exec = true;
@@ -401,12 +401,12 @@ int execute_and_wait(perf_function_t &exec_func, const dnnl_engine_t &engine,
     }
 #endif
     if (run_regular_exec) {
-        status = exec_func(stream, dnnl_args);
-        DNN_SAFE(dnnl_stream_wait(stream), CRIT);
+        TIME_EXECUTE(status = exec_func(stream, dnnl_args));
+        TIME_EXECUTE(DNN_SAFE(dnnl_stream_wait(stream), CRIT));
     }
     if (res) res->state = EXECUTED;
 
-    execute_map_args(args);
+    TIME_EXECUTE(execute_map_args(args));
     if (status != dnnl_success) {
         if (res) res->state = FAILED;
         return FAIL;

tests/benchdnn/graph/bench_graph.cpp

@@ -46,7 +46,13 @@ void check_correctness(const settings_t &s) {
         const char *pstr = cpp_pstr.c_str();
         BENCHDNN_PRINT(1, "run: %s\n", pstr);
         res_t res {};
+
+        // A timer for each test case.
+        auto &tct = res.timer_map.get_timer(timer::names::test_case_timer);
+        tct.start();
         doit(&prb, &res);
+        tct.stamp();
+
         // Reset the memory size args for the graph after testing.
         reset_graph_mem_req();
 

tests/benchdnn/rnn/rnn_task.hpp

@@ -1,5 +1,5 @@
 /*******************************************************************************
-* Copyright 2023-2024 Intel Corporation
+* Copyright 2023-2025 Intel Corporation
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
@@ -45,6 +45,12 @@ struct rnn_task_t {
 
         v_prim_ = std::make_shared<
                 std::vector<benchdnn_dnnl_wrapper_t<dnnl_primitive_t>>>();
+
+        // A timer for each test case. Starts from `create_func_` and ends at
+        // `parse_result`.
+        auto &tct = res_.timer_map.get_timer(timer::names::test_case_timer);
+        tct.start();
+
         const prb_t *prb = prb_.get();
         SAFE(create_func_(*v_prim_, *prb, &res_), WARN);
         return OK;
@@ -68,6 +74,11 @@ struct rnn_task_t {
             do_func_(*v_prim_, *prb, &res_);
         }
 
+        // A timer for each test case. Starts from `create_func_` and ends at
+        // `parse_result`.
+        auto &tct = res_.timer_map.get_timer(timer::names::test_case_timer);
+        tct.stamp();
+
         return report();
     }
 

tests/benchdnn/utils/task.hpp

@@ -48,6 +48,12 @@ struct task_t {
 
         v_prim_ = std::make_shared<
                 std::vector<benchdnn_dnnl_wrapper_t<dnnl_primitive_t>>>();
+
+        // A timer for each test case. Starts from `create_func_` and ends at
+        // `parse_result`.
+        auto &tct = res_.timer_map.get_timer(timer::names::test_case_timer);
+        tct.start();
+
         SAFE(create_func_(*v_prim_, &prb_, &res_), WARN);
         return OK;
     }
@@ -74,6 +80,11 @@ struct task_t {
             BENCHDNN_PRINT(1, "run (just report, no exec): %s\n", prb_.str());
         }
 
+        // A timer for each test case. Starts from `create_func_` and ends at
+        // `parse_result`.
+        auto &tct = res_.timer_map.get_timer(timer::names::test_case_timer);
+        tct.stamp();
+
         return report();
     }
 

tests/benchdnn/utils/timer.cpp

@@ -1,5 +1,5 @@
 /*******************************************************************************
-* Copyright 2021-2023 Intel Corporation
+* Copyright 2021-2025 Intel Corporation
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
@@ -112,8 +112,14 @@ const std::vector<service_timers_entry_t> &get_global_service_timers() {
     // initializer list would use explicit constructor
     // ‘constexpr std::tuple<...>’.
     static const std::vector<service_timers_entry_t> global_service_timers = {
+            service_timers_entry_t {
+                    "create_pd", mode_bit_t::init, timer::names::cpd_timer},
+            service_timers_entry_t {
+                    "create_prim", mode_bit_t::init, timer::names::cp_timer},
             service_timers_entry_t {
                     "fill", mode_bit_t::exec, timer::names::fill_timer},
+            service_timers_entry_t {
+                    "execute", mode_bit_t::exec, timer::names::execute_timer},
             service_timers_entry_t {
                     "compute_ref", mode_bit_t::corr, timer::names::ref_timer},
             service_timers_entry_t {

tests/benchdnn/utils/timer.hpp

@@ -39,6 +39,8 @@
 #define TIME_COMPARE(func) TIME_FUNC(func, res, timer::names::compare_timer)
 // Designated timer to calculate time spent on filling
 #define TIME_FILL(func) TIME_FUNC(func, res, timer::names::fill_timer)
+// Designated timer to calculate time spent on execute
+#define TIME_EXECUTE(func) TIME_FUNC(func, res, timer::names::execute_timer)
 
 namespace timer {
 
@@ -101,6 +103,10 @@ const std::string cp_timer = "create_prim_timer";
 const std::string compare_timer = "compare_timer";
 // Driver's memory filling.
 const std::string fill_timer = "fill_timer";
+// Test case timer from the create function till dumping the output.
+const std::string test_case_timer = "test_case_timer";
+// Driver's execute.
+const std::string execute_timer = "execute_timer";
 } // namespace names
 
 struct timer_map_t {