Skip to content

W5b-14: timing.Ledger wired into the engine stages — one measurement per interval - #58

Merged
bnsd55 merged 4 commits into
mainfrom
w5b-timing
Sep 19, 2026
Merged

bnsd55 merged 4 commits into
mainfrom
w5b-timing

Conversation

@bnsd55

@bnsd55 bnsd55 commented Sep 19, 2026

Copy link
Copy Markdown
Owner

Per scratchpad/w5b-timing-ledger.md and the required-parameter design: ONE jevmlx.timing.Ledger per request, passed DOWN as a required parameter — no optional/dual path.

  • Spans: plan, prefill, cache_merge/ transformer/ gather (inside _score_rows, per chunk), rescore (field finalization + batch=1 rescores), reconciliation (constraint MAP), dependency (the selective second pass), assembly (batched per-context), group_wall (batched per group); the neutral prior pass is a prior-phase span.
  • ScoreRowsResult.gather_ms/broadcast_ms deleted; the internal t_gather_ms/t_broadcast_ms accumulators gone. A failed forward/gather records no interval (the ledger drops spans an exception unwinds through).
  • finalize_public_result derives EVERY *_ms key from Ledger.derived_flat() — same contract keys (suffix_eval_ms stays the documented composite), no accumulator fallback.
  • Batched (GAP A fix): ONE Ledger PER CONTEXT — each result's flat *_ms keys derive from its OWN ledger (own prefill span + own assembly spans + amortized share of the group's merged scoring pass); group_wall_ms/per_item_amortized_ms come from the per-group ledger; per_item_end_to_end_ms = the context's own prefill-span start → its assembly-span end (the note's definition; the shared prior_ms is reported separately, not added).
  • check_results/ARCHITECTURE/CHANGELOG updated; keys unchanged.

Tests: 7 new (ledger-derivation consistency, prior phase, dependency span, group-vs-amortized, per-item e2e, no dual fields). 697 fast passed; slow suite green except the pre-existing api.py '#count' KeyError — routed to PR #51 by the coordinator. Rebased over 4a656e6 (includes #54's prior-cache-key fix).

