Stop the ASAN lane reporting contention as a hang

.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

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:

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

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,18 +116,52 @@ 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
 # on this project with an unrelated prover run in the background, correct code
 # 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
 }

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.

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