From f925a439d535467d9ce9f2644841c1e38834fab2 Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Tue, 1 Sep 2026 10:27:10 +0800 Subject: [PATCH 1/2] Give the ASAN lane room for its slowest test test-dup-setfl-race races a dup against an F_SETFL sweep for 700 rounds, which takes about 10s under ASAN on an idle host. The lane capped each test at 30s, and the CI runner shares its machine with a second runner, so contention pushed the test past the cap and the suite reported a hang that was not one. Raise the cap to 60s, which is what the TSAN leg already uses. The number lives in two places because CI never reaches the check-asan target: it sets TEST_TIMEOUT itself and calls check-sanitizer, so the makefile default governs only a local run. They are policy for two different machines and may legitimately differ. Leave job_timeout at 30 minutes. The failing job ran for 1m42s, so raising it would buy nothing and would only delay the report of a real deadlock. --- .github/workflows/build.yml | 9 +++++---- mk/tests.mk | 8 +++++++- 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index edd8f26b..91f8ab73 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -162,7 +162,7 @@ jobs: asan_options: abort_on_error=1:detect_leaks=0 ubsan_options: '' tsan_options: '' - test_timeout: '30' + test_timeout: '60' job_timeout: 30 run_matrix: false check_target: check-sanitizer @@ -210,9 +210,10 @@ jobs: UBSAN_OPTIONS: ${{ matrix.ubsan_options }} TSAN_OPTIONS: ${{ matrix.tsan_options }} # Empty on the release leg leaves each script its own default: 60s in - # tests/driver.sh, 10s in tests/lib/test-runner.sh. The 30 on the ASAN - # and UBSAN legs is therefore a raise for the lanes and a cut for the - # driver. + # tests/driver.sh, 10s in tests/lib/test-runner.sh. So 30 on UBSAN raises + # the lanes and cuts the driver, while 60 on ASAN and TSAN raises the + # lanes and leaves the driver at its default. mk/tests.mk carries the + # matching check-{asan,ubsan,tsan} defaults and records why ASAN is 60. TEST_TIMEOUT: ${{ matrix.test_timeout }} HOMEBREW_NO_INSTALL_CLEANUP: 1 HOMEBREW_NO_AUTO_UPDATE: 1 diff --git a/mk/tests.mk b/mk/tests.mk index 05411868..c402a19b 100644 --- a/mk/tests.mk +++ b/mk/tests.mk @@ -114,6 +114,12 @@ endef # (test-runner.sh defaults to 10s) to keep the slowdown from surfacing as a # spurious TIMEOUT. TEST_TIMEOUT is only overridden if the caller has not # already set one. +# +# ASAN was raised from 30 after test-dup-setfl-race, whose 700 rounds take ~10s +# under ASAN on an idle host, timed out on a CI runner that shares its machine +# with a second runner. These defaults are for a local run: CI never reaches +# these targets, it sets TEST_TIMEOUT itself in .github/workflows/build.yml. +# The two are policy for different machines and may legitimately differ. # No "clean" prerequisite. These lanes used to depend on it, which removed the # whole build tree including the 186 cross-compiled guest binaries -- built with @@ -129,7 +135,7 @@ endef ## Run the sanitizer subset with AddressSanitizer (ASAN) check-asan: - ASAN_OPTIONS="abort_on_error=1:detect_leaks=0" TEST_TIMEOUT="$${TEST_TIMEOUT:-30}" $(MAKE) EXTRA_CFLAGS="-fsanitize=address -fno-omit-frame-pointer" check-sanitizer + ASAN_OPTIONS="abort_on_error=1:detect_leaks=0" TEST_TIMEOUT="$${TEST_TIMEOUT:-60}" $(MAKE) EXTRA_CFLAGS="-fsanitize=address -fno-omit-frame-pointer" check-sanitizer ## Run the sanitizer subset with UndefinedBehaviorSanitizer (UBSAN) check-ubsan: From c22431dc55546d2f4a9b74882d9de8bc259602bb Mon Sep 17 00:00:00 2001 From: Jim Huang Date: Tue, 1 Sep 2026 10:27:22 +0800 Subject: [PATCH 2/2] Sample host load before the watchdog, not after The per-test watchdogs re-run a timed-out test when the host is busy, so a run starved by a neighbour is not reported as a hang. The gate only ever read the load after the watchdog had fired. That reading is a 1-minute average, so contention that was already easing when the test started has decayed out of it by the time the test gives up, and the re-run never happens. Mark the load as the timed region starts and let the check afterwards accept either end. Two readings cover the window: the average decays with a 60s time constant, so a spike must end roughly 40s before a reading to fall under the threshold, which inside a 60s watchdog puts it at or before the mark. All three retry sites carried the same gap and now go through the pair. This is not what broke run 33440761454. No load figures survive from that runner, and under the 30s watchdog in force there the mark and the check average over windows that overlap by half, so the mark would most likely have agreed with the check. The cap raised in the previous commit is the fix for that run. This is a second gap the investigation turned up beside it. The state is lowercase and module-prefixed, matching hang_sample_out next door. Uppercase in these libraries means a caller-tunable knob, so reading one as internal state let a stray TEST_HOST_WAS_BUSY in the environment re-run every timeout. The mark runs before every test, so fold the predicate's two sysctl calls into one: sysctl takes several keys at once, which cuts six process creations per call to two. --- tests/driver.sh | 5 ++-- tests/lib/bash-compat.sh | 55 +++++++++++++++++++++++++++++++++------- tests/lib/test-runner.sh | 3 ++- tests/test-sharun.sh | 3 ++- 4 files changed, 53 insertions(+), 13 deletions(-) diff --git a/tests/driver.sh b/tests/driver.sh index ced82909..16ab3dbe 100755 --- a/tests/driver.sh +++ b/tests/driver.sh @@ -98,7 +98,7 @@ TEST_LIST="$SCRIPT_DIR/manifest.txt" # shellcheck source=tests/test-config.sh source "$SCRIPT_DIR/test-config.sh" source "$SCRIPT_DIR/lib/hang-sample.sh" -source "$SCRIPT_DIR/lib/bash-compat.sh" # test_host_is_busy +source "$SCRIPT_DIR/lib/bash-compat.sh" # test_host_busy_mark/_since_mark # Capture a stack sample from a test about to hit the watchdog. A hang that only # reproduces under suite load is otherwise reported as a bare "timeout after Ns" @@ -417,6 +417,7 @@ for i in "${filtered_idx[@]}"; do # "${array[@]}". Host-limit annotations live in the manifest. Keep this # execution path generic so adding another constrained test does not require # a name-qualified branch here. + test_host_busy_mark if host_nofile=$(elfuse_test_host_nofile "$TEST_LIST" "$name"); then run_test_binary "$binary" "$host_nofile" \ "$TESTDIR_ABS/test-timeouts/$(basename "$binary")-hang.txt" \ @@ -435,7 +436,7 @@ for i in "${filtered_idx[@]}"; do # Its sample goes to a separate file. The first attempt's is the one taken # while the suite was in the state that produced the timeout, so it is the # one worth keeping. - if [ "$rc" -eq 124 ] && test_host_is_busy; then + if [ "$rc" -eq 124 ] && test_host_busy_since_mark; then if [ "$TAP" -eq 1 ]; then echo "# $name timed out under host load; re-running" else diff --git a/tests/lib/bash-compat.sh b/tests/lib/bash-compat.sh index 99b28aa1..9b3a53bc 100644 --- a/tests/lib/bash-compat.sh +++ b/tests/lib/bash-compat.sh @@ -16,8 +16,11 @@ # . "$(dirname "${BASH_SOURCE[0]}")/lib/bash-compat.sh" # # Provides: -# epoch_us -- print current wall-clock time in microseconds -# bash_compat_require -- abort with a helpful message if BASH is too old +# epoch_us -- print current wall-clock time in microseconds +# bash_compat_require -- abort with a helpful message if BASH is too old +# test_host_is_busy -- true when the host is too loaded for timing +# test_host_busy_mark -- record that verdict as a timed region starts +# test_host_busy_since_mark -- true when busy at the mark or busy now # # Conventions for portable bash: # - Do not expand "${array[@]}" when the array may be empty under set -u @@ -113,8 +116,9 @@ else fi # True when this machine is too loaded for a wall-clock measurement to mean -# anything. Shared so the throughput guardrail and the per-test watchdog agree -# on what "busy" is rather than drifting apart. +# anything. One threshold for every caller, directly here for the throughput +# guardrail and through the mark pair below for the watchdogs, so they cannot +# drift apart on what "busy" means. # # The threshold is deliberately generous: below it, a timing failure is the code # and gets reported; above it, the number is measuring the neighbours. Observed @@ -122,9 +126,42 @@ fi # ran 2 to 3 times slower and tripped several bounds at once. test_host_is_busy() { - local load ncpu - load=$(sysctl -n vm.loadavg 2> /dev/null | awk '{print $2}') - ncpu=$(sysctl -n hw.ncpu 2> /dev/null) - [ -n "$load" ] && [ -n "$ncpu" ] || return 1 - awk -v l="$load" -v n="$ncpu" 'BEGIN { exit !(l > n * 0.6) }' + sysctl -n vm.loadavg hw.ncpu 2> /dev/null \ + | awk 'NR == 1 { l = $2 } NR == 2 { n = $1 } + END { exit !(NR == 2 && n > 0 && l > n * 0.6) }' +} + +# Asking only "is the host busy now" after a watchdog fires misses contention +# that was already easing when the run began: the reading is a 1-minute average, +# so a spike ending near the start of the test has decayed out of it by the time +# the test gives up. Mark the load as the timed region starts and let the check +# afterwards accept either end. +# +# Two readings cover the window and a third taken mid-run would add nothing. The +# average decays with a 60s time constant, so a spike must end roughly 40s +# before a reading to fall under the threshold, which inside a 60s watchdog puts +# it at or before the mark. One brief enough to hide from both readings is too +# brief to have eaten the run's headroom. +# +# Its own pair rather than a change to test_host_is_busy: the throughput +# guardrail wants the instantaneous reading, and one predicate cannot mean both. + +# Set by test_host_busy_mark, read by test_host_busy_since_mark. +test_host_busy_at_mark=0 + +test_host_busy_mark() +{ + # if/else rather than "test_host_is_busy && x=1", so the status returned is + # an assignment's and never the predicate's: this must return 0 on an idle + # host, including inside the set -e regions the callers run under. + if test_host_is_busy; then + test_host_busy_at_mark=1 + else + test_host_busy_at_mark=0 + fi +} + +test_host_busy_since_mark() +{ + [ "$test_host_busy_at_mark" -eq 1 ] || test_host_is_busy } diff --git a/tests/lib/test-runner.sh b/tests/lib/test-runner.sh index b660b39d..502eb016 100644 --- a/tests/lib/test-runner.sh +++ b/tests/lib/test-runner.sh @@ -158,6 +158,7 @@ run() local start_us end_us elapsed_us limit_us hang_sample_arm "$tool" "$TEST_TIMEOUT" \ "${BUILD_DIR:-build}/test-timeouts/$(basename "$tool")-hang.txt" + test_host_busy_mark start_us=$(epoch_us) if output=$(timeout "$TEST_TIMEOUT" ${TEST_RUNNER[@]+"${TEST_RUNNER[@]}"} \ "$(test_tool_path "$tool")" "$@" 2>&1); then @@ -183,7 +184,7 @@ run() # every attempt, so a second one still fails. The retry samples to its own # file so the first attempt's stack, taken in the state that produced the # timeout, survives. - if [ "$harness_timed_out" -eq 1 ] && test_host_is_busy; then + if [ "$harness_timed_out" -eq 1 ] && test_host_busy_since_mark; then # Informational, not a verdict: the test has not been decided yet, so # this must not advance the skip counter the summary reports. diff --git a/tests/test-sharun.sh b/tests/test-sharun.sh index 0d5833e4..871a0f2d 100755 --- a/tests/test-sharun.sh +++ b/tests/test-sharun.sh @@ -168,6 +168,7 @@ run_guest() local tag="$1" shift set +e + test_host_busy_mark timeout "$GUEST_TIMEOUT" "$@" > "$scratch/$tag.out" 2> "$scratch/$tag.err" guest_rc=$? @@ -185,7 +186,7 @@ run_guest() # the launcher and the probe, which exit 1 to 6 and never 124. A 124 here is # the cap and nothing else, so the only open question is whether load caused # it. - if [ "$guest_rc" -eq 124 ] && test_host_is_busy; then + if [ "$guest_rc" -eq 124 ] && test_host_busy_since_mark; then printf 'timeout under host load, re-running: %s\n' "$tag" >&2 timeout "$GUEST_TIMEOUT" "$@" > "$scratch/$tag.out" 2> "$scratch/$tag.err" guest_rc=$?