[PATCH stalld 04/36] tests: Add per-test runtime measurement to run_tests.sh

[Wander Lairson Costa <wander@redhat.com>]

The test runner provides no visibility into how long individual
tests take or the total suite runtime. This makes it difficult to
identify slow tests and to measure the impact of future
optimizations to test determinism.

Add elapsed time tracking to run_unit_test() and run_shell_test()
using bash's built-in SECONDS variable. Each test result now
includes the elapsed time in its output, changing the format from
"PASS" to "PASS (12s)" for all outcomes (PASS, FAIL, SKIP). The
total suite runtime is also displayed in print_summary().

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/run_tests.sh | 19 ++++++++++++++-----
 1 file changed, 14 insertions(+), 5 deletions(-)

diff --git a/tests/run_tests.sh b/tests/run_tests.sh
index 16b6750..bbb3b16 100755
--- a/tests/run_tests.sh
+++ b/tests/run_tests.sh
@@ -464,8 +464,10 @@ run_unit_test() {
 		test_log="${RESULTS_DIR}/${backend_mode//:/_}_${test_name}.log"
 	fi
 
+	local start_time=$SECONDS
 	if "${test_path}" > "${test_log}" 2>&1; then
-		echo -e "${GREEN}PASS${NC}" | tee -a "${LOG_FILE}"
+		local elapsed=$((SECONDS - start_time))
+		echo -e "${GREEN}PASS${NC} (${elapsed}s)" | tee -a "${LOG_FILE}"
 		PASSED_TESTS=$((PASSED_TESTS + 1))
 		if [ -n "${backend}" ]; then
 			BACKEND_PASSED["${backend}"]=$((BACKEND_PASSED["${backend}"] + 1))
@@ -474,7 +476,8 @@ run_unit_test() {
 			MODE_PASSED["${mode}"]=$((MODE_PASSED["${mode}"] + 1))
 		fi
 	else
-		echo -e "${RED}FAIL${NC}" | tee -a "${LOG_FILE}"
+		local elapsed=$((SECONDS - start_time))
+		echo -e "${RED}FAIL${NC} (${elapsed}s)" | tee -a "${LOG_FILE}"
 		echo "  See ${test_log} for details" | tee -a "${LOG_FILE}"
 		FAILED_TESTS=$((FAILED_TESTS + 1))
 		if [ -n "${backend}" ]; then
@@ -601,8 +604,10 @@ run_shell_test() {
 		test_log="${RESULTS_DIR}/${backend_mode//:/_}_${test_name}.log"
 	fi
 
+	local start_time=$SECONDS
 	if bash "${test_path}" > "${test_log}" 2>&1; then
-		echo -e "${GREEN}PASS${NC}" | tee -a "${LOG_FILE}"
+		local elapsed=$((SECONDS - start_time))
+		echo -e "${GREEN}PASS${NC} (${elapsed}s)" | tee -a "${LOG_FILE}"
 		PASSED_TESTS=$((PASSED_TESTS + 1))
 		if [ -n "${backend}" ]; then
 			BACKEND_PASSED["${backend}"]=$((BACKEND_PASSED["${backend}"] + 1))
@@ -612,9 +617,10 @@ run_shell_test() {
 		fi
 	else
 		local exit_code=$?
+		local elapsed=$((SECONDS - start_time))
 		if [ ${exit_code} -eq 77 ]; then
 			# Exit code 77 = SKIP (autotools convention)
-			echo -e "${YELLOW}SKIP${NC}" | tee -a "${LOG_FILE}"
+			echo -e "${YELLOW}SKIP${NC} (${elapsed}s)" | tee -a "${LOG_FILE}"
 			SKIPPED_TESTS=$((SKIPPED_TESTS + 1))
 			if [ -n "${backend}" ]; then
 				BACKEND_SKIPPED["${backend}"]=$((BACKEND_SKIPPED["${backend}"] + 1))
@@ -623,7 +629,7 @@ run_shell_test() {
 				MODE_SKIPPED["${mode}"]=$((MODE_SKIPPED["${mode}"] + 1))
 			fi
 		else
-			echo -e "${RED}FAIL${NC}" | tee -a "${LOG_FILE}"
+			echo -e "${RED}FAIL${NC} (${elapsed}s)" | tee -a "${LOG_FILE}"
 			echo "  See ${test_log} for details" | tee -a "${LOG_FILE}"
 			FAILED_TESTS=$((FAILED_TESTS + 1))
 			if [ -n "${backend}" ]; then
@@ -644,6 +650,7 @@ print_summary() {
 	echo -e "  ${GREEN}Passed:  ${PASSED_TESTS}${NC}" | tee -a "${LOG_FILE}"
 	echo -e "  ${RED}Failed:  ${FAILED_TESTS}${NC}" | tee -a "${LOG_FILE}"
 	echo -e "  ${YELLOW}Skipped: ${SKIPPED_TESTS}${NC}" | tee -a "${LOG_FILE}"
+	echo "  Time:    $((SECONDS - SUITE_START_TIME))s" | tee -a "${LOG_FILE}"
 
 	# Print per-backend statistics if matrix testing enabled
 	if [ ${BACKEND_MATRIX} -eq 1 ] && [ ${#BACKEND_TOTAL[@]} -gt 0 ]; then
@@ -866,6 +873,8 @@ run_specific_test() {
 
 # Main execution
 main() {
+	SUITE_START_TIME=$SECONDS
+
 	# Export BACKEND and THREADING_MODE for use by test scripts
 	export STALLD_TEST_BACKEND="${BACKEND}"
 	export STALLD_TEST_THREADING_MODE="${THREADING_MODE}"
-- 
2.53.0