michaelh/zephyr
1
0
Fork 0
Code Releases Activity

ztest: Add test duration to summary for new ztest

Browse source 
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 <ming.shao@intel.com>
This commit is contained in:
Ming Shao 2022-08-02 15:40:07 +08:00 • committed by Anas Nashif
commit 9a4b5e1d90
3 changed files with 23 additions and 6 deletions
Download patch file Download diff file Expand all files Collapse all files

2
subsys/testsuite/include/zephyr/tc_util.h
View file

@ -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)

2
subsys/testsuite/ztest/include/zephyr/ztest_test_new.h
View file

@ -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;
};
/**

25
subsys/testsuite/ztest/src/ztest_new.c
View file

@ -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) {