From 3cb3531da2f58819c61dd8d80b5a61133ab4b84b Mon Sep 17 00:00:00 2001 From: Jean-Pierre Bergamin Date: Sat, 19 Sep 2026 16:42:03 +0200 Subject: [PATCH] test(live): record host load beside timing bounds (iter 264) --- crates/ff-rdp-cli/tests/common/mod.rs | 15 ++++ .../live_220_navigating_action_with_page.rs | 7 +- .../tests/live/live_237_act_and_see_timing.rs | 7 +- .../tests/live/live_navigate_default_fast.rs | 7 +- .../iteration-264-sweep-load-timing-bounds.md | 83 +++++++++++++++++-- kb/research/hyalo-interaction-feedback.md | 11 +++ 6 files changed, 118 insertions(+), 12 deletions(-) diff --git a/crates/ff-rdp-cli/tests/common/mod.rs b/crates/ff-rdp-cli/tests/common/mod.rs index 70bc74b1..55b5efd1 100644 --- a/crates/ff-rdp-cli/tests/common/mod.rs +++ b/crates/ff-rdp-cli/tests/common/mod.rs @@ -1555,6 +1555,21 @@ pub fn assert_colors_equal(actual: &str, expected: &str, context: &str) { ); } +/// Return the host's current load-average text for timing-test diagnostics. +/// +/// This runs only after the timed operation, so collecting the diagnostic +/// cannot inflate the measurement it explains. Platforms without `uptime` +/// retain an explicit unavailable value rather than hiding the sample. +pub fn timing_load_note() -> String { + std::process::Command::new("uptime") + .output() + .ok() + .filter(|output| output.status.success()) + .map(|output| String::from_utf8_lossy(&output.stdout).trim().to_owned()) + .filter(|output| !output.is_empty()) + .unwrap_or_else(|| "load average unavailable".to_owned()) +} + // --------------------------------------------------------------------------- // PNG pixel decoding (iter-144 Theme D) // --------------------------------------------------------------------------- diff --git a/crates/ff-rdp-cli/tests/live/live_220_navigating_action_with_page.rs b/crates/ff-rdp-cli/tests/live/live_220_navigating_action_with_page.rs index 28a36820..60d49b18 100644 --- a/crates/ff-rdp-cli/tests/live/live_220_navigating_action_with_page.rs +++ b/crates/ff-rdp-cli/tests/live/live_220_navigating_action_with_page.rs @@ -308,6 +308,11 @@ fn live_non_navigating_click_with_page_is_not_delayed() { let started = Instant::now(); let click = run_json(port, &["click", "#noop", "--with-page"]); let elapsed = started.elapsed(); + let load = crate::common::timing_load_note(); + eprintln!( + "TIMING_SAMPLE test=live_non_navigating_click_with_page_is_not_delayed elapsed_ms={} {load}", + elapsed.as_millis() + ); assert_eq!( first_heading(&click), @@ -317,7 +322,7 @@ fn live_non_navigating_click_with_page_is_not_delayed() { assert!( elapsed < NO_NAVIGATION_BUDGET, "a non-navigating click --with-page took {elapsed:?}, over the {NO_NAVIGATION_BUDGET:?} \ - bound — the navigation settle loop must not run when nothing navigated: {click}" + bound — the navigation settle loop must not run when nothing navigated; {load}: {click}" ); stop_daemon(port); diff --git a/crates/ff-rdp-cli/tests/live/live_237_act_and_see_timing.rs b/crates/ff-rdp-cli/tests/live/live_237_act_and_see_timing.rs index 2f6723ad..3ab3c6d9 100644 --- a/crates/ff-rdp-cli/tests/live/live_237_act_and_see_timing.rs +++ b/crates/ff-rdp-cli/tests/live/live_237_act_and_see_timing.rs @@ -338,6 +338,11 @@ fn live_237_cancelled_submit_does_not_wait_out_the_timeout() { let started = Instant::now(); let typed = run_json(port, &["type", "input[name=q]", "lovelace", "--submit"]); let elapsed = started.elapsed(); + let load = crate::common::timing_load_note(); + eprintln!( + "TIMING_SAMPLE test=live_237_cancelled_submit_does_not_wait_out_the_timeout elapsed_ms={} {load}", + elapsed.as_millis() + ); assert_eq!( typed["results"]["navigated"], false, @@ -352,7 +357,7 @@ fn live_237_cancelled_submit_does_not_wait_out_the_timeout() { assert!( elapsed < Duration::from_millis(CLICK_TIMEOUT_MS / 5), "a cancelled submission must stay on the fast local check, not the wider \ - post-requestSubmit grace period, took {elapsed:?}" + post-requestSubmit grace period, took {elapsed:?}; {load}" ); stop_daemon(port); diff --git a/crates/ff-rdp-cli/tests/live/live_navigate_default_fast.rs b/crates/ff-rdp-cli/tests/live/live_navigate_default_fast.rs index 6aa9f43a..41aaf6bd 100644 --- a/crates/ff-rdp-cli/tests/live/live_navigate_default_fast.rs +++ b/crates/ff-rdp-cli/tests/live/live_navigate_default_fast.rs @@ -216,10 +216,15 @@ fn live_navigate_elapsed_matches_wall() { // strictly ≤ the externally-measured wall time (which also includes connect // + teardown). Assert it is within ±750ms and never absurdly small. let delta = (measured_wall_ms - elapsed_ms).abs(); + let load = crate::common::timing_load_note(); + eprintln!( + "TIMING_SAMPLE test=live_navigate_elapsed_matches_wall wall_ms={measured_wall_ms} \ + reported_ms={elapsed_ms} delta_ms={delta} {load}" + ); assert!( delta <= 750, "elapsed_ms ({elapsed_ms}) must be within ±750ms of measured wall ({measured_wall_ms}); \ - delta {delta}ms — honest-timing fix (iter-122 Theme B) regressed" + delta {delta}ms — honest-timing fix (iter-122 Theme B) regressed; {load}" ); assert!( elapsed_ms > 5, diff --git a/kb/iterations/iteration-264-sweep-load-timing-bounds.md b/kb/iterations/iteration-264-sweep-load-timing-bounds.md index 5fc43bbf..31bd78cc 100644 --- a/kb/iterations/iteration-264-sweep-load-timing-bounds.md +++ b/kb/iterations/iteration-264-sweep-load-timing-bounds.md @@ -2,7 +2,7 @@ title: "Iteration 264: three live timing bounds fail under sweep load, and nothing distinguishes that from a regression" type: iteration date: 2026-09-07 -status: planned +status: done branch: iter-264/sweep-load-timing-bounds depends_on: - iteration-252-content-process-resources-on-the-direct-route @@ -62,23 +62,88 @@ of the thing being asserted. What these tests need is a way to say *why* they we ## Scope -- [ ] measure each of the three in isolation, ten runs, and record the distribution — a bound +- [x] measure each of the three in isolation, ten runs, and record the distribution — a bound cannot be re-sized against a single loaded observation -- [ ] measure the same three under a deliberate sweep-like load and record the distribution -- [ ] for each, decide between: a wider bound justified by the isolated distribution; a bound +- [x] measure the same three under a deliberate sweep-like load and record the distribution +- [x] for each, decide between: a wider bound justified by the isolated distribution; a bound expressed against a measured baseline rather than a constant; or a failure message that distinguishes "over the bound" from "over the bound while the box was saturated" (e.g. capturing load average at assertion time, the way iteration 203's conditions 6 and 7 use it) -- [ ] whatever is chosen, the test must still fail on the regression it was written for — +- [x] whatever is chosen, the test must still fail on the regression it was written for — demonstrate that, do not assert it -## Acceptance Criteria [0/3] +## Acceptance Criteria [3/3] -- [ ] each of the three tests has an isolated and a loaded distribution recorded in this plan -- [ ] each has one of the three dispositions above applied, with the measurement that justifies it -- [ ] for at least `live_navigate_elapsed_matches_wall`, the iter-122 regression it guards is +- [x] each of the three tests has an isolated and a loaded distribution recorded in this plan +- [x] each has one of the three dispositions above applied, with the measurement that justifies it +- [x] for at least `live_navigate_elapsed_matches_wall`, the iter-122 regression it guards is re-introduced locally and shown to still fail the reworked assertion +## Iteration 264 measurements — 2026-09-19 + +Every entry below came from a separate test process and emitted exactly one +`TIMING_SAMPLE` marker after the timed operation. The runner rejected a run unless that marker +was present exactly once, so an exit-zero bind skip could not enter either distribution. Raw +per-run output, argv, environment, UTC start/end and exit status are under +`.git/ralph-loop/20260919-queue/iter264/{isolated,loaded}/`. + +The isolated set ran the tests sequentially with no deliberate load process and no foreign +Cargo or managed-Firefox workload present. The host was not idle: its one-minute load average +was 18.13–30.17. Values are sorted milliseconds; the third row measures +`abs(external wall - results.elapsed_ms)`. + +| test | isolated distribution (10/10 reached measurement) | +|---|---| +| `live_non_navigating_click_with_page_is_not_delayed` | 117, 119, 127, 129, 134, 163, 163, 167, 191, 220 | +| `live_237_cancelled_submit_does_not_wait_out_the_timeout` | 1322, 1360, 1385, 1393, 1393, 1403, 1419, 1429, 1446, 1448 | +| `live_navigate_elapsed_matches_wall` delta | 179, 190, 191, 192, 194, 194, 195, 197, 200, 227 | + +The loaded set used eight run-owned `yes` CPU workers on this 10-logical-core host, held for +the complete sequential 30-run set. This reproduces the CPU scheduling pressure of the six +parallel sweep workers without launching competing Cargo builds or sibling Firefox profiles. +The one-minute load average rose from 18.19 to 102.92. The cleanup trap stopped and waited for +the eight recorded PIDs; its post-cleanup process check was empty. + +| test | loaded distribution (10/10 reached measurement) | +|---|---| +| `live_non_navigating_click_with_page_is_not_delayed` | 178, 180, 192, 193, 194, 216, 216, 217, 237, 253 | +| `live_237_cancelled_submit_does_not_wait_out_the_timeout` | 1344, 1386, 1395, 1421, 1427, 1448, 1450, 1454, 1468, 1483 | +| `live_navigate_elapsed_matches_wall` delta | 249, 333, 378, 422, 431, 468, 507, 509, 523, 656 | + +### Dispositions + +All three use the permitted diagnostic disposition. Their existing bounds remain unchanged: +the largest deliberately loaded observations stayed well below 2500 ms, 2000 ms and 750 ms, +respectively. Each test now records the post-measurement host load-average line and includes it +in any bound failure. Collection happens after the timed operation, so it cannot inflate the +measurement. A future red therefore preserves the behavioral assertion while exposing whether +the host was saturated; load is context, not an automatic waiver. + +For the iter-122 sensitivity check, a temporary product mutation replaced plain `navigate`'s +reported `elapsed_ms` with `1`, reproducing the dishonest internal timing shape. The reworked +test reached its measurement (`wall_ms=425`, `reported_ms=1`, `delta_ms=424`) and failed with +exit 101 on the existing lower sanity assertion. The mutation was then removed; the restored +`navigate.rs` SHA-256 is `40ecd8188d6a63eb3967b8bf921af0e0899ebc7cd21eb5c3a6b79356c1e16a46`, +byte-for-byte equal to the branch baseline. Evidence: +`.git/ralph-loop/20260919-queue/iter264/temporary-iter122-mutation.patch` and +`iter122-mutation.log`. + +## Closing validation — 2026-09-19 + +- Firefox 156.0 dual-gate sweep: + `LIVE_SWEEP_SUMMARY executed=346 skipped=0 preexisting=0 vanished=0 launch_timeout=0 timed_out=0 total=346` +- Profile accounting: + `LIVE_SWEEP_PROFILES leaked=0 unattributed=0 root=/Users/james/Library/Application Support/ff-rdp/profiles` +- The three timing tests were named passes in that sweep. All nine enumerated xtask `check-*` + gates passed, followed in order by current-stable `cargo fmt`, strict workspace/all-target + clippy, and workspace tests. + +## Carry-over + +No new behavioral failure, diagnostic anomaly, unticked acceptance criterion or deferred item +was produced by this iteration. The pre-existing parked iteration 203 observations and the +unselected backlog remain outside this plan's scope. + ## Notes - Do not fold these into [[iteration-203-live-sweep-watch-conditions-third-holder]]: 203 holds diff --git a/kb/research/hyalo-interaction-feedback.md b/kb/research/hyalo-interaction-feedback.md index fd5f2f2c..be3b501c 100644 --- a/kb/research/hyalo-interaction-feedback.md +++ b/kb/research/hyalo-interaction-feedback.md @@ -108,3 +108,14 @@ Installed executable: /Users/james/.cargo/bin/hyalo, version 0.23.0 (adbafda6c7f - The combined read-help tool output was truncated by the tool-output budget, not Hyalo. No verified Hyalo defect found; no ../hyalo changes. Supervisor: new cascade carry-over initially reused275, already allocated on blocked262 branch. Hyalo mv dry-run correctly previewed one backlink rewrite; apply moved it to276 and updated that backlink. Scalar title/branch updated with set; unsupported body heading prose updated directly. This was queue-numbering coordination, not a Hyalo defect. Long mv --help output exceeded the calling-tool budget; no provider output loss established. + +## 2026-09-19 iteration264 and next-plan lookup + +Hyalo remains0.23.0. Worker operator error: `hyalo version` is unsupported; +`/Users/james/.cargo/bin/hyalo --version` succeeded. Supervisor guessed a269 +basename that did not exist; the exact filename recorded in the prior audit +worked with body/frontmatter reads. These are operator mistakes, not verified +Hyalo defects. Final264 scalar `set --file ... --property status=done` and +HYALO005 validation support completion without altering original AC wording. +Long combined reads were truncated by the calling tool, not Hyalo. No version +change or ../hyalo edit.