From c1db188e6a5b17dbd3a9bf64e7ec15e3471c8ceb Mon Sep 17 00:00:00 2001 From: Vuong Hoang Date: Tue, 25 Aug 2026 20:30:29 -0700 Subject: [PATCH] =?UTF-8?q?docs(training-playbook):=20=C2=A74.3=20records?= =?UTF-8?q?=20an=20OBSERVED=20consequence,=20not=20just=20a=20config=20str?= =?UTF-8?q?ing?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit brokkr-smithy-dev pointed §4.5's own test at §4.3's remedy: recording `attn_implementation_resolved` is a check that cannot fail on the axis the failure lives on. A silent Dynamo fallback to uncompiled flex leaves `config._attn_implementation == "flex_attention"` untouched while the run computes at ~20x the cost and, per torch's own docs, does not work correctly through the backward pass. The field records the request's RESOLUTION, not its SURVIVAL. On the failure mode that matters it reports success either way. So the section now requires the step-time distribution beside it -- n, min, p50, p99, max -- which is the check that can actually fail. Compiled sits at p50 ~20 s; a fallback at ~400 s. One perf_counter() in on_step_end buys it. Distribution rather than a mean, because a mean hides exactly the bimodality a PARTIAL fallback produces. Generalised past this instance: any provenance field recording a CONFIGURED value is a claim about intent. If the failure you fear is the configuration silently not taking effect, you need a second field recording an OBSERVED consequence, and the pairing is the check. A settings dump alone is decorative. Two implementation details are called out because both were wrong in the first draft -- percentiles nearest-rank so every reported value is a real observation, and exclude the FIRST step rather than the slowest, since step 1 carries compilation but is not reliably the maximum on a variable-width run. New §4.7.1: rotate the log on relaunch. Run 2's first attempt died on the warmup_ratio TypeError and the relaunch appended, so the traceback sat at line 15 of a file whose live run began at line 39 -- and a `tail -n +1 -F` monitor replayed the dead traceback as a fresh event. One file describes one run. Checklist gains both lines. --- docs/pfi/training-throughput-playbook.md | 81 ++++++++++++++++++++++-- 1 file changed, 77 insertions(+), 4 deletions(-) diff --git a/docs/pfi/training-throughput-playbook.md b/docs/pfi/training-throughput-playbook.md index 9ed0bfa..dfd19d2 100644 --- a/docs/pfi/training-throughput-playbook.md +++ b/docs/pfi/training-throughput-playbook.md @@ -629,10 +629,53 @@ availability, and only that one describes the run. A framework that silently downgrades an unavailable backend will make them differ, and that difference is exactly what you want on the record. -The dynamo counters matter for the same reason: dynamo's fallback to -**uncompiled** flex is silent, roughly 20× slower, and documented not to work -correctly through the backward pass. The counters are the only in-band evidence -it did not happen. +#### ⚠⚠ The resolved field is itself an inert gate on the axis that matters + +Recording `_attn_implementation` is necessary and **not sufficient**, and the +reason is §4.5 pointed at this section's own remedy. + +Dynamo's fallback to **uncompiled** flex leaves +`config._attn_implementation == "flex_attention"` sitting there untouched while +the run computes at roughly 20× the cost — and the uncompiled path is documented +not to work correctly through the backward pass. **The field records the +request's resolution, not its survival.** On the failure mode you actually care +about, it reports success either way. + +So record the **step-time distribution** beside it. It is the check that can +fail: + +```python +"attn_implementation_resolved": model.config._attn_implementation, # what it SAYS +"step_seconds": step_time_summary(step_timer.durations), # what it DID +"dynamo_counters": _dynamo_counters(), # best-effort +``` + +``` +n=1312 min=11.84 p50=19.48 p99=28.96 max=45.79 seconds_per_optimizer_step +``` + +A compiled run and a fallen-back run are not close: p50 ~20 s against p50 ~400 s. +One `perf_counter()` in `on_step_end` buys it. Record the **distribution**, not a +mean — a mean hides exactly the bimodality a *partial* fallback produces. + +Two details worth getting right, because both were wrong in the first draft: + +- **Percentiles nearest-rank, no interpolation.** Every reported value is then a + real observation rather than a number no step ever took. +- **Exclude the FIRST step, not the slowest.** Step 1 carries compilation, but on + a variable-width run it is not reliably the maximum — an ordinary long batch + can beat it. Dropping `sorted(durations)[-1]` silently reports a different + statistic than the key is named after. + +⚠ **Generalise the shape, not just this instance.** Any provenance field that +records a *configured* value is a claim about intent. If the failure you fear is +the configuration silently not taking effect, you need a second field recording +an *observed* consequence — and the pairing is the check. A settings dump alone +is decorative. + +The dynamo counters are the third leg: cheap, in-band, and they name the +recompile activity directly. Keep them best-effort and nullable — a missing +counter table is not worth failing a seven-hour run over at save time. **When the run is already going and the field is missing** — as ours was — you can often still answer it, but only forensically. For us: @@ -774,6 +817,33 @@ the same motion that was supposed to retire it.** 2026-08-26" — over a bare figure. A dated claim invites a re-check; a bare one reads as timeless. +#### ⚠ 4.7.1 Rotate the log on relaunch, or it becomes a liar by accumulation + +Same family, different artifact. Our launcher appended (`>> run-02.log`), so +when the first attempt died on the `warmup_ratio` TypeError and we relaunched, +**the traceback stayed at line 15 of a file whose live run started at line 39.** + + $ grep -c Traceback run-02.log + 1 # ...from a run that no longer exists + +Anyone grepping that file for a failure signature gets a hit that predates the +run, and nothing in the file says so. A log-scraping monitor gets it too — ours +replayed the dead traceback as a fresh event on re-arm, because `tail -n +1 -F` +starts at line 1. + +```bash +# rotate, don't append +if [ -s "$LOG" ]; then + mv "$LOG" "${LOG%.log}.$(date -u +%Y%m%dT%H%M%SZ).log" +fi +``` + +Keep the rotated copies — the crashed attempt's log is evidence. The point is +that **one file describes one run.** The general rule: an artifact that +accumulates across state changes needs either rotation or an in-band marker +saying where the current state begins; without one, every reader has to know the +history to interpret it, and none of them do. + ### 4.8 The pre-launch honesty checklist Ten minutes, before the window opens. Every item is something that produced a @@ -786,6 +856,9 @@ completed, plausible, wrong run above. [ ] kwargs checked by NAME against the installed library signature [ ] config validated before tokenizer, encode and model load [ ] provenance records RESOLVED backend, library versions, aux-file shas +[ ] AND an observed consequence step-time distribution beside the config + string -- a settings dump alone is decorative +[ ] log rotates on relaunch one file describes one run [ ] present-and-null, not absent a run that claims nothing must say so explicitly [ ] watchdog tested negative kill something and confirm it fires [ ] stale numbers grepped for the figure, repo-wide, not just in view