phase: 13_llm_page_and_decode_rate
All green. Final verification summary:
**Verified / implemented (phase 13 final pass)**
- All 4 tasks already in `complete/`; this was the verification pass. Confirmed the CSS rhythm rules (`#strip`, `#banners:empty ~ #fleet`) are served and pinned, `data/logs/NOTES-decode-spike.md` names the mechanism, and the phase-07/04 surfaces still pass their pins.
- **Found and fixed a residual defect in this phase's own code**: a stalled fetch stamps its body with the poll's *finish* time, so that sample anchors every window for the rest of the span; the jump gate "confirmed" a jump measured from that same anchor → live gufo rows 232.28 tok/s (one request at ~50) + a decaying 146/114/95 tail, repeated at 200.6. `rates.py::_publish` now requires an **independent anchor** (`_pending` stores the base sample's ts; the hold continues until it ages out). Pinned by `test_a_held_jump_is_not_confirmed_by_a_window_on_the_same_anchor` + `test_gufo_a_stale_scrape_body_never_becomes_a_rate_above_the_engine` (both fail on task 03's gate).
- Re-verified live after a dev-server restart: 10 min / 540 signed-in `/api/llm/snapshot` polls + read-only SQLite pass; **0 values > 300, 0 without a `Δ<window>` label**; 0 post-fix stored rows over the ceiling except the two pre-fix-shape rows above.
**Tests / lint (exact, all 100 % green)**
- `bash .agents/validate.sh` → **EXIT=0**; `uv run pytest --cov --cov-fail-under=94` → **1195 passed, 11 skipped, coverage 98.70 %**; `ruff check src tests agent` → All checks passed; `pyright` → 0 errors; `node --check` clean; repo hygiene clean.
- `uv run pytest -m live --live` → **11 passed / 0 failed**. `/api/health` → **all nine sources ok**.
**Completion criteria**
- Fleet/strip + head/fleet gap with screenshots (`llm-fleet-spacing{,-top,-banner-case}.png`) — met (CSS unchanged this pass, pinned on served bytes).
- Task-02 findings file names the confirmed mechanism — met.
- `test_rates.py`/`test_llm_source.py` pin label-set, both window bounds and the always-honest `Δ` — met (+2 new pins).
- Sustained watch under the recorded ceiling (300 tok/s) — met (worst 203.05, all labelled).
- Full suite + validate green; no phase-07/04 behaviour change — met.
**Documentation**
- README: `RATE_WINDOW_SECONDS` row now states the hold/confirm rule (only change needed; rest verified consistent).
- AGENTS.md: `rates.py` bullet + gap 9 rewritten (residual closed *and* the remaining sub-8× skew measured, root-caused to gap 4, explicitly not fixed by inventing a new threshold).
- **Fleet facts changed under this pass and were corrected**: operator added driveripper's bearer token → `host:driveripper`/`disks:driveripper` `ok`, live suite 9/2→11/0; but driveripper reads **identity only, zero SMART numbers** (root `smartctl` gives 55 °C/14 %; `/dev/nvme0`, `/dev/ng0n1`, `/dev/bsg/*` are root-only; its unit is `DevicePolicy=auto`, not the installer's `strict`). Evidence appended to `data/logs/NOTES-agent-install.md` + `NOTES-decode-stable.md`.
**Notable decisions / deviations**
- Did **not** add a span-relative window floor: that would re-decide task 03's pinned `MIN_WINDOW_SECONDS` and its "in-bounds diluted row publishes" test. Recorded as the next phase's call, with the root cause left at gap 4 / `14_store_performance` (the ~10 s stall).
- No live fleet change made (read-only probes + one dev-server restart). Fixtures deliberately not re-captured (no parse change, task 02 proved no shape drift). Dependency-currency advisory left untouched (no dependency moved in this phase): certifi/fastapi/starlette/websockets have newer releases.
**Next pending phase:** `.agents/phases/todo/14_store_performance` (then `15_agent_mtls`).
This commit is contained in:
@@ -52,6 +52,203 @@ def test_nan_and_inf_are_treated_as_missing() -> None:
|
||||
assert r.rate("x", bad, now=1.0) == (None, None)
|
||||
|
||||
|
||||
# --- phase 13: the live decode-tok/s spike ---------------------------------- #
|
||||
# Confirmed against the stored history and reproduced on live hardware; the findings are in
|
||||
# data/logs/NOTES-decode-spike.md. These two tests were written RED (as strict xfails) by
|
||||
# task 02 and turned GREEN by task 03's bounded window; the markers were removed and every
|
||||
# assertion kept verbatim, as the phase mandated. They are permanent pins now.
|
||||
#
|
||||
# The incident, from `sample` (source=llm, host=gufo, metric=llm.decode_tokens_per_second,
|
||||
# res=raw) on 2026-10-18, with the counter value reconstructed from the rows' own windows:
|
||||
#
|
||||
# 09:16:15.839 53.64 tok/s window ~10 s (steady work on deskwork: 53 tok/s)
|
||||
# ... 15.25 s with no sample at all: every source in the process gaps at the same instant ...
|
||||
# 09:16:31.091 7.47 tok/s window 15.25 s (114 tokens — a body generated ~2 s into it)
|
||||
# 09:16:31.308 3284.59 tok/s window 0.217 s (713 tokens — the rest of the stall)
|
||||
# 09:16:33.311 371.23 tok/s window 2.22 s (the stale sample is still base[0])
|
||||
# 09:16:35.315 222.32, 09:16:37.318 166.23, 09:16:39.316 138.37, then back to ~50
|
||||
#
|
||||
# 827 tokens across the whole 15.47 s is 53.5 tok/s — the engine's true rate. The tokens are
|
||||
# real; the window is the lie. `probe-decode-spike2.py` produced the same row pair (and nearly
|
||||
# the same tail: 379 / 232 / 174 / 140) against live gufo with the production parser.
|
||||
|
||||
GUFO_TOKENS = "llamacpp:tokens_predicted_total"
|
||||
|
||||
|
||||
def stalled_estimator(span: float = 10.0) -> RateEstimator:
|
||||
"""A window fed the steady 2 s cadence at exactly 50 tok/s."""
|
||||
r = RateEstimator(span=span)
|
||||
for i in range(6):
|
||||
r.rate(GUFO_TOKENS, 100.0 * i, now=1_000.0 + 2.0 * i)
|
||||
return r
|
||||
|
||||
|
||||
def test_a_catch_up_poll_after_a_stall_answers_na_not_a_spike() -> None:
|
||||
"""A fetch that takes 15 s and the loop's 0.2 s catch-up floor must not make a rate.
|
||||
|
||||
`poller.Job._loop` sleeps `max(0.2, interval - elapsed)`, so any poll slower than the
|
||||
interval is followed by a second one ~0.2 s later. Whatever the stalled fetch carried is
|
||||
then diffed over that 0.2 s.
|
||||
"""
|
||||
r = stalled_estimator() # steady 50 tok/s, last sample (1010.0, 500.0)
|
||||
# the stalled fetch: 15.25 s after the last sample, but its body was generated ~2 s in,
|
||||
# so it carries 114 tokens and gets stamped 13 s later than the engine measured them
|
||||
diluted, _window = r.rate(GUFO_TOKENS, 614.0, now=1_025.25)
|
||||
assert diluted == pytest.approx(7.47, abs=0.01) # the diluted row the DB actually holds
|
||||
# the catch-up: 0.22 s later, the current counter (713 tokens of stall still unaccounted)
|
||||
rate, window = r.rate(GUFO_TOKENS, 1_327.0, now=1_025.47)
|
||||
assert window == pytest.approx(0.22)
|
||||
assert rate is None, "a 0.22 s window is not a rate over the span; it must be n/a"
|
||||
|
||||
|
||||
def test_a_stalled_sample_does_not_inflate_the_polls_after_it() -> None:
|
||||
"""The tail is as wrong as the spike: base[0] is the stale sample for the next ~span."""
|
||||
r = stalled_estimator()
|
||||
r.rate(GUFO_TOKENS, 614.0, now=1_025.25)
|
||||
r.rate(GUFO_TOKENS, 1_327.0, now=1_025.47)
|
||||
# back to a normal 2 s cadence and the same honest 50 tok/s
|
||||
tail = [r.rate(GUFO_TOKENS, 1_327.0 + 100.0 * n, now=1_029.47 + 2.0 * (n - 1))[0]
|
||||
for n in range(1, 5)]
|
||||
assert all(v is None or v <= 60.0 for v in tail), f"inflated tail, real rate is 50: {tail}"
|
||||
|
||||
|
||||
# --- phase 13 task 03: both window bounds and the confirmed jump ------------- #
|
||||
|
||||
def test_window_below_the_floor_answers_na_with_its_honest_label() -> None:
|
||||
"""A 0.4 s catch-up gap is not a measurement over a 10 s span; it labels itself."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 100.0, now=0.0)
|
||||
rate, window = r.rate("x", 103.0, now=0.4)
|
||||
assert rate is None
|
||||
assert window == pytest.approx(0.4), "the n/a still names the window it refused"
|
||||
# the refused base was dropped: the next normal poll measures from the catch-up sample
|
||||
rate, window = r.rate("x", 203.0, now=4.4)
|
||||
assert rate == pytest.approx(25.0)
|
||||
assert window == pytest.approx(4.0)
|
||||
|
||||
|
||||
def test_fallback_base_older_than_two_spans_answers_na_and_recovers() -> None:
|
||||
"""A 20-second window on a 10-second panel is a different claim — one n/a, then normal."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 0.0, now=0.0)
|
||||
assert r.rate("x", 50.0, now=30.0) == (None, None)
|
||||
rate, window = r.rate("x", 100.0, now=32.0)
|
||||
assert rate == pytest.approx(25.0)
|
||||
assert window == pytest.approx(2.0), "the next poll re-bases on the fresh sample"
|
||||
|
||||
|
||||
def test_a_fallback_inside_the_documented_ceiling_still_publishes() -> None:
|
||||
"""The stall row the DB actually holds (15.25 s ≤ 2 x 10 s) keeps its diluted rate."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 0.0, now=0.0)
|
||||
rate, window = r.rate("x", 100.0, now=15.25)
|
||||
assert rate == pytest.approx(100.0 / 15.25)
|
||||
assert window == pytest.approx(15.25)
|
||||
|
||||
|
||||
def test_two_samples_at_the_same_instant_are_not_a_rate() -> None:
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 100.0, now=5.0)
|
||||
assert r.rate("x", 200.0, now=5.0) == (None, None)
|
||||
|
||||
|
||||
def test_a_jump_is_held_for_one_poll_and_publishes_when_confirmed() -> None:
|
||||
"""A real step-up survives one more interval and then prints — one poll late.
|
||||
|
||||
The confirming window is anchored on the sample 10 s back, which has moved on from the one
|
||||
the held jump was measured from — that is what makes it a second measurement. The other
|
||||
half is `test_a_held_jump_is_not_confirmed_by_a_window_on_the_same_anchor`.
|
||||
"""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 0.0, now=0.0)
|
||||
r.rate("x", 100.0, now=10.0) # 10 tok/s published
|
||||
rate, window = r.rate("x", 900.0, now=20.0) # 80 tok/s = 8x: held
|
||||
assert rate == pytest.approx(10.0)
|
||||
assert window == pytest.approx(10.0), "the held value keeps the Δ label it was published with"
|
||||
rate, window = r.rate("x", 1_720.0, now=30.0) # 82 tok/s: the step is real — publish
|
||||
assert rate == pytest.approx(82.0)
|
||||
assert window == pytest.approx(10.0)
|
||||
|
||||
|
||||
def test_an_unconfirmed_jump_is_dropped_and_the_held_value_keeps_printing() -> None:
|
||||
"""A one-interval artifact never publishes; the cell kept printing through it anyway."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 0.0, now=0.0)
|
||||
r.rate("x", 100.0, now=10.0) # 10 tok/s
|
||||
assert r.rate("x", 900.0, now=20.0)[0] == pytest.approx(10.0) # 80: held
|
||||
assert r.rate("x", 1_005.0, now=30.0)[0] == pytest.approx(10.0) # 10.5: artifact dropped
|
||||
rate, _ = r.rate("x", 1_105.0, now=40.0) # ordinary publishing resumes
|
||||
assert rate == pytest.approx(10.0)
|
||||
|
||||
|
||||
def test_a_held_jump_is_not_confirmed_by_a_window_on_the_same_anchor() -> None:
|
||||
"""A stalled fetch stamps its body late, and that body then anchors the whole span.
|
||||
|
||||
Measured on live gufo at 2026-10-19 12:42 (`data/logs/NOTES-decode-stable.md`'s window,
|
||||
one request running at ~50 tok/s): the process stalled 11 s, the first reply back carried
|
||||
the counter gufo had rendered ~2 s into it, and the estimator diffed the rest of the stall
|
||||
over a 3 s window — 232 tok/s — then re-diffed **the same delta** over 5, 7 and 9 s
|
||||
(146, 114, 95) because the stale sample stayed `inside[0]`. Measured twice from one sample
|
||||
is one measurement, so the confirmation gate requires a window anchored on a different
|
||||
sample; the hold simply continues until the stale anchor ages out of the span.
|
||||
"""
|
||||
r = RateEstimator(span=10.0)
|
||||
tokens = lambda t: 45.0 * t # noqa: E731 the engine: a steady 45 tok/s
|
||||
polls = [(0.0, tokens(0.0)),
|
||||
(11.0, tokens(2.2)), # the stalled reply: honest body, 9 s-old stamp
|
||||
(12.0, tokens(12.0)), # the catch-up: ≥8x the diluted row, so it is held
|
||||
(14.0, tokens(14.0)), # …and every poll still anchored on that stale sample
|
||||
(16.0, tokens(16.0)),
|
||||
(18.0, tokens(18.0)),
|
||||
(20.0, tokens(20.0)),
|
||||
(22.0, tokens(22.0)), # the anchor has aged out; one poll still denies the jump
|
||||
(24.0, tokens(24.0)),
|
||||
(26.0, tokens(26.0))]
|
||||
published = [r.rate("g", value, now=1_000.0 + t)[0] for t, value in polls]
|
||||
assert all(v is None or v <= 60.0 for v in published), \
|
||||
f"a 45 tok/s engine printed {max(v for v in published if v is not None):.0f}: {published}"
|
||||
assert published[-1] == pytest.approx(45.0), "the stall ends in the truth, not a tail"
|
||||
|
||||
|
||||
def test_a_rise_from_zero_is_never_held() -> None:
|
||||
"""The first work an idle engine does must print on its own poll, not one late."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 0.0, now=0.0)
|
||||
r.rate("x", 0.0, now=10.0) # 0 tok/s published
|
||||
assert r.rate("x", 500.0, now=20.0)[0] == pytest.approx(50.0)
|
||||
|
||||
|
||||
def test_confirmation_state_is_per_key() -> None:
|
||||
"""One key's pending jump must not hold another key's numbers."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("busy", 0.0, now=0.0)
|
||||
r.rate("busy", 100.0, now=10.0) # 10 tok/s — a jump base exists
|
||||
r.rate("idle", 5.0, now=0.0)
|
||||
r.rate("idle", 5.0, now=10.0) # 0 tok/s — previous is 0, nothing to confirm against
|
||||
assert r.rate("busy", 900.0, now=20.0)[0] == pytest.approx(10.0)
|
||||
assert r.rate("idle", 505.0, now=20.0)[0] == pytest.approx(50.0)
|
||||
|
||||
|
||||
def test_a_counter_restart_clears_the_confirmation_state() -> None:
|
||||
"""A restarted counter has no previous lineage to be judged against."""
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("x", 0.0, now=0.0)
|
||||
r.rate("x", 100.0, now=10.0) # 10 tok/s
|
||||
assert r.rate("x", 10.0, now=20.0) == (None, None) # restart drops the window
|
||||
rate, _ = r.rate("x", 910.0, now=30.0) # 90 tok/s on the new counter
|
||||
assert rate == pytest.approx(90.0)
|
||||
|
||||
|
||||
def test_forget_drops_the_judgement_state_with_the_window() -> None:
|
||||
r = RateEstimator(span=10)
|
||||
r.rate("host:x", 0.0, now=0.0)
|
||||
r.rate("host:x", 100.0, now=10.0)
|
||||
r.rate("host:x", 900.0, now=20.0) # held: one pending jump, one published rate
|
||||
assert r._published and r._pending
|
||||
assert r.forget("host:") == 1
|
||||
assert r._published == {} and r._pending == {}
|
||||
|
||||
|
||||
def test_counter_reset_yields_none_once_then_recovers() -> None:
|
||||
"""A restart must not report a huge negative — or, worse, a huge positive — rate."""
|
||||
r = RateEstimator(span=60)
|
||||
|
||||
Reference in New Issue
Block a user