tests: ztest: provide test execution times per ztest testcase

Add execution time for testing result of each ztest testcase as:

START - test_sem_multi_take_timeout_diff_sem
PASS - test_sem_multi_take_timeout_diff_sem in 2.54 seconds

Fix zephyrproject-rtos#32137.

Signed-off-by: Enjia Mai <enjiax.mai@intel.com>

scripts/pylib/twister/harness.py

@@ -2,7 +2,7 @@
 import re
 from collections import OrderedDict
 
-result_re = re.compile(".*(PASS|FAIL|SKIP) - (test_)?(.*)")
+result_re = re.compile(".*(PASS|FAIL|SKIP) - (test_)?(.*) in")
 
 class Harness:
     GCOV_START = "GCOV_COVERAGE_DUMP_START"

subsys/testsuite/include/tc_util.h

@@ -92,6 +92,27 @@ static inline const char *TC_RESULT_TO_STR(int result)
 	}
 }
 
+static uint32_t tc_start_time;
+static uint32_t tc_spend_time;
+
+static inline void get_start_time_cyc(void)
+{
+	/* Besides the ztest framework, some testcase will also call
+	 * TC_START() in their code. But the caller thread cannot be
+	 * in userspace.
+	 */
+	if (!_is_user_context()) {
+		tc_start_time = k_cycle_get_32();
+	}
+}
+
+static inline void test_time_ms(void)
+{
+	uint32_t spend_cycle = k_cycle_get_32() - tc_start_time;
+
+	tc_spend_time = k_cyc_to_ms_ceil32(spend_cycle);
+}
+
 #ifndef TC_ERROR
 #define TC_ERROR(fmt, ...)                               \
 	do {                                                 \
@@ -105,7 +126,11 @@ static inline const char *TC_RESULT_TO_STR(int result)
 #endif
 
 #ifndef TC_START
-#define TC_START(name) PRINT_DATA("START - %s\n", name)
+#define TC_START(name)							\
+	do {								\
+		PRINT_DATA("START - %s\n", name);			\
+		get_start_time_cyc();					\
+	} while (0)
 #endif
 
 #ifndef TC_END
@@ -114,10 +139,13 @@ static inline const char *TC_RESULT_TO_STR(int result)
 
 #ifndef Z_TC_END_RESULT
 /* prints result and the function name */
-#define Z_TC_END_RESULT(result, func)					\
-	do {								\
-		TC_END(result, " %s - %s\n", TC_RESULT_TO_STR(result), func); \
-		PRINT_LINE;						\
+#define Z_TC_END_RESULT(result, func)						\
+	do {									\
+		test_time_ms();							\
+		TC_END(result, " %s - %s in %u.%u seconds\n",			\
+			TC_RESULT_TO_STR(result), func, tc_spend_time/1000,	\
+			tc_spend_time%1000);					\
+		PRINT_LINE;							\
 	} while (0)
 #endif
 
@@ -157,7 +185,7 @@ static inline const char *TC_RESULT_TO_STR(int result)
 #define TC_CMD_ITEM(name)	cmd_##name
 #else
 #define TC_CMD_DEFINE(name)				\
-	int cmd_##name(int argc, char *argv[]) 		\
+	int cmd_##name(int argc, char *argv[])		\
 	{						\
 		TC_START(__func__);			\
 		name();					\