Review round 1 (77af115)

  • GAP B: Ledger.__exit__ with an exception unwinds ONLY to the failing span — ancestors stay open (a Metal retry under group_wall no longer drops the parents); nested spans are dropped.
  • F1 conflict marker resolved; F2 dual path + t0 deleted; F3 second_pass_ms = dependency span only; F6 _eval_cache_state unconditional; F7 R==0 branch spans fixed; F8 transformer span covers mx.eval(out); F9 leftovers deleted (PrefillResult.t_prefill_ms, stale docstrings, dead timers); F10 one top-level request span (elapsed_ms = true wall); F11 with everywhere except _score_rows retry paths; F12 module-top import, prior_pass name, cache-hit note; F13 body/code agree.
  • New tests: per-context prefill_ms differ; second_pass_ms == dependency span; forced Metal retry under group_wall; unpadded cache eval unconditional. 721 passed (slow suite green except the pre-existing api.py KeyError routed to PR W5-C: exact setcons solver, one count+set optimization, typed CalibrationBundle, internal telemetry, abstention contract #51).

Review round 3 (d1e9dd4, rebased on 5449b64)

  • N2 crash fixed: the R==0 branch shares the main loop's store path (no nested group_wall, no double pop); repro is a test.
  • N1 fixed: every batched result reports the shared prior_ms (derived_flat(prior_ms=...) override for per-context ledgers); total_ms includes it; test added.
  • REAL BUG found by round 2's failures: _SpanContext.exit compared identity against the context manager instead of the pushed _OpenSpan — every exc-info unwind no-op'd and leaked the span. _open now returns the _OpenSpan; exit pops by identity; ancestors still survive (GAP B).
  • F4: _amortize_group_spans deleted (no fabricated per-context intervals, no _intervals writes). ONE amortization rule: group spans on the group ledger; per-context flat keys carry the context's own spans; per_item_amortized_ms is the single derived share via Ledger.batched_views (N5, now used).
  • F13: per_item_end_to_end_ms = own prefill start -> own assembly end (note's definition); prior_ms reported separately; body amended.
  • F9: dead timers deleted (_selective_second_pass, _build_schema_rows).
  • F11: with-forms for prefill/rescore/reconciliation/dependency.
  • N4: failed_attempts passes through the batched ScoreRowsResult; retry test asserts >= 1; second_pass_ms test is an equality against the dependency interval.
  • Tests: 14 in test_w5b14_ledger.py. Gates: ruff clean, 733 passed (pre-existing api.py KeyError routed to W5-C: exact setcons solver, one count+set optimization, typed CalibrationBundle, internal telemetry, abstention contract #51).

…per interval

jevmlx/engine.py:
- ONE Ledger per request in run_parallel_generation and
  run_parallel_generation_batched; REQUIRED parameter on every stage that
  records a span (no optional/dual path): _prefill (prefill),
  _score_rows (cache_merge/transformer/gather),
  _rescore_rows_batch1 + _make_rescore_evidence_fn + _rescore_multi_options
  (rescore), score_scalar_field/score_multi_field/_score_all_fields,
  reconcile_case_constraints (reconciliation), run_dependency_waves ->
  _selective_second_pass (dependency), _assemble, finalize_public_result.
- The neutral prior pass runs in the ledger's 'prior' phase (prior_ms =
  that span; total_ms includes it).
- ScoreRowsResult.gather_ms/broadcast_ms DELETED — the ledger spans are
  the measurement of record; the internal t_gather_ms/t_broadcast_ms
  accumulators are gone. A failed forward/gather records NO interval
  (the ledger drops spans an exception unwinds through).
- finalize_public_result derives EVERY flat *_ms key from
  Ledger.derived_flat() — same keys, no accumulator fallback;
  second_pass_ms = the dependency span.
- Batched: group_wall span per group (prefill + one merged scoring pass +
  every assembly); per-context assembly spans;
  per_item_end_to_end_ms = the context's own prefill-span start -> its
  assembly-span end (honest per-context latency, no fabricated splits);
  prefill intervals tracked per context index.

benchmarks/check_results.py: TIMING_SPLIT_KEYS unchanged; provenance note
(ledger-derived). ARCHITECTURE.md: timing.py row (ADOPTED), result-dict
flow, timing-split contract row. CHANGELOG Unreleased.

Tests: tests/test_w5b14_ledger.py (7) — keys are ledger derivations
(total = prior + elapsed, suffix_eval >= lm_head), prior phase,
second_pass_ms = dependency span, group wall vs amortized, honest
per-item end-to-end, no dual fields on ScoreRowsResult. 697 fast passed;
slow suite green except the pre-existing api.py '<field>#count'
telemetry KeyError (routed to PR #51 by the coordinator).
Review (2026-09-19) blockers + gaps:
- GAP A/F4: ONE Ledger PER CONTEXT in decide_many — each result's flat
  *_ms keys derive from ITS OWN ledger (own prefill span, own assembly
  spans, amortized share of the group's merged scoring pass via
  _amortize_group_spans); group_wall + the merged pass spans live on a
  per-group ledger. prefill_ms is never the batch-wide sum.
- GAP B/F5: Ledger.__exit__ with an exception unwinds only to the FAILING
  span — ancestors stay open (a Metal retry under group_wall no longer
  drops the parents); spans nested INSIDE the failing span are dropped.
- F1: the unresolved merge conflict in _assemble's docstring resolved.
- F2: finalize_public_result dual path deleted (no t0, no else branch);
  every key comes from derived_flat.
- F3: second_pass_ms is the dependency span only (duplicated comment
  removed); no depends_on => no dependency span (contract 0.0).
- F6: _eval_cache_state(b_cache) unconditional again (unpadded merges
  evaluated; cache_merge spans the whole broadcast region).
- F7: batched R==0 branch wraps its assembly in a span and reads the
  group interval after the span closes, like the main loop.
- F8: the transformer span covers mx.eval(out) (real sync inside).
- F9: PrefillResult.t_prefill_ms deleted; stale docstrings fixed; dead
  perf_counter/t0 leftovers deleted; prior_ms from derived_flat.
- F10: ONE top-level request span per run_parallel_generation —
  elapsed_ms is true wall time (derived_flat prefers it).
- F11:  everywhere except _score_rows' retry
  paths (documented exception-drop semantics).
- F12: Ledger imported once at module top; prior span renamed
  prior_pass; cache-hit ~0 span noted in docs.
- F13: per_item_end_to_end_ms = own prefill span start -> own assembly
  span end + shared prior_ms (docs and code now agree; PR body amended).

Tests: 4 new (per-context prefill_ms differ, second_pass_ms == the
dependency span, forced Metal retry under group_wall survives, unpadded
cache eval unconditional) + ScoreRowsResult._fields check. 721 passed;
slow suite green except the pre-existing api.py KeyError (PR #51).
… leftovers

- N2 (crash): the batched R==0 branch no longer opens a nested group_wall
  and stores results[idx] like the main loop (one store path, one
  _per_item_end_to_end_ms write); repro added as a test.
- N1: prior_ms now exposed on every batched result — derived_flat takes an
  optional prior_ms override for ledgers with no prior span (the neutral
  pass runs once on the request ledger, finding 26); total_ms includes it;
  test added (two contexts, prior_correction=True, prior_ms > 0 on both).
- REAL BUG behind N2/round-2: _SpanContext.__exit__ checked identity
  against the wrong object — every exc-info unwind no-op'd and leaked the
  span (stack held _OpenSpan, self was the context). _open now returns the
  pushed _OpenSpan and __exit__ pops by identity against it; ancestors
  survive (GAP B semantics intact).
- F4: _amortize_group_spans DELETED (no fabricated per-context intervals,
  no _intervals writes) — group spans stay on the group ledger; the
  amortized share is the ONE derived number per_item_amortized_ms via
  Ledger.batched_views (N5, now used).
- F13: per_item_end_to_end_ms = own prefill start -> own assembly end
  (the note's definition); prior_ms reported separately; PR body updated.
- F9: dead timers deleted (_selective_second_pass t0/second_pass_ms,
  _build_schema_rows t_plan0/plan_compile_ms).
- F11: with-forms for prefill/rescore/reconciliation/dependency (the
  finally-form recorded failed attempts).
- N4: batched ScoreRowsResult passes failed_attempts through; retry test
  asserts >= 1. second_pass_ms test is now an equality against the
  dependency interval.
- Tests: 14 in test_w5b14_ledger.py (N2 repro, N1 shared prior added).
  Gates: ruff clean, 733 passed; pre-existing api.py KeyError (#51).
- Rebased onto origin/main 5449b64.
…onal param

- N6: group_wall_ms = merged scoring + assembly of the group (prefill is
  per context — the grouping loop needs prefill sizes before it can form
  groups); docstring + ARCHITECTURE rows updated. per_item_end_to_end_ms
  redefined as OWN prefill span + amortized group share + OWN assembly
  span (sum of intervals, not t1 - t0) — a context in group k never
  carries other groups' wall time; test added.
- N7: cache_merge/transformer/gather use with-forms (a failed attempt
  unwinds through the span and records no interval; the retry catches
  outside the with).
- N8: the Optional public ledger param removed from
  run_parallel_generation; the equality test reads the result keys.
- batched_views signature: n_items int (no [(i, None)] tuples); docstring
  no longer claims per_item_end_to_end; per-context e2e is assembled by
  the engine from the per-context ledgers.
- last_interval('assembly') at both e2e sites (no bare intervals[-1]).
- finalize_public_result docstring: the 'Without a ledger' clause deleted.
- Gates: ruff clean, 713 fast passed.
@bnsd55
bnsd55 merged commit 670909e into main Sep 19, 2026
2 checks passed
@bnsd55
bnsd55 deleted the w5b-timing branch September 19, 2026 07:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant