pgw#989: the dynamo mint's warmup_forward hour gets a breakdown, and inductor_compile: 0.0 stops lying

changelog.d/pgw989.md

@@ -0,0 +1,23 @@
+- **pgw#989: a dynamo mint's hour gets a breakdown, and the row that never
+  measured a compile stops claiming to.** Every published JIT cell reported the
+  same shape — sdxl w8a8-lora64 on an L40S, 2026-08-06: `{'load': 13.87,
+  '**warmup_forward': 4416.91**, '**inductor_compile': 0.0**, 'seal_publish':
+  96.81, 'finalize': 0.16}`. 97.6 % of the mint under one name, beside a zero
+  named after the work. Not a broken clock: `mint_child` framed
+  `_drain_router` as `inductor_compile`, and a fleet mint arms COLD with no
+  router (gw#587), so that phase measured an empty queue while every compile
+  ran INLINE inside the warm forwards. The drain is now `router_drain`, which
+  is what it is.
+- The warm plan now carries its own ledger (`gen_worker.warm_spans`): per warm
+  job and in total, `warm_compile_s` vs `warm_execute_s` — with the inductor
+  partition inside the compile half and an explicit `compile_other_s` residual,
+  so a newly-introduced phase shows up as the residual growing rather than as
+  time silently vanishing (pgw#830's rule, applied to the JIT path). The parent
+  re-emits it as `jit_compile` rows `warm:totals` / `warm:<member>` /
+  `warm_job:<name>`, so an AOT-vs-JIT comparison stays one grouped query.
+- The key set is the JIT one and that difference is the point: MEASURED on the
+  pin, the AOT partition prices a `torch.compile` call at **1.10 s of 5.05 s
+  (22 %)** because `AotCodeCompiler.compile` never runs on this path.
+  `_compile.compile_inner` is the JIT total, and `PyCodeCache.load_by_key_path`
+  (63 %) is where the time actually is. `MintReport.mint_phases`, documented as
+  "empty for the dynamo recipe", now carries this.

src/gen_worker/activity.py

@@ -42,6 +42,7 @@
 import psutil
 
 from . import progress as progress_mod
+from . import warm_spans
 from .pb import worker_scheduler_pb2 as pb
 
 logger = logging.getLogger(__name__)
@@ -119,6 +120,11 @@
 PHASE_LOAD = "load"
 PHASE_TRACE_GRAPH = "trace_graph"
 PHASE_INDUCTOR_COMPILE = "inductor_compile"
+# pgw#989: the dynamo mint used to report its router drain under
+# PHASE_INDUCTOR_COMPILE, next to a `warmup_forward` row holding every compile
+# it ever ran. Re-exported (defined in `warm_spans`, which the mint child can
+# import without protobuf) so the vocabulary is enumerable from one module.
+PHASE_ROUTER_DRAIN = warm_spans.PHASE_ROUTER_DRAIN
 PHASE_WARMUP_FORWARD = "warmup_forward"
 PHASE_SEAL_PUBLISH = "seal_publish"
 # gw#612: post-proof tail — sibling-lane resolution, publish decision,

src/gen_worker/mint_child.py

@@ -69,7 +69,7 @@
 
 import msgspec
 
-from . import worker_goals
+from . import warm_spans, worker_goals
 from .config import load_settings
 from .mint_process import (
     EXIT_BAD_REQUEST,
@@ -460,9 +460,16 @@ async def _drain() -> None:
 def _drive_warm_plan(
     instance: Any, jobs: Sequence[Any], request: MintRequest, *,
     proof_only: bool = False,
-) -> None:
+) -> warm_spans.WarmLedger:
     """Run the endpoint's OWN warm plan, framed as ``warmup_forward``.
 
+    Returns the plan's own cost ledger (pgw#989). On the dynamo recipe these
+    forwards ARE the compile, so ``warmup_forward`` is 97.6 % of the mint under
+    a single name — measured beside an ``inductor_compile`` row reading 0.0 s.
+    The ledger splits it into compile and forward per job. It is measured on
+    the AOT recipe's proof forward too: that job costs real seconds and an
+    unmeasured cost is how this one hid.
+
     ``proof_only`` runs ONE job (pgw#984, the AOT recipe); otherwise the whole
     plan runs (the dynamo recipe, where these forwards ARE the compile).
 
@@ -475,15 +482,18 @@ def _drive_warm_plan(
     ``(phase=warmup_forward, deterministic)`` while the worker was still
     calling it ``crashed`` and buying the second pod.
     """
+    ledger = warm_spans.WarmLedger()
     total = 1 if proof_only else len(jobs)
     frame(phase="warmup_forward", step=0, total=total)
     for index, job in enumerate(jobs[:total], start=1):
         frame(phase="warmup_forward", step=index, total=total,
               note=job.spec.name)
         try:
-            _run_warm_job(
-                instance, job, dict(request.configs.get(job.spec.name) or {}),
-                request.execution_lane, origin=mint_identity(request))
+            with ledger.job(job.spec.name):
+                _run_warm_job(
+                    instance, job,
+                    dict(request.configs.get(job.spec.name) or {}),
+                    request.execution_lane, origin=mint_identity(request))
         except BaseException as exc:
             if _is_resource_error(exc) or not isinstance(exc, Exception):
                 raise
@@ -492,6 +502,7 @@ def _drive_warm_plan(
                 f"not run — warm job {job.spec.name!r} raised "
                 f"{type(exc).__name__}: {exc}. A cell must not seal for a "
                 f"handler that cannot serve.") from exc
+    return ledger
 
 
 def _drain_router(pipe: Any, *, poll_s: float = 0.5) -> None:
@@ -514,7 +525,7 @@ def _drain_router(pipe: Any, *, poll_s: float = 0.5) -> None:
         _warm, pending, _failed = router.stats()
         if pending == 0:
             return
-        frame(phase="inductor_compile", note=f"{pending} compile(s) queued")
+        frame(phase=warm_spans.PHASE_ROUTER_DRAIN, note=f"{pending} compile(s) queued")
         time.sleep(poll_s)
 
 
@@ -865,8 +876,9 @@ def _load(_execution_lane: str) -> Tuple[Any, Any, Any]:
         raise MintChildRefused(f"{mint_identity(request)}: {exc}") from exc
     miss_before = cc.cache_miss_count(pipe)
 
-    _drive_warm_plan(instance, jobs, request)
-    frame(phase="inductor_compile", note="draining any queued compiles")
+    ledger = _drive_warm_plan(instance, jobs, request)
+    frame(phase=warm_spans.PHASE_ROUTER_DRAIN,
+          note="draining any queued compiles")
     _drain_router(pipe)
 
     if cc.execution_count(pipe) <= 0:
@@ -898,6 +910,10 @@ def _load(_execution_lane: str) -> Tuple[Any, Any, Any]:
         peak_vram_bytes=peak,
         elapsed_s=time.monotonic() - started,
         phases=_close_phases(),
+        # pgw#989: the dynamo recipe's `mint_phases` was documented as "empty —
+        # no per-graph-class breakdown". It has one; it was just never
+        # measured. The parent re-emits this exactly as it does the AOT table.
+        mint_phases=ledger.table(),
     )
 
 

src/gen_worker/mint_delegate.py

@@ -34,14 +34,14 @@
 import tempfile
 from dataclasses import dataclass, field
 from pathlib import Path
-from typing import Any, Dict, Optional, Tuple
+from typing import Any, Dict, Mapping, Optional, Tuple
 
 from . import activity as activity_mod
 from . import aot_resume
 from . import mint_budget
 from . import mint_process
 from . import progress as progress_mod
-from .mint_process import MintOutcome, MintRequest
+from .mint_process import MintOutcome, MintReport, MintRequest
 
 logger = logging.getLogger(__name__)
 
@@ -492,10 +492,16 @@ def _emit_jit_compile(
     """th#1322: one delegated JIT mint's duration, as typed NUMERIC events.
 
     This is the fleet's real JIT compile path — the child arms COLD and drives
-    the endpoint's own warm plan (gw#587), so its `warmup_forward` +
-    `inductor_compile` spans ARE "how long does JIT take". Before this the
-    number lived only in the child's stdout, and a serve pod exposes no logs
-    (pgw#760), so it was unrecoverable the moment the pod went away.
+    the endpoint's own warm plan (gw#587), so its `warmup_forward` span IS
+    "how long does JIT take". Before this the number lived only in the child's
+    stdout, and a serve pod exposes no logs (pgw#760), so it was unrecoverable
+    the moment the pod went away.
+
+    pgw#989: that span is also 97.6 % of the mint, so "how long" was as far as
+    it went. ``report.mint_phases`` now carries the warm plan's own ledger
+    (:class:`gen_worker.warm_spans.WarmLedger`) and it is emitted here under
+    `phase=warm:<name>` / `phase=warm_job:<name>` — compile vs forward, and the
+    inductor partition inside the compile half.
 
     Shape matches ``aot_mint_phases`` exactly: `phase=minted` carries the total,
     `phase=child:<phase>` the spans inside it. A mint that did NOT produce a
@@ -520,6 +526,7 @@ def _emit_jit_compile(
                 phase=f"child:{name}",
                 duration_ms=int(round(value * 1000)),
             )
+        _emit_warm_ledger(report, head=head)
         # The child's own elapsed is authoritative when it wrote a report; the
         # parent's wall clock covers a child that died before writing one (spawn
         # + run, which is the honest cost of that attempt).
@@ -541,6 +548,61 @@ def _emit_jit_compile(
                      exc_info=True)
 
 
+def _emit_warm_ledger(report: Optional[MintReport], *, head: str) -> None:
+    """pgw#989: the warm plan's compile-vs-forward split, as numeric events.
+
+    Three row shapes, all under ``jit_compile`` so one grouped query still
+    covers a JIT mint:
+
+    * ``warm:totals`` — the roll-up, carrying ``warm_compile_s`` in
+      ``duration_ms``. The one number that says whether a slow mint is a slow
+      COMPILE.
+    * ``warm:<member>`` — the inductor partition inside the compile half.
+    * ``warm_job:<name>`` — one warm forward. A plan whose jobs mostly compile
+      nothing is paying full forward cost for coverage it already has; that is
+      a different defect from a slow compile, and only the per-job rows can
+      tell them apart.
+
+    Silent when the recipe produced no ledger (the AOT path, or a child that
+    died before the warm loop) — an absent measurement is reported as absence.
+    """
+    table = dict(getattr(report, "mint_phases", None) or {}) \
+        if report is not None else {}
+    totals = dict(table.get("totals") or {})
+    if not totals.get("warm_wall_s"):
+        return
+    overlays = dict(table.get("overlays") or {})
+    activity_mod.emit_event(
+        activity_mod.KIND_JIT_COMPILE,
+        f"{head} warm_totals={totals} overlays={overlays}",
+        phase="warm:totals",
+        duration_ms=int(round(float(totals.get("warm_compile_s") or 0.0) * 1000)),
+    )
+    for name, seconds in sorted(dict(table.get("phases") or {}).items()):
+        value = float(seconds or 0.0)
+        if value <= 0:
+            continue
+        activity_mod.emit_event(
+            activity_mod.KIND_JIT_COMPILE,
+            f"{head} warm_phase={name} seconds={round(value, 2)}",
+            phase=f"warm:{name}",
+            duration_ms=int(round(value * 1000)),
+        )
+    for row in table.get("jobs") or ():
+        if not isinstance(row, Mapping):
+            continue
+        wall = float(row.get("wall_s") or 0.0)
+        if wall <= 0:
+            continue
+        activity_mod.emit_event(
+            activity_mod.KIND_JIT_COMPILE,
+            f"{head} warm_job={row.get('job')} wall_s={round(wall, 2)} "
+            f"compile_s={row.get('compile_s')} execute_s={row.get('execute_s')}",
+            phase=f"warm_job:{row.get('job')}",
+            duration_ms=int(round(wall * 1000)),
+        )
+
+
 def _emit_abort(
     outcome: MintOutcome, family: str, key: str, attempt: int,
 ) -> None: