test: Show the average time per test

Show the average duration of a test, so we can keep track of how it is
trending. Report the suite with the longest average test to encourage
people to improve it.

Add a function to update the stats based on the results from a single
suite and another to show the summary information.

Make this optional, since sandbox's SPL tests do not have a timer driver
and people may want to print results without times.

Signed-off-by: Simon Glass <sjg@chromium.org>

include/test/test.h

@@ -33,6 +33,8 @@ struct ut_stats {
  * @cur: Statistics for the current run
  * @total: Statistics for all test runs
  * @run_count: Number of times ut_run_list() has been called
+ * @worst: Sute which had the first per-text run time
+ * @worst_ms: Time taken by that test
  * @start: Store the starting mallinfo when doing leak test
  * @of_live: true to use livetree if available, false to use flattree
  * @of_root: Record of the livetree root node (used for setting up tests)
@@ -56,6 +58,8 @@ struct unit_test_state {
 	struct ut_stats cur;
 	struct ut_stats total;
 	int run_count;
+	const struct suite *worst;
+	int worst_ms;
 	struct mallinfo start;
 	struct device_node *of_root;
 	bool of_live;

test/cmd_ut.c

@@ -192,6 +192,36 @@ static int run_suite(struct unit_test_state *uts, struct suite *ste,
 	return ret;
 }
 
+static void show_stats(struct unit_test_state *uts)
+{
+	if (uts->run_count < 2)
+		return;
+
+	ut_report(&uts->total, uts->run_count);
+	if (CONFIG_IS_ENABLED(UNIT_TEST_DURATION) &&
+	    uts->total.test_count && uts->worst) {
+		ulong avg = uts->total.duration_ms / uts->total.test_count;
+
+		printf("Average test time: %ld ms, worst case '%s' took %d ms\n",
+		       avg, uts->worst->name, uts->worst_ms);
+	}
+}
+
+static void update_stats(struct unit_test_state *uts, const struct suite *ste)
+{
+	if (CONFIG_IS_ENABLED(UNIT_TEST_DURATION) && uts->cur.test_count) {
+		ulong avg;
+
+		avg = uts->cur.duration_ms ?
+			uts->cur.duration_ms /
+			uts->cur.test_count : 0;
+		if (avg > uts->worst_ms) {
+			uts->worst_ms = avg;
+			uts->worst = ste;
+		}
+	}
+}
+
 static int do_ut_all(struct unit_test_state *uts, struct cmd_tbl *cmdtp,
 		     int flag, int argc, char *const argv[])
 {
@@ -208,6 +238,7 @@ static int do_ut_all(struct unit_test_state *uts, struct cmd_tbl *cmdtp,
 			retval = run_suite(uts, ste, cmdtp, flag, 1, argv);
 			if (!any_fail)
 				any_fail = retval;
+			update_stats(uts, ste);
 		}
 	}
 	ut_report(&uts->total, uts->run_count);
@@ -306,6 +337,7 @@ static int do_ut(struct cmd_tbl *cmdtp, int flag, int argc, char *const argv[])
 
 		ret = run_suite(&uts, ste, cmdtp, flag, argc, argv);
 	}
+	show_stats(&uts);
 	if (ret)
 		return ret;
 	ut_uninit_state(&uts);

test/test-main.c

@@ -677,12 +677,16 @@ static int ut_run_tests(struct unit_test_state *uts, const char *prefix,
 void ut_report(struct ut_stats *stats, int run_count)
 {
 	if (run_count > 1)
-		printf("Suites run: %d, total tests", run_count);
+		printf("Total tests");
 	else
 		printf("Tests");
 	printf(" run: %d, ", stats->test_count);
-	if (stats)
+	if (stats && stats->test_count) {
-		printf("%ld ms, ", stats->duration_ms);
+		ulong dur = stats->duration_ms;
+
+		printf("%ld ms, average: %ld ms, ", dur,
+		       dur ? dur / stats->test_count : 0);
+	}
 	if (stats->skip_count)
 		printf("skipped: %d, ", stats->skip_count);
 	printf("failures: %d\n", stats->fail_count);