Timing under load: the GPU span test, co-watch re-entry, and the SRT link tests #614
Loading…
Reference in a new issue
No description provided.
Delete branch "test/timing-under-load"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Four CI failures that came and went with how busy the runner's host was. For each, the cause was found and shown on the build host under load, and the defect behind it was fixed. A timeout was not raised to hide any of them. Based on main after #611; the CHANGELOG entry sits above #611's.
1. jouleclaw-energy: the GPU span test (standards-build energy job)
What failed.
tests/process_gpu.rsfailed in four ways:Cause. The host is shared. Other processes open, close and reset GPU clients all the time, and the test assumed they didn't:
What changed.
finish_showing_gpu, so the test can check the meter's own snapshots.process-gpu: oracle-checked:, so the step fails if the burn was never checked against the oracle.2. Co-watch: a page the room took for gone (wai-examples watch-together; joule-moq-web cowatch scenario)
What failed. "both play on Ada's control: not within 60000 ms", in watch-together (jobs 65458, 71887, 72455, 76030, 76114) and in the e2e cowatch scenario (jobs 67776, 70090, 73183, 76976, 77089).
Cause. It wasn't slowness; the page had stopped:
not_present, and the page entered again.time_reversed, and the page stopped for good.What changed.
leavecould be signed after its newjoin. The room now signs thatleavefirst, under the clock's lock.3. joule-contrib: the SRT link test (
thor-linux-arm64runner, runs 16749 and 17926)What failed.
part.recovery.max < 300_000 && part.margin_min > 0, with nothing dropped and every payload whole and in order.Cause. Under load, the receiving task fell up to 384 ms behind its socket, and two defects showed up:
What changed.
margin_min > 0).Verification
Run on the build host as CI would; every step passed.
cargo check --workspace --all-targets.srt_link10 of 10.e2ee.--only cowatch3 of 3.co_watch_verify.py,cowatch.test.mjsandlive_contribution_verify.py.wai breakingagainst main: no unacknowledged break.srt_link6/6.rapl,nvml.🤖 Generated with Claude Code
Step 5 of `a_gpu_span_is_a_sole_users_rail_or_an_exact_zero_or_no_figure` burns this process's GPU across a second child's exit and asserted matches!(refused, Err(GpuClientVanished { pid, .. }) if pid == second_pid) It failed on the macOS energy job four times since 2026-10-11 (jobs 21067, 36264, 75996, 76205), each time naming another process's pid. The meter was right each time; the assertion assumed the child's client is the only one that can vanish in that ~0.3 s span, and the build host is shared: Playwright's headless browsers, other test processes and mediaanalysisd open, close and reset GPU clients all the time (the same run's 1.5 s burn had already retried twice for two other pids). `apportion` checks this process's own clients first, then the others, each pass walking the start snapshot in order and naming the first client that is gone or went back. The registry lists clients oldest first, so any older client of another process's that vanished in the same span is named before the child's. Every such client is a true witness: its time over the span is lost, so `all_ns`, and the 99% sole-user test, cannot be decided. The step now proves what it is for, whatever else the host does: - the refusal is `GpuClientVanished`, never a figure; - the client it names was at the start under that pid and is gone or went back at the end (the check `until_no_client_vanished` already made, now one helper); - it is exactly the one the rule picks: this process's own vanished client first, else the first vanished in the start snapshot; - every client of the second child's is gone from the end snapshot; - with the host's other vanished clients taken out of the real start snapshot, the child's exit alone still refuses the span, naming the child; so the check cannot pass only because unrelated churn refused it. When another client was named it says which. The step is not retried: there is nothing to wait out, and a retry would hide a regression in the rule. The tie-break gets a unit test of its own over built snapshots (two other processes' clients vanish: the first at the start is named, in either order, gone or gone back alike; this process's own vanished client is named even when it comes last), and `GpuClientVanished`'s doc states it. The meter is unchanged. Verified on the build host (load 95-160): clippy -D warnings on jouleclaw-energy with `--features ioreport` and without; the CI step (`cargo test -p jouleclaw-energy --features ioreport`, the liveness line printed) passed; process_gpu passed 5 of 5 on the host as it is and 6 of 6 beside a churner opening an idle GPU client for 1.5 s every 2.5 s, which failed the old assertion 2 of 6. In one of those six the refusal named a churner's client, as in CI, and every check above held. Falsified: dropping a vanished other-process client instead of refusing fails step 5 (it gave GpuShared) and two unit tests; walking the start snapshot last-first fails the new unit test alone. Co-Authored-By: Claude Opus 5.5 <[email protected]>The macOS energy job's process_gpu test gave up when a GPU client vanished in six spans in a row: its checks needed a span in which no client of the shared host vanished, and on a host whose other sessions open and close GPU clients every second there may be none. Reproduced on the build host beside a churner of short-lived GPU clients of our own: at one every 0.75 s, 4 of 4 runs gave up; at one every 1.5 s each run took 2-4 tries. Two other failures had the same root: the oracle's sum over every client gave up when one went back inside its window (job 27254, the `.expect` on `oracle_times`), and fell below the counter's when a client came and went inside the span (job 48857, the every-client assertion). No span now needs to be free of churn. Each span of the counter's or the span meter's is bracketed by `ioreg` listings of the registry, read independently of the counter: before it, around its work and after it. `classify` sorts every client against them. A registry entry once destroyed never comes back and its ID is not reused, so: - a client two reads list is in every read between them, under one pid; anything else is a contradiction and fails the test: a client the end snapshot lacks while `ioreg` lists it after (step 5's own check, now on every span), one the start lacks while `ioreg` listed it before and after, one both snapshots hold that `ioreg` did not list around the work, one gone inside the work and back in the end snapshot; - a client's time goes down only where a queue of it closed, which the listings show as a fall, so each counter reading lies between the listings either side of it, or on one side of a fall across it; a reading the registry does not explain voids the span; - a client the counter saw vanish is corroborated if `ioreg` listed it under the same pid (gone) or showed its fall inside the span (gone back); one `ioreg` never listed voids the span; - a client only `ioreg` listed inside the span, or a fall it showed where the counter saw an advance, is GPU time the counter's snapshots cannot hold, counted as hidden, a lower bound; - this process's own clients must be clean, or the span is void. A void span is taken again after 0.5, 1, 2, 4, 8, 8 ... s, and none the registry vouches for in 90 s fails as `process-gpu INCONCLUSIVE`, with each reason's count: not a verdict, and not a pass. A refusal must be the registry's: a corroborated vanished client refuses the span, naming the client the meter's rule picks (`expected_refusal`, factored out of step 5), and with none the span is not refused. The checks then run on the view, the snapshots with the vanished clients taken out of both, which can only raise this process's share. `agrees_with_oracle` checks client by client. This process's GPU time equals `ioreg`'s exactly, as before. The clients whose time went down nowhere advanced at most the oracle's advance plus what the gap can hold (their lower bound is now the sorting's, per client). The meter's every-client time is the sum over the view's clients. The rail is checked against the test's own IOReport read on every span whose snapshots both read it current, shared ones included (it had been on sole-user spans only), and a figure's rail is the snapshots' own advance. A figure must be a sole user's share of the time the counter saw plus the time hidden from it. `oracle_times` and its give-up are gone. Steps 4c and 6 take the span meter's span through `finish_showing_gpu` (the previous commit) and check that it is the GPU counter's figure, or the CPU alone with the counter's reason, over the meter's own snapshots, where the test had picked a span out of six by the text of its reason. A corroborated refusal is accepted there as the CPU alone, `HwShunt`, `Partial`, with CPU energy. Step 5's span-meter span gives the counter's reason over its own snapshots. The idle spans of steps 3 and 4a, and 4c's CPU-only span, also assert that `ioreg` saw no GPU time of this process's inside them. After the liveness askers, the test waits, at most 3 s and never failing, for this process's own clients to settle. the_span_classifier_sorts_every_client drives `classify` over six built reads: clean; gone and gone back, with the registry vouching and without; made and destroyed inside the span (48857's shape); a fall inside the work that the counter saw as an advance (27254's); falls across each snapshot inside the span and outside it; under- and over-reads; this process's own client not clean; each contradiction and a pid mismatch; `expected_refusal`'s order; and the 99% gate with hidden time. standards-build.yml: the jouleclaw-energy step also greps `process-gpu: oracle-checked:`, which step 2 prints once its burn was checked against the oracle. MEASURED_ENERGY.md says what the test checks. Verified on the build host, at this commit's jouleclaw files: clippy -D warnings on jouleclaw-energy with `--features ioreport` and without; the macOS energy job's jouleclaw-energy step as standards-build.yml runs it (under `bash -eo pipefail`, both greps), 5 of 5, three of them beside a churner of short-lived GPU clients of our own every 0.75 s; and the process_gpu test 16 of 16, 4 quiet and 4 beside a churner every 3, 1.5 and 0.75 s, with no void span, no INCONCLUSIVE and no contradiction, every vanished client corroborated on the first attempt. A read-only walk of the registry the way the counter walks it, every 5 ms for 60 s beside a churner every 0.2 s (268 clients made and destroyed), found no walk lacking a client the walks either side of it held and no child iterator invalid at the end of a walk (phantom_walks 0, invalid_at_end 0, of 7266 walks): a contradiction is a fault in a read, not churn. Falsified, each failing as named: a start or end walk dropping a client, or giving it another pid, and a phantom client in both snapshots (contradictions); the counter skipping another process's vanished client, or giving a figure across a gone one ("the registry vouches for ... but the counter gave Ok"); refusing a client that did not vanish, or naming another than the rule's; this process's time and every client's time each 1 ns off; the end snapshot misstating when it read; the rail under-read by 10%, and a figure's rail not the snapshots' advance; the sole-user gate at 1%; the span meter's figure, or its reason, not the counter's over its own snapshots; GPU work in an idle span; the CI grep's line renamed; and the classifier's stretch rule, fit rule, fall placement, the per-pid oracle, the refusal order and the hidden-time gate, each broken in turn. Two persistent faults end INCONCLUSIVE, as designed: (c) a 10% under-read of another process's client in every snapshot, "process-gpu INCONCLUSIVE: 1.5 s burn: no span in 92 s (12 spans) could be checked against the oracle: a counter reading out of the registry's order ×12; ...", and (d) a phantom client in every start snapshot, "... a vanished client the registry never listed ×12; ...". Co-Authored-By: Claude Opus 5.5 <[email protected]>The macOS browser e2e job failed its cowatch scenario five times with "cowatch: both play from Ada's control: not within 60000 ms (last: false)" (jobs 67776, 70090, 73183, 76976, 77089). It is the take-for-gone chain b01681570 records for watch-together, with the stall in Ada's own entering: `begin()` posted nothing for longer than the room's 4 s silence limit on the loaded host, the room took her for gone, and the old page, entering again, sent an event signed before its new join, refused `time_reversed`, and stopped. This branch's page recovers (b01681570, 4cc9a3e1b), but the scenario still failed: its check that the service carried every event the pages posted required the service to have refused nothing, and the service counts each `not_present` a page taken for gone gets before it enters again. On the build host under load, 8 of 11 runs of the branch head failed on exactly that check, with {"not_present":1} or {"not_present":2}, every page having entered again and played. The check now takes the design at work for what it is. The service's refusals must all be `not_present`, as many as the pages count themselves taken for gone (`gone`); each page must have entered again as often (`rejoins`, at most three), had no other event refused (`post_refused`), and not stopped. The pages' counts are read either side of the service's until the two readings agree. That check and the closing one print each page's gone, rejoins, resigned and dropped. Each control's instant is now read from the room's log, as the room carried it: a page that entered again signs its controls again, no earlier than its new join plus the lead, so the instant can be later than the one first signed. The waits for each control use it, and the play's line reports it, with the instant first signed when it moved. Before, a seek moved that way could pass its wait before it applied, and the position check after it then failed. The scenario does not hold a page on purpose: the watch-together example does that every run, and this scenario stays the room as people use it. Co-Authored-By: Claude Opus 5.5 <[email protected]>Step 4's burner child burned for at most 60 s, its wall time capped there whatever it was asked, while steps 4b and 4c now each take spans again for up to 90 s (`BUDGET`) where the old test allowed six quick tries. A long run of void spans could outlast the child; its exit then read as a corroborated vanish, the view was no longer shared, and the test failed with messages that look like a meter defect ("a shared GPU gave Ok(..)", "the child did not contend", "the child's client is not in the start snapshot") instead of INCONCLUSIVE. - The child burns for the seconds it is asked, of wall time, and step 4 asks for 2 × `BUDGET` + 60 s, longer than 4a, 4b and 4c can take between them; step 5 still kills it. - Right after 4b's and 4c's spans, the test fails `process-gpu INCONCLUSIVE: ... the contending child exited (<status>) while its spans were taken` if the child is gone. - The child is held in `Burning`, which kills and reaps it on drop: std's `Child` does neither, and a failed check would otherwise leave a GPU burner on the shared host for the rest of its life. A child whose parent is gone (killed outright, dropping nothing) stops burning too. Co-Authored-By: Claude Opus 5.5 <[email protected]>