diff --git a/tests/benchdnn/common.cpp b/tests/benchdnn/common.cpp index 979a72ed8e9..861c2877fcf 100644 --- a/tests/benchdnn/common.cpp +++ b/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(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(); } diff --git a/tests/benchdnn/dnnl_common.cpp b/tests/benchdnn/dnnl_common.cpp index 47feb05d923..25da515274e 100644 --- a/tests/benchdnn/dnnl_common.cpp +++ b/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_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; diff --git a/tests/benchdnn/graph/bench_graph.cpp b/tests/benchdnn/graph/bench_graph.cpp index 441bd29ea8b..3559f64cd86 100644 --- a/tests/benchdnn/graph/bench_graph.cpp +++ b/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(); diff --git a/tests/benchdnn/rnn/rnn_task.hpp b/tests/benchdnn/rnn/rnn_task.hpp index cfc77a25832..9f5dc32c335 100644 --- a/tests/benchdnn/rnn/rnn_task.hpp +++ b/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>>(); + + // 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(); } diff --git a/tests/benchdnn/utils/task.hpp b/tests/benchdnn/utils/task.hpp index 8b18624b925..ad2f9ac294c 100644 --- a/tests/benchdnn/utils/task.hpp +++ b/tests/benchdnn/utils/task.hpp @@ -48,6 +48,12 @@ struct task_t { v_prim_ = std::make_shared< std::vector>>(); + + // 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(); } diff --git a/tests/benchdnn/utils/timer.cpp b/tests/benchdnn/utils/timer.cpp index 856e1eafea9..e8b0d4f134c 100644 --- a/tests/benchdnn/utils/timer.cpp +++ b/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 &get_global_service_timers() { // initializer list would use explicit constructor // ‘constexpr std::tuple<...>’. static const std::vector 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 { diff --git a/tests/benchdnn/utils/timer.hpp b/tests/benchdnn/utils/timer.hpp index 626476b434a..a27d6a8195c 100644 --- a/tests/benchdnn/utils/timer.hpp +++ b/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 {