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: 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=$?