[PATCH 00/11] tests: harden functional test suite against flakiness

[PATCH 00/11] tests: harden functional test suite against flakiness

[Wander Lairson Costa]

The functional test suite had several sources of intermittent
failure and weak diagnostics that made CI failures hard to
reproduce and debug: readiness detection for both stalld and
starvation_gen relied on fragile heuristics and racy liveness
checks, a test-ordering assumption used across several test
files turned out to be backwards, and the stalld startup
timeout was too short for PREEMPT_RT systems with large CPU
counts, where BPF tracepoint attachment can take well over 15
seconds due to SRCU synchronization. On top of that, many
assertion and startup failures did not dump the relevant log
output, and the test framework's own logging polluted the
system journal that other tests inspect directly.

This series addresses these issues end to end. stalld gains a
single deterministic "monitoring started" log marker emitted
once initialization completes, giving the test helpers a
stable synchronization point instead of matching internal
debug messages that could change across refactors. The
starvation_gen readiness check is reordered to check the log
file before process liveness, so a transient kill -0 miss no
longer aborts an otherwise healthy test. All 15 affected test
sections across five functional test files (test_fifo_boosting.sh,
test_fifo_priority_starvation.sh, test_starvation_detection.sh,
test_starvation_threshold.sh, and test_log_only.sh) are
reordered to start stalld before starvation_gen, since source
analysis showed the previous ordering rested on an unfounded
assumption about stalld's scanning loop and was itself a
source of intermittent timeouts. The stalld initialization
timeout is raised from 15s to 240s to tolerate slow BPF/SRCU
synchronization on large-CPU RT systems, paired with startup
timing instrumentation so the actual latency stays visible.
Diagnostics are improved by dumping log contents on every
assertion and startup failure, and helper functions are
switched to consistently call fail() instead of silently
swallowing errors. The test framework's own logging is
trimmed to stdout only, removing journal writes that had been
contaminating journalctl-based assertions in other tests.
Finally, run_tests.sh gains --verbose and --fail-fast options
for faster local debugging and CI triage.

With the exception of the single log marker added to stalld's
initialization path, every change in this series is confined
to the test framework and functional test scripts; no other
daemon runtime behavior is touched.

Wander Lairson Costa (11):
  stalld: add readiness log marker for tests
  tests: use fail() for error paths in helpers
  tests: add --verbose flag for bash trace output
  tests: drop journal logging from test framework
  tests: fix intermittent starvation_gen readiness failure
  tests: add --fail-fast flag to stop on first failure
  tests: dump log contents on assert_log_contains failure
  tests: dump log on start_stalld_with_log failure
  tests: start stalld before starvation_gen in all tests
  tests: add startup timing to stalld launch helpers
  tests: increase stalld initialization timeout to 240s

 src/stalld.c                                  |  2 +
 tests/functional/test_backend_selection.sh    |  2 +-
 tests/functional/test_fifo_boosting.sh        | 22 ++---
 .../test_fifo_priority_starvation.sh          | 38 ++++----
 tests/functional/test_log_only.sh             | 10 +--
 tests/functional/test_starvation_detection.sh | 18 ++--
 tests/functional/test_starvation_threshold.sh | 23 ++---
 tests/helpers/test_helpers.sh                 | 86 +++++++++----------
 tests/run_tests.sh                            | 23 ++++-
 9 files changed, 109 insertions(+), 115 deletions(-)

-- 
2.55.0

[PATCH 01/11] stalld: add readiness log marker for tests

[Wander Lairson Costa]

The test helper wait_for_stalld_ready() previously matched
implementation-detail messages like "checking cpu", "waiting
tasks", or "skipping" that appear during the first monitoring
cycle. These messages depend on system state and verbose-mode
internals that could change across refactors.

Add a "monitoring started" log_msg() call at the end of main()
initialization, after write_pidfile() and before entering the
main loop. Update wait_for_stalld_ready() to match this
deterministic marker instead of the old alternation pattern.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 src/stalld.c                  | 2 ++
 tests/helpers/test_helpers.sh | 2 +-
 2 files changed, 3 insertions(+), 1 deletion(-)

diff --git a/src/stalld.c b/src/stalld.c
index ac9800d..34b0fd0 100644
--- a/src/stalld.c
+++ b/src/stalld.c
@@ -1239,6 +1239,8 @@ int main(int argc, char **argv)
 
 	write_pidfile();
 
+	log_msg("monitoring started\n");
+
 	/* The less likely first. */
 	if (config_aggressive)
 		aggressive_main(cpus, config_nr_cpus);
diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index af341e0..53de276 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -696,7 +696,7 @@ wait_for_log_message() {
 wait_for_stalld_ready() {
 	local log_file=$1
 	local timeout=${2:-5}
-	wait_for_log_message "checking cpu\|waiting tasks\|skipping" "${timeout}" "${log_file}"
+	wait_for_log_message "monitoring started" "${timeout}" "${log_file}"
 }
 
 # Wait for stalld to detect a starving task.
-- 
2.55.0

[PATCH 02/11] tests: use fail() for error paths in helpers

[Wander Lairson Costa]

Replace ad-hoc error reporting in test_helpers.sh with the
framework's fail() function.  Twelve call sites previously used
echo/return 1, but callers never checked the return value, so
errors were silently ignored and tests continued in a broken
state.  fail() calls end_test and exit 1, which terminates the
test immediately on error.

Switch log() from echo to echo -e so the ANSI escape sequences
in the color variables are actually interpreted.  Where fail()
is preceded by cleanup actions (stop_stalld, signal delivery,
log dumps), move those actions before the fail call since it
does not return.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/helpers/test_helpers.sh | 38 ++++++++++++-----------------------
 1 file changed, 13 insertions(+), 25 deletions(-)

diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index 53de276..12b548e 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -45,7 +45,7 @@ log() {
 	local message="$*"
 
 	# Echo to stdout with timestamp
-	echo "${timestamp} ${message}"
+	echo -e "${timestamp} ${message}"
 
 	# Also send to journal with stalld tag for easy correlation
 	# Strip ANSI color codes before sending to journal
@@ -418,8 +418,7 @@ start_stalld() {
 		stalld_bin="../stalld"
 	fi
 	if [ ! -x "${stalld_bin}" ]; then
-		echo -e "${RED}ERROR: stalld binary not found at ${stalld_bin}${NC}"
-		return 1
+		fail "stalld binary not found at ${stalld_bin}"
 	fi
 
 	# Parse arguments to find pidfile if specified
@@ -485,12 +484,10 @@ start_stalld() {
 		if [ -f "$pidfile" ]; then
 			STALLD_PID=$(cat "$pidfile" 2>/dev/null)
 			if [ -z "${STALLD_PID}" ]; then
-				echo -e "${RED}ERROR: pidfile exists but is empty${NC}"
-				return 1
+				fail "pidfile exists but is empty"
 			fi
 		else
-			echo -e "${RED}ERROR: pidfile was not created within ${timeout} seconds${NC}"
-			return 1
+			fail "pidfile was not created within ${timeout} seconds"
 		fi
 	else
 		# No pidfile - use pgrep with retries
@@ -540,13 +537,11 @@ start_stalld() {
 
 	# Verify we found a PID and it's running
 	if [ -z "${STALLD_PID}" ]; then
-		echo -e "${RED}ERROR: Could not determine stalld PID${NC}"
-		return 1
+		fail "could not determine stalld PID"
 	fi
 
 	if ! process_alive ${STALLD_PID}; then
-		echo -e "${RED}ERROR: stalld PID ${STALLD_PID} is not running${NC}"
-		return 1
+		fail "stalld PID ${STALLD_PID} is not running"
 	fi
 
 	CLEANUP_PIDS+=("${STALLD_PID}")
@@ -676,8 +671,7 @@ wait_for_log_message() {
 	local log_file=$3
 
 	if [ -z "${log_file}" ]; then
-		echo -e "${RED}ERROR: wait_for_log_message requires a log file${NC}"
-		return 1
+		fail "wait_for_log_message requires a log file"
 	fi
 
 	# Process substitution runs tail in the background so bash
@@ -930,8 +924,7 @@ disable_dl_server() {
 		echo "Disabled DL-server for ${cpu_count} CPUs"
 		return 0
 	else
-		echo -e "${RED}ERROR: Failed to disable DL-server${NC}"
-		return 1
+		fail "failed to disable DL-server"
 	fi
 }
 
@@ -980,8 +973,7 @@ disable_rt_throttling() {
 			echo "Disabled RT throttling"
 			return 0
 		else
-			echo -e "${RED}ERROR: Failed to disable RT throttling (need root?)${NC}"
-			return 1
+			fail "failed to disable RT throttling (need root?)"
 		fi
 	else
 		echo -e "${YELLOW}WARNING: /proc/sys/kernel/sched_rt_runtime_us not found${NC}"
@@ -1173,9 +1165,8 @@ start_stalld_with_log() {
 	CLEANUP_PIDS+=("${STALLD_PID}")
 
 	if ! wait_for_stalld_ready "${log_file}" 15; then
-		echo -e "${RED}ERROR: stalld did not initialize within 15s${NC}"
 		stop_stalld
-		return 1
+		fail "stalld did not initialize within 15s"
 	fi
 }
 
@@ -1272,8 +1263,7 @@ init_functional_test() {
 start_starvation_gen() {
 	local starve_bin="${TEST_ROOT}/helpers/starvation_gen"
 	if [ ! -x "${starve_bin}" ]; then
-		echo -e "${RED}ERROR: starvation_gen not found at ${starve_bin}${NC}"
-		return 1
+		fail "starvation_gen not found at ${starve_bin}"
 	fi
 
 	STARVE_LOG="/tmp/stalld_starvgen_$$.log"
@@ -1293,10 +1283,9 @@ start_starvation_gen() {
 	local elapsed=0
 	while [ $elapsed -lt $timeout ]; do
 		if ! process_alive ${STARVE_PID}; then
-			echo -e "${RED}ERROR: starvation_gen exited prematurely${NC}"
 			echo "  Log contents:"
 			cat "${STARVE_LOG}"
-			return 1
+			fail "starvation_gen exited prematurely"
 		fi
 		if grep -q "Press Ctrl+C to stop early" "${STARVE_LOG}" 2>/dev/null; then
 			echo "starvation_gen ready (PID ${STARVE_PID})"
@@ -1306,7 +1295,6 @@ start_starvation_gen() {
 		elapsed=$((elapsed + 1))
 	done
 
-	echo -e "${RED}ERROR: starvation_gen did not become ready within ${timeout}s${NC}"
 	echo "  Log contents:"
 	cat "${STARVE_LOG}"
 	send_signal TERM ${STARVE_PID}
@@ -1314,7 +1302,7 @@ start_starvation_gen() {
 	if process_alive ${STARVE_PID}; then
 		send_signal KILL ${STARVE_PID}
 	fi
-	return 1
+	fail "starvation_gen did not become ready within ${timeout}s"
 }
 
 # Export functions for use in tests
-- 
2.55.0

[PATCH 03/11] tests: add --verbose flag for bash trace output

[Wander Lairson Costa]

Add a --verbose option to run_tests.sh that passes -vx to bash
when running test scripts, producing trace output in the per-test
log files for debugging test failures.

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

diff --git a/tests/run_tests.sh b/tests/run_tests.sh
index 1fbb3f2..6bfae0f 100755
--- a/tests/run_tests.sh
+++ b/tests/run_tests.sh
@@ -18,6 +18,7 @@ BACKENDS=("sched_debug" "queue_track")  # Backends to test
 THREADING_MODE_MATRIX=0  # Threading mode matrix testing disabled by default (enable with --full-matrix)
 THREADING_MODES=("power" "adaptive" "aggressive")  # Threading modes to test
 THREADING_MODE=""  # Specific threading mode to use (empty = default)
+VERBOSE=0  # Run tests with bash -vx for trace output
 
 # Source test helpers for RT throttling and DL-server management
 source "${TEST_ROOT}/helpers/test_helpers.sh" 2>/dev/null || true
@@ -480,8 +481,13 @@ run_shell_test() {
 		test_log="${RESULTS_DIR}/${backend_mode//:/_}_${test_name}.log"
 	fi
 
+	local bash_flags=""
+	if [ ${VERBOSE} -eq 1 ]; then
+		bash_flags="-vx"
+	fi
+
 	local start_time=$SECONDS
-	if bash "${test_path}" > "${test_log}" 2>&1; then
+	if bash ${bash_flags} "${test_path}" > "${test_log}" 2>&1; then
 		local elapsed=$((SECONDS - start_time))
 		echo -e "${GREEN}PASS${NC} (${elapsed}s)" | tee -a "${LOG_FILE}"
 		PASSED_TESTS=$((PASSED_TESTS + 1))
@@ -599,6 +605,10 @@ while [[ $# -gt 0 ]]; do
 			SPECIFIC_TEST="$2"
 			shift 2
 			;;
+		--verbose)
+			VERBOSE=1
+			shift
+			;;
 		--disable-dl-server)
 			DISABLE_DL_SERVER=1
 			shift
@@ -662,6 +672,7 @@ while [[ $# -gt 0 ]]; do
 			echo "                                aggressive - Aggressive (-A)"
 			echo ""
 			echo "Other Options:"
+			echo "  --verbose            Run tests with bash -vx for trace output"
 			echo "  --disable-dl-server  Disable DL-server before running tests"
 			echo "  -h, --help           Show this help"
 			echo ""
-- 
2.55.0

[PATCH 04/11] tests: drop journal logging from test framework

[Wander Lairson Costa]

The test helper's log() function wrote every message to the system
journal via logger -t stalld, tagging entries with [TEST] to
distinguish them from real stalld output.  start_test() and
end_test() also called logger directly alongside echo.

These journal entries interfered with test_logging_destinations.sh,
which inspects journalctl for stalld's own syslog messages.  The
[TEST] entries appeared under the same stalld identifier and had
to be filtered out, making the assertions fragile and causing
spurious failures from journal flush races.

Remove the logger calls and the ANSI-stripping sed from log().
Replace the separate echo/logger pairs in start_test() and
end_test() with a single log() call each.  The test framework
now writes only to stdout, leaving the journal free of test
noise.

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

diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index 12b548e..1e3d736 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -38,19 +38,13 @@ else
 	NC=''
 fi
 
-# Logging function that writes to both stdout and journal
-# This allows correlating test activities with stalld behavior in journalctl
+# Logging function that writes to stdout with a timestamp
 log() {
 	local timestamp="[$(date +'%H:%M:%S')]"
 	local message="$*"
 
 	# Echo to stdout with timestamp
 	echo -e "${timestamp} ${message}"
-
-	# Also send to journal with stalld tag for easy correlation
-	# Strip ANSI color codes before sending to journal
-	local clean_message=$(echo "${message}" | sed 's/\x1b\[[0-9;]*m//g')
-	logger -t stalld "[TEST] ${clean_message}"
 }
 
 # Parse common test options
@@ -87,20 +81,16 @@ parse_test_options() {
 # Start a test
 start_test() {
 	TEST_NAME=$1
-	echo -e "${BLUE}=== Starting test: ${TEST_NAME} ===${NC}"
-	# Log test start to journal for correlation
-	logger -t stalld "[TEST] === Starting test: ${TEST_NAME} ==="
+	log "${BLUE}=== Starting test: ${TEST_NAME} ===${NC}"
 }
 
 # End a test
 end_test() {
 	if [ ${TEST_FAILED} -eq 0 ]; then
-		echo -e "${GREEN}=== Test ${TEST_NAME}: PASSED ===${NC}"
-		logger -t stalld "[TEST] === Test ${TEST_NAME}: PASSED ==="
+		log "${GREEN}=== Test ${TEST_NAME}: PASSED ===${NC}"
 		return 0
 	else
-		echo -e "${RED}=== Test ${TEST_NAME}: FAILED ===${NC}"
-		logger -t stalld "[TEST] === Test ${TEST_NAME}: FAILED ==="
+		log "${RED}=== Test ${TEST_NAME}: FAILED ===${NC}"
 		return 1
 	fi
 }
-- 
2.55.0

[PATCH 05/11] tests: fix intermittent starvation_gen readiness failure

[Wander Lairson Costa]

The process_alive check in the start_starvation_gen polling loop
uses kill -0, which can occasionally fail even when the process
is running. When this happens before the readiness grep has a
chance to run, the test aborts with a spurious "exited
prematurely" error.

Reorder the loop to check the log file for the ready message
before checking process liveness, so a transient kill -0 failure
does not prevent detection of a process that is already running.
Increase the initial sleep from 0.01s to 0.5s to give
starvation_gen time to start up before the first poll.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/helpers/test_helpers.sh | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index 1e3d736..20937a3 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -1267,21 +1267,21 @@ start_starvation_gen() {
 	# starvation_gen prints "ready" after all threads pass the barrier.
 	# Brief initial sleep covers the fast path, then 1-second polling
 	# for slow/loaded systems.
-	sleep 0.01
+	sleep 0.5
 
 	local timeout=10
 	local elapsed=0
 	while [ $elapsed -lt $timeout ]; do
-		if ! process_alive ${STARVE_PID}; then
-			echo "  Log contents:"
-			cat "${STARVE_LOG}"
-			fail "starvation_gen exited prematurely"
-		fi
 		if grep -q "Press Ctrl+C to stop early" "${STARVE_LOG}" 2>/dev/null; then
 			echo "starvation_gen ready (PID ${STARVE_PID})"
 			return 0
 		fi
 		sleep 1
+		if ! process_alive ${STARVE_PID}; then
+			echo "  Log contents:"
+			cat "${STARVE_LOG}"
+			fail "starvation_gen exited prematurely"
+		fi
 		elapsed=$((elapsed + 1))
 	done
 
-- 
2.55.0

[PATCH 06/11] tests: add --fail-fast flag to stop on first failure

[Wander Lairson Costa]

Add a --fail-fast option to run_tests.sh that prints the test
summary and exits immediately when a test fails.  The exit
triggers the cleanup trap, so RT throttling and DL-server state
are still restored.

Use print_summary || true before exit 1 to prevent set -e from
intercepting the non-zero return of print_summary's final
[ ${FAILED_TESTS} -eq 0 ] check.

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

diff --git a/tests/run_tests.sh b/tests/run_tests.sh
index 6bfae0f..a2d50e0 100755
--- a/tests/run_tests.sh
+++ b/tests/run_tests.sh
@@ -19,6 +19,7 @@ THREADING_MODE_MATRIX=0  # Threading mode matrix testing disabled by default (en
 THREADING_MODES=("power" "adaptive" "aggressive")  # Threading modes to test
 THREADING_MODE=""  # Specific threading mode to use (empty = default)
 VERBOSE=0  # Run tests with bash -vx for trace output
+FAIL_FAST=0  # Stop on first test failure
 
 # Source test helpers for RT throttling and DL-server management
 source "${TEST_ROOT}/helpers/test_helpers.sh" 2>/dev/null || true
@@ -520,6 +521,10 @@ run_shell_test() {
 			if [ -n "${mode}" ]; then
 				MODE_FAILED["${mode}"]=$((MODE_FAILED["${mode}"] + 1))
 			fi
+			if [ ${FAIL_FAST} -eq 1 ]; then
+				print_summary || true
+				exit 1
+			fi
 		fi
 	fi
 }
@@ -609,6 +614,10 @@ while [[ $# -gt 0 ]]; do
 			VERBOSE=1
 			shift
 			;;
+		--fail-fast)
+			FAIL_FAST=1
+			shift
+			;;
 		--disable-dl-server)
 			DISABLE_DL_SERVER=1
 			shift
@@ -673,6 +682,7 @@ while [[ $# -gt 0 ]]; do
 			echo ""
 			echo "Other Options:"
 			echo "  --verbose            Run tests with bash -vx for trace output"
+			echo "  --fail-fast          Stop on first test failure"
 			echo "  --disable-dl-server  Disable DL-server before running tests"
 			echo "  -h, --help           Show this help"
 			echo ""
-- 
2.55.0

[PATCH 07/11] tests: dump log contents on assert_log_contains failure

[Wander Lairson Costa]

assert_starvation_detected and assert_boost_detected already dump the
log file before calling fail, but assert_log_contains does not, making
failures harder to diagnose in CI.  Add the same log-dump pattern so
the file contents appear in the output on any assertion failure.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/helpers/test_helpers.sh | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index 20937a3..a2db0a9 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -209,6 +209,8 @@ assert_log_contains() {
 		else
 			log "    Pattern '${pattern}' not found in ${log_file}"
 		fi
+		log "Log contents:"
+		cat "${log_file}"
 		fail "${message}"
 	fi
 }
-- 
2.55.0

[PATCH 08/11] tests: dump log on start_stalld_with_log failure

[Wander Lairson Costa]

When stalld fails to initialize within the timeout,
start_stalld_with_log calls fail without first dumping the log file,
making CI failures harder to diagnose.  Add the same log-dump pattern
used by assert_starvation_detected, assert_boost_detected and
assert_log_contains so the file contents appear in the output.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/helpers/test_helpers.sh | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index a2db0a9..85b1805 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -1157,6 +1157,8 @@ start_stalld_with_log() {
 	CLEANUP_PIDS+=("${STALLD_PID}")
 
 	if ! wait_for_stalld_ready "${log_file}" 15; then
+		log "Log contents:"
+		cat "${log_file}"
 		stop_stalld
 		fail "stalld did not initialize within 15s"
 	fi
-- 
2.55.0

[PATCH 09/11] tests: start stalld before starvation_gen in all tests

[Wander Lairson Costa]

The test sections previously started starvation_gen before stalld,
based on a belief that stalld's idle detection could miss tasks
appearing after it began scanning.  Source analysis showed this
concern was unfounded -- stalld re-scans continuously and will detect
starvation regardless of when the starved tasks appear.  Meanwhile,
the old ordering introduced intermittent failures: starvation_gen
could finish and exit before stalld had a chance to scan, causing
timeouts in assert_starvation_detected and wait_for_boost_detected.

Reorder all 15 test sections across test_fifo_boosting.sh,
test_fifo_priority_starvation.sh, test_starvation_detection.sh,
test_starvation_threshold.sh, and test_log_only.sh so that
start_stalld_with_log runs before start_starvation_gen.  Remove stale
comments about the old ordering rationale ("Create starvation FIRST",
"avoid idle detection race").

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/functional/test_fifo_boosting.sh        | 22 +++++------
 .../test_fifo_priority_starvation.sh          | 38 ++++++++-----------
 tests/functional/test_log_only.sh             | 10 ++---
 tests/functional/test_starvation_detection.sh | 18 ++++-----
 tests/functional/test_starvation_threshold.sh | 23 +++++------
 5 files changed, 45 insertions(+), 66 deletions(-)

diff --git a/tests/functional/test_fifo_boosting.sh b/tests/functional/test_fifo_boosting.sh
index e489950..4d2841d 100755
--- a/tests/functional/test_fifo_boosting.sh
+++ b/tests/functional/test_fifo_boosting.sh
@@ -22,16 +22,14 @@ init_functional_test "SCHED_FIFO Boosting Mechanism" "test_fifo_boost"
 test_section "Test 1: FIFO Boost with -F Flag"
 
 threshold=5
-# Create starvation FIRST (before stalld starts)
 starvation_duration=$((threshold + 5))
-log "Creating starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
-start_starvation_gen -c ${TEST_CPU} -p 80 -n 2 -d ${starvation_duration}
 
 log "Starting stalld with -F flag to force SCHED_FIFO boosting"
-# Note: -F requires non-single-threaded mode (aggressive mode)
-# Use -g 1 for 1-second granularity to ensure timely detection
 start_stalld_with_log "${STALLD_LOG}" -f -v -g 1 -N -F -A -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
 
+log "Creating starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
+start_starvation_gen -c ${TEST_CPU} -p 80 -n 2 -d ${starvation_duration}
+
 # Wait for boosting
 log "Waiting for boost detection..."
 assert_boost_detected "${STALLD_LOG}" "Boosting occurred with -F flag"
@@ -48,14 +46,13 @@ test_section "Test 2: FIFO Priority Verification"
 threshold=5
 rm -f "${STALLD_LOG}"
 
-# Create starvation FIRST
+log "Starting stalld with -F flag (FIFO boosting)"
+start_stalld_with_log "${STALLD_LOG}" -f -v -g 1 -N -F -A -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
+
 log "Creating starvation on CPU ${TEST_CPU}"
 start_starvation_gen -c ${TEST_CPU} -p 80 -n 1 -d 10
 tracked_pid=$(find_starved_child "${STARVE_PID}")
 
-log "Starting stalld with -F flag (FIFO boosting)"
-start_stalld_with_log "${STALLD_LOG}" -f -v -g 1 -N -F -A -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
-
 # Wait for boosting
 log "Waiting for boost detection..."
 wait_for_boost_detected "${STALLD_LOG}"
@@ -101,13 +98,12 @@ log "  Expected cycles: ~5"
 
 rm -f "${STALLD_LOG}"
 
-# Create starvation FIRST
-log "Creating starvation on CPU ${TEST_CPU}"
-start_starvation_gen -c ${TEST_CPU} -p 80 -n 1 -d 12
-
 start_stalld_with_log "${STALLD_LOG}" -f -v -g 1 -N -F -A -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU} \
     -d ${boost_duration} -p ${boost_period} -r ${boost_runtime}
 
+log "Creating starvation on CPU ${TEST_CPU}"
+start_starvation_gen -c ${TEST_CPU} -p 80 -n 1 -d 12
+
 # Wait for boosting to start
 log "Waiting for boost detection..."
 wait_for_boost_detected "${STALLD_LOG}"
diff --git a/tests/functional/test_fifo_priority_starvation.sh b/tests/functional/test_fifo_priority_starvation.sh
index 028b825..86c6517 100755
--- a/tests/functional/test_fifo_priority_starvation.sh
+++ b/tests/functional/test_fifo_priority_starvation.sh
@@ -27,17 +27,16 @@ test_section "Test 1: Basic FIFO-on-FIFO Starvation Detection"
 log "Testing: FIFO:10 blocker starves FIFO:5 blockee"
 
 threshold=5
-
-# Create starvation BEFORE starting stalld to avoid idle detection race
 starvation_duration=$((threshold + 5))
+
+log "Starting stalld with ${threshold}s threshold (log-only mode)"
+start_stalld_with_log "${STALLD_LOG}" -f -v -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
+
 log "Creating FIFO-on-FIFO starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
 log "  Blocker: SCHED_FIFO priority 10"
 log "  Blockee: SCHED_FIFO priority 5"
 start_starvation_gen -c ${TEST_CPU} -p 10 -b 5 -n 2 -d ${starvation_duration}
 
-log "Starting stalld with ${threshold}s threshold (log-only mode)"
-start_stalld_with_log "${STALLD_LOG}" -f -v -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
-
 # Wait for starvation detection
 log "Waiting for starvation detection..."
 assert_starvation_detected "${STALLD_LOG}" "FIFO-on-FIFO starvation detected"
@@ -57,6 +56,9 @@ rm -f "${STALLD_LOG}"
 threshold=5
 boost_duration=3
 
+log "Starting stalld with boosting enabled"
+start_stalld_with_log "${STALLD_LOG}" -f -v -N -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU} -d ${boost_duration}
+
 log "Creating FIFO-on-FIFO starvation on CPU ${TEST_CPU}"
 start_starvation_gen -c ${TEST_CPU} -p 10 -b 5 -n 1 -d 12
 
@@ -69,9 +71,6 @@ if [ -n "${blockee_pid}" ]; then
     log "Blockee task PID ${blockee_pid}, context switches before boost: ${ctxt_before}"
 fi
 
-log "Starting stalld with boosting enabled"
-start_stalld_with_log "${STALLD_LOG}" -f -v -N -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU} -d ${boost_duration}
-
 # Wait for detection and boosting
 wait_for_boost_detected "${STALLD_LOG}"
 sleep ${boost_duration}
@@ -103,16 +102,15 @@ log "Verify duration accumulates correctly (task merging)"
 
 rm -f "${STALLD_LOG}"
 threshold=3
-
-# Create long starvation to trigger multiple detection cycles
 starvation_duration=12
-log "Creating long FIFO-on-FIFO starvation for ${starvation_duration}s"
-start_starvation_gen -c ${TEST_CPU} -p 10 -b 5 -n 2 -d ${starvation_duration}
 
 log "Starting stalld with ${threshold}s threshold (log-only mode)"
 log "Will monitor for multiple detection cycles to verify timestamp preservation"
 start_stalld_with_log "${STALLD_LOG}" -f -v -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
 
+log "Creating long FIFO-on-FIFO starvation for ${starvation_duration}s"
+start_starvation_gen -c ${TEST_CPU} -p 10 -b 5 -n 2 -d ${starvation_duration}
+
 # Wait for multiple detection cycles
 log "Waiting for first detection cycle..."
 wait_for_starvation_detected "${STALLD_LOG}"
@@ -147,15 +145,14 @@ log "Testing edge case with only 1 priority difference"
 rm -f "${STALLD_LOG}"
 threshold=5
 
-# Test with very close priorities
+log "Starting stalld with ${threshold}s threshold"
+start_stalld_with_log "${STALLD_LOG}" -f -v -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
+
 log "Creating FIFO-on-FIFO starvation with close priorities"
 log "  Blocker: SCHED_FIFO priority 6"
 log "  Blockee: SCHED_FIFO priority 5"
 start_starvation_gen -c ${TEST_CPU} -p 6 -b 5 -n 1 -d $((threshold + 5))
 
-log "Starting stalld with ${threshold}s threshold"
-start_stalld_with_log "${STALLD_LOG}" -f -v -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
-
 # Wait for starvation detection
 log "Waiting for starvation detection..."
 if wait_for_starvation_detected "${STALLD_LOG}"; then
@@ -180,16 +177,13 @@ log "Ensure stalld boosts the blockee (FIFO:5), not the blocker (FIFO:10)"
 rm -f "${STALLD_LOG}"
 threshold=5
 
+log "Starting stalld with boosting enabled"
+start_stalld_with_log "${STALLD_LOG}" -f -v -N -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
+
 log "Creating FIFO-on-FIFO starvation"
 start_starvation_gen -c ${TEST_CPU} -p 10 -b 5 -n 2 -d 12 -v
-
-# Extract blocker and blockee PIDs from starvation_gen output
-# The output shows "Blocker TID: <pid>" and "Blockee N TID: <pid>"
 log "Starvation generator PID: ${STARVE_PID}"
 
-log "Starting stalld with boosting enabled"
-start_stalld_with_log "${STALLD_LOG}" -f -v -N -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
-
 # Wait for boosting
 log "Waiting for boost detection..."
 if wait_for_boost_detected "${STALLD_LOG}"; then
diff --git a/tests/functional/test_log_only.sh b/tests/functional/test_log_only.sh
index b38db70..cba7596 100755
--- a/tests/functional/test_log_only.sh
+++ b/tests/functional/test_log_only.sh
@@ -44,16 +44,12 @@ echo "Stalld will run on CPU ${STALLD_CPU}"
 LOG_FILE="/tmp/stalld_test_log_only_$$.log"
 CLEANUP_FILES+=("${LOG_FILE}")
 
-echo "Creating starvation on CPU ${TEST_CPU} (will run for 10 seconds)"
-
-# Start starvation generator BEFORE stalld to ensure CPU is busy from the start
-start_starvation_gen -c ${TEST_CPU} -p 10 -n 1 -d 10
-STARVGEN_PID=${STARVE_PID}
-
-# Start stalld in log-only mode with verbose output to capture logs
 echo "Starting stalld in log-only mode with 5 second threshold"
 start_stalld_with_log "${LOG_FILE}" -f -v -l -t 5 -c ${TEST_CPU} -a ${STALLD_CPU}
 
+echo "Creating starvation on CPU ${TEST_CPU} (will run for 10 seconds)"
+start_starvation_gen -c ${TEST_CPU} -p 10 -n 1 -d 10
+STARVGEN_PID=${STARVE_PID}
 echo "Starvation generator started (PID ${STARVGEN_PID})"
 echo "Waiting for starvation detection..."
 
diff --git a/tests/functional/test_starvation_detection.sh b/tests/functional/test_starvation_detection.sh
index 52031c5..9702f99 100755
--- a/tests/functional/test_starvation_detection.sh
+++ b/tests/functional/test_starvation_detection.sh
@@ -24,15 +24,14 @@ NUM_CPUS=$(get_num_cpus)
 test_section "Test 1: Basic Starvation Detection"
 
 threshold=5
-
-# Create starvation BEFORE starting stalld to avoid idle detection race
 starvation_duration=$((threshold + 5))
-log "Creating starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
-start_starvation_gen -c ${TEST_CPU} -p 80 -n 2 -d ${starvation_duration}
 
 log "Starting stalld with ${threshold}s threshold (log-only mode)"
 start_stalld_with_log "${STALLD_LOG}" -f -v -N -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
 
+log "Creating starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
+start_starvation_gen -c ${TEST_CPU} -p 80 -n 2 -d ${starvation_duration}
+
 # Wait for starvation detection
 log "Waiting for starvation detection..."
 assert_starvation_detected "${STALLD_LOG}" "Starvation detected"
@@ -50,13 +49,12 @@ test_section "Test 2: Context Switch Count Tracking"
 rm -f "${STALLD_LOG}"
 threshold=5
 
-# Create starvation
-log "Creating starvation on CPU ${TEST_CPU}"
-start_starvation_gen -c ${TEST_CPU} -p 80 -n 1 -d 10
-
 log "Starting stalld with ${threshold}s threshold (log-only mode)"
 start_stalld_with_log "${STALLD_LOG}" -f -v -N -l -t $threshold -c ${TEST_CPU} -a ${STALLD_CPU}
 
+log "Creating starvation on CPU ${TEST_CPU}"
+start_starvation_gen -c ${TEST_CPU} -p 80 -n 1 -d 10
+
 # Wait for starvation detection
 log "Waiting for starvation detection..."
 wait_for_starvation_detected "${STALLD_LOG}"
@@ -116,6 +114,8 @@ else
     rm -f "${STALLD_LOG}"
     threshold=5
 
+    start_stalld_with_log "${STALLD_LOG}" -f -v -N -l -t $threshold -c ${CPU0},${CPU1} -a ${STALLD_CPU_MULTI}
+
     # Create starvation on CPU0
     log "Creating starvation on CPU ${CPU0}"
     start_starvation_gen -c ${CPU0} -p 80 -n 1 -d 12
@@ -126,8 +126,6 @@ else
     start_starvation_gen -c ${CPU1} -p 80 -n 1 -d 12
     STARVE_PID1=${STARVE_PID}
 
-    start_stalld_with_log "${STALLD_LOG}" -f -v -N -l -t $threshold -c ${CPU0},${CPU1} -a ${STALLD_CPU_MULTI}
-
     # Wait for starvation detection on both CPUs
     log "Waiting for starvation detection on CPU ${CPU0}..."
     assert_starvation_detected "${STALLD_LOG}" "Starvation detected on CPU ${CPU0}" "30" "${CPU0}"
diff --git a/tests/functional/test_starvation_threshold.sh b/tests/functional/test_starvation_threshold.sh
index b372a87..bb4a862 100755
--- a/tests/functional/test_starvation_threshold.sh
+++ b/tests/functional/test_starvation_threshold.sh
@@ -25,16 +25,14 @@ init_functional_test "Starvation Threshold Option (-t)" "test_threshold"
 test_section "Test 1: Custom threshold of 5 seconds"
 
 threshold=5
-
-# Create starvation BEFORE starting stalld (avoid detecting kworker tasks)
 starvation_duration=10
-log "Creating starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
-start_starvation_gen -c "${TEST_CPU}" -p 80 -n 2 -d ${starvation_duration}
 
 log "Starting stalld with ${threshold}s threshold"
-# Use -i to ignore kernel workers that may starve before our test tasks
 start_stalld_with_log "${STALLD_LOG}" -f -v -N -M -g 1 -i "ksoftirqd,kworker" -c "${TEST_CPU}" -a "${STALLD_CPU}" -t ${threshold}
 
+log "Creating starvation on CPU ${TEST_CPU} for ${starvation_duration}s"
+start_starvation_gen -c "${TEST_CPU}" -p 80 -n 2 -d ${starvation_duration}
+
 # Wait for starvation detection
 log "Waiting for detection (threshold: ${threshold}s)"
 
@@ -51,15 +49,14 @@ test_section "Test 2: No detection before threshold"
 threshold=10
 rm -f "${STALLD_LOG}"
 
-# Create starvation BEFORE starting stalld (avoid detecting kworker tasks)
-# Create starvation that will last 6 seconds (less than threshold)
 starvation_duration=6
-log "Creating short starvation (${starvation_duration}s) with threshold of ${threshold}s"
-start_starvation_gen -c "${TEST_CPU}" -p 80 -n 2 -d ${starvation_duration}
 
 log "Starting stalld with ${threshold}s threshold"
 start_stalld_with_log "${STALLD_LOG}" -f -v -N -M -g 1 -c "${TEST_CPU}" -a "${STALLD_CPU}" -t ${threshold}
 
+log "Creating short starvation (${starvation_duration}s) with threshold of ${threshold}s"
+start_starvation_gen -c "${TEST_CPU}" -p 80 -n 2 -d ${starvation_duration}
+
 # Wait for starvation generator to fully complete
 wait "${STARVE_PID}" 2>/dev/null || true
 
@@ -82,16 +79,14 @@ test_section "Test 3: Shorter threshold (3 seconds)"
 threshold=3
 rm -f "${STALLD_LOG}"
 
-# Create starvation BEFORE starting stalld (avoid detecting kworker tasks)
-# Create starvation for 8 seconds
 starvation_duration=8
-log "Creating starvation for ${starvation_duration}s with threshold of ${threshold}s"
-start_starvation_gen -c "${TEST_CPU}" -p 80 -n 2 -d ${starvation_duration}
 
 log "Starting stalld with ${threshold}s threshold"
-# Use -i to ignore kernel workers that may starve before our test tasks
 start_stalld_with_log "${STALLD_LOG}" -f -v -N -M -g 1 -i "ksoftirqd,kworker" -c "${TEST_CPU}" -a "${STALLD_CPU}" -t ${threshold}
 
+log "Creating starvation for ${starvation_duration}s with threshold of ${threshold}s"
+start_starvation_gen -c "${TEST_CPU}" -p 80 -n 2 -d ${starvation_duration}
+
 # Wait for starvation detection
 log "Waiting for detection (threshold: ${threshold}s)"
 
-- 
2.55.0

[PATCH 10/11] tests: add startup timing to stalld launch helpers

[Wander Lairson Costa]

Instrument start_stalld and start_stalld_with_log to measure and log
the elapsed time from process launch to readiness.  Both functions
capture nanosecond timestamps via date +%s%N before and after the
startup sequence, compute the elapsed seconds with awk, and report
the result through log().

The echo in start_stalld is converted to log() for consistency with
the rest of the test framework.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/helpers/test_helpers.sh | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index 85b1805..9222d07 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -459,6 +459,8 @@ start_stalld() {
 		esac
 	fi
 
+	local start_ns=$(date +%s%N)
+
 	${stalld_bin} ${args} &
 	local shell_pid=$!
 
@@ -537,7 +539,9 @@ start_stalld() {
 	fi
 
 	CLEANUP_PIDS+=("${STALLD_PID}")
-	echo "stalld started with PID ${STALLD_PID}"
+	local end_ns=$(date +%s%N)
+	local elapsed=$(awk "BEGIN {printf \"%.3f\", (${end_ns} - ${start_ns}) / 1000000000}")
+	log "stalld started with PID ${STALLD_PID} (startup: ${elapsed}s)"
 	return 0
 }
 
@@ -1152,6 +1156,8 @@ start_stalld_with_log() {
 
 	# Start stalld with line-buffered output so tail -f can detect
 	# readiness immediately instead of waiting for the buffer to fill.
+	local start_ns=$(date +%s%N)
+
 	stdbuf -oL ${TEST_ROOT}/../stalld ${stalld_args} > "${log_file}" 2>&1 &
 	STALLD_PID=$!
 	CLEANUP_PIDS+=("${STALLD_PID}")
@@ -1162,6 +1168,10 @@ start_stalld_with_log() {
 		stop_stalld
 		fail "stalld did not initialize within 15s"
 	fi
+
+	local end_ns=$(date +%s%N)
+	local elapsed=$(awk "BEGIN {printf \"%.3f\", (${end_ns} - ${start_ns}) / 1000000000}")
+	log "stalld ready (PID ${STALLD_PID}, startup: ${elapsed}s)"
 }
 
 # Wait for scheduling policy to change to expected value
-- 
2.55.0

[PATCH 11/11] tests: increase stalld initialization timeout to 240s

[Wander Lairson Costa]

On PREEMPT_RT systems with large CPU counts (32+), BPF tracepoint
attachment triggers SRCU synchronization that can take well over
15 seconds, causing spurious test failures. Raise the
wait_for_stalld_ready timeout from 15s to 240s in
start_stalld_with_log and test_backend_selection.

This does not affect happy-path latency: the underlying grep -m1
returns as soon as "monitoring started" appears in the log.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 tests/functional/test_backend_selection.sh | 2 +-
 tests/helpers/test_helpers.sh              | 4 ++--
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/tests/functional/test_backend_selection.sh b/tests/functional/test_backend_selection.sh
index 26654e1..e6924ff 100755
--- a/tests/functional/test_backend_selection.sh
+++ b/tests/functional/test_backend_selection.sh
@@ -38,7 +38,7 @@ test_backend_flag() {
 	STALLD_PID=$!
 	CLEANUP_PIDS+=("${STALLD_PID}")
 
-	if ! wait_for_stalld_ready "${log_file}" 15; then
+	if ! wait_for_stalld_ready "${log_file}" 240; then
 		fail "stalld failed to start (${description})"
 	fi
 
diff --git a/tests/helpers/test_helpers.sh b/tests/helpers/test_helpers.sh
index 9222d07..e06ff8b 100755
--- a/tests/helpers/test_helpers.sh
+++ b/tests/helpers/test_helpers.sh
@@ -1162,11 +1162,11 @@ start_stalld_with_log() {
 	STALLD_PID=$!
 	CLEANUP_PIDS+=("${STALLD_PID}")
 
-	if ! wait_for_stalld_ready "${log_file}" 15; then
+	if ! wait_for_stalld_ready "${log_file}" 240; then
 		log "Log contents:"
 		cat "${log_file}"
 		stop_stalld
-		fail "stalld did not initialize within 15s"
+		fail "stalld did not initialize within 240s"
 	fi
 
 	local end_ns=$(date +%s%N)
-- 
2.55.0