From 9a4b5e1d908575a552f15204a51c92c9732f3d84 Mon Sep 17 00:00:00 2001 From: Ming Shao Date: Tue, 2 Aug 2022 15:40:07 +0800 Subject: [PATCH] ztest: Add test duration to summary for new ztest Add duration stats at both suite level and unit test level into test summary. The duration is at second level. Since the new ztest fx can execute a test suite for multiple times, the worst/longest test duration is collected. Note that even a skipped test can have a duration greater than 0 because the skip operation itself is not free. Signed-off-by: Ming Shao --- subsys/testsuite/include/zephyr/tc_util.h | 2 +- .../ztest/include/zephyr/ztest_test_new.h | 2 ++ subsys/testsuite/ztest/src/ztest_new.c | 25 +++++++++++++++---- 3 files changed, 23 insertions(+), 6 deletions(-) diff --git a/subsys/testsuite/include/zephyr/tc_util.h b/subsys/testsuite/include/zephyr/tc_util.h index edcf8c02d38..8366475373b 100644 --- a/subsys/testsuite/include/zephyr/tc_util.h +++ b/subsys/testsuite/include/zephyr/tc_util.h @@ -178,7 +178,7 @@ static inline void print_nothing(const char *fmt, ...) #ifndef Z_TC_END_RESULT #define Z_TC_END_RESULT(result, func) \ do { \ - TC_END_PRINT(result, " %s - %s in %u.%u seconds\n", \ + TC_END_PRINT(result, " %s - %s in %u.%03u seconds\n", \ TC_RESULT_TO_STR(result), func, tc_spend_time/1000, \ tc_spend_time%1000); \ } while (0) diff --git a/subsys/testsuite/ztest/include/zephyr/ztest_test_new.h b/subsys/testsuite/ztest/include/zephyr/ztest_test_new.h index 2ac62c6436b..4465f784152 100644 --- a/subsys/testsuite/ztest/include/zephyr/ztest_test_new.h +++ b/subsys/testsuite/ztest/include/zephyr/ztest_test_new.h @@ -129,6 +129,8 @@ struct ztest_unit_test_stats { uint32_t fail_count; /** The number of times that the test passed */ uint32_t pass_count; + /** The longest duration of the test across multiple times */ + uint32_t duration_worst_ms; }; /** diff --git a/subsys/testsuite/ztest/src/ztest_new.c b/subsys/testsuite/ztest/src/ztest_new.c index ff52c1af50f..f36328cff40 100644 --- a/subsys/testsuite/ztest/src/ztest_new.c +++ b/subsys/testsuite/ztest/src/ztest_new.c @@ -456,6 +456,7 @@ static int run_test(struct ztest_suite_node *suite, struct ztest_unit_test *test * running the tests. */ if (IS_ENABLED(CONFIG_MULTITHREADING)) { + get_start_time_cyc(); k_thread_create(&ztest_thread, ztest_thread_stack, K_THREAD_STACK_SIZEOF(ztest_thread_stack), (k_thread_entry_t)test_cb, suite, test, data, @@ -475,6 +476,7 @@ static int run_test(struct ztest_suite_node *suite, struct ztest_unit_test *test } else if (test_result != ZTEST_RESULT_SUITE_SKIP && test_result != ZTEST_RESULT_SUITE_FAIL) { test_result = ZTEST_RESULT_PENDING; + get_start_time_cyc(); run_test_rules(/*is_before=*/true, test, data); if (suite->before) { suite->before(data); @@ -487,6 +489,12 @@ static int run_test(struct ztest_suite_node *suite, struct ztest_unit_test *test suite->after(data); } run_test_rules(/*is_before=*/false, test, data); + + get_test_duration_ms(); + if (tc_spend_time > test->stats->duration_worst_ms) { + test->stats->duration_worst_ms = tc_spend_time; + } + phase = TEST_PHASE_FRAMEWORK; /* Flush all logs in case deferred mode and default logging thread are used. */ @@ -683,6 +691,7 @@ static void __ztest_init_unit_test_result_for_suite(struct ztest_suite_node *sui test->stats->skip_count = 0; test->stats->fail_count = 0; test->stats->pass_count = 0; + test->stats->duration_worst_ms = 0; } } @@ -710,10 +719,12 @@ static void __ztest_show_suite_summary_oneline(struct ztest_suite_node *suite) int suite_result = TC_PASS; struct ztest_unit_test *test = NULL; + unsigned int suite_duration_worst_ms = 0; /** summary of disctinct run */ while (((test = z_ztest_get_next_test(suite->name, test)) != NULL)) { distinct_total++; + suite_duration_worst_ms += test->stats->duration_worst_ms; if (test->stats->skip_count == test->stats->run_count) { distinct_skip++; } else if (test->stats->pass_count == test->stats->run_count) { @@ -740,11 +751,12 @@ static void __ztest_show_suite_summary_oneline(struct ztest_suite_node *suite) } TC_SUMMARY_PRINT("SUITE %s - %3d.%02d%% [%s]: pass = %d, fail = %d, " - "skip = %d, total = %d\n", + "skip = %d, total = %d duration = %u.%03u seconds\n", TC_RESULT_TO_STR(suite_result), passrate_major, passrate_minor, suite->name, distinct_pass, distinct_fail, - distinct_skip, distinct_total); + distinct_skip, distinct_total, + suite_duration_worst_ms / 1000, suite_duration_worst_ms % 1000); flush_log(); } @@ -766,8 +778,11 @@ static void __ztest_show_suite_summary_verbose(struct ztest_suite_node *suite) tc_result = TC_FAIL; } - TC_SUMMARY_PRINT(" - %s - [%s.%s]\n", TC_RESULT_TO_STR(tc_result), - test->test_suite_name, test->name); + TC_SUMMARY_PRINT(" - %s - [%s.%s] duration = %u.%03u seconds\n", + TC_RESULT_TO_STR(tc_result), + test->test_suite_name, test->name, + test->stats->duration_worst_ms / 1000, + test->stats->duration_worst_ms % 1000); if (flush_frequency % 3 == 0) { /** Reduce the flush frequencey a bit to speed up the output */ @@ -786,7 +801,7 @@ static void __ztest_show_suite_summary(void) * is dropped if it goes through the logging subsystem. */ flush_log(); - TC_SUMMARY_PRINT("\n------ TESTSUITE SUMMARY START ------\n"); + TC_SUMMARY_PRINT("\n------ TESTSUITE SUMMARY START ------\n\n"); flush_log(); for (struct ztest_suite_node *ptr = _ztest_suite_node_list_start; ptr < _ztest_suite_node_list_end; ++ptr) {