Repository navigation
feature: per-phase timing and cache skip stats in get_job / job events #867
Copy link
Copy link
Closed
2 / 22 of 2 issues completedClosed
2 / 22 of 2 issues completed
Copy link
Labels
featureWork bigger than a fix: designed with Don, built in stages (harnest R11)Work bigger than a fix: designed with Don, built in stages (harnest R11)owner:testerTester's turn to actTester's turn to actperformanceTiming/perf regression flagged by the regression agentTiming/perf regression flagged by the regression agentstatus:plan-approvedDon approved the feature plan (Don only)Don approved the feature plan (Don only)status:verifiedTester confirmed the fix via a real MCP callTester confirmed the fix via a real MCP calltarget:mini-aiFound against a non-lem server (DW_TARGET=mini-ai); Don triagesFound against a non-lem server (DW_TARGET=mini-ai); Don triagesverified-on:mps
Description
Problem
To answer "where does the time go and did the cache do anything", the matrix had to write tools/phases.py, which reconstructs load / encode / denoise / decode minutes and seconds-per-pass by walking /api/jobs/<id>/event-log. And there is no way to see whether a cache skipped anything:
- P2 (
first_block0.05 at 12 steps) took exactly as long as its baseline - the only evidence it skipped nothing was s/pass (56.3 vs 55.8). The event log hasquantized_cachehit/miss events for weights, but nothing for the step cache. - P1 (
first_blockat 30 steps) averaged 42.2 s/pass vs 55.8 - inferred ~25% skipped, never reported. - Yet P2's output differed from B3 (PSNR 25.6 dB, where a plain rerun P4 was 44 dB), so the hook changes numerics even when it saves nothing - only visible by diffing outputs.
Proposal
get_job(and the MCPget_job) returns atimingblock per generation step:load_s,encode_s,denoise_s,passes,s_per_pass(first and rest - the first pass carries compile/autotune),decode_s,save_s.- A
cache_statsevent at the end of denoise: cache type, threshold, per-block or per-step computed vs skipped counts (diffusers' hooks hold this state; read it before reset). Surface astiming.cache = {type, skipped_passes_equiv, hit_rate}. - Same for compile:
compile_son the first pass.
This also gives the plan estimator (separate issue) clean inputs.
Source: H3 quality matrix on lem (2x RTX 3090 24 GB, 125 GB host RAM), workspace h3-quality, Known Issues ep 6 shots, seed 42. Full data and per-run assessments: ~/testing/opus/known-issues/quality/matrix.json, report quality/REPORT.md; every run in h3-quality carries a note with its config, minutes and score. Related: #861 (follow-up experiments).
Reactions are currently unavailable
Metadata
Metadata
Assignees
Labels
featureWork bigger than a fix: designed with Don, built in stages (harnest R11)Work bigger than a fix: designed with Don, built in stages (harnest R11)owner:testerTester's turn to actTester's turn to actperformanceTiming/perf regression flagged by the regression agentTiming/perf regression flagged by the regression agentstatus:plan-approvedDon approved the feature plan (Don only)Don approved the feature plan (Don only)status:verifiedTester confirmed the fix via a real MCP callTester confirmed the fix via a real MCP calltarget:mini-aiFound against a non-lem server (DW_TARGET=mini-ai); Don triagesFound against a non-lem server (DW_TARGET=mini-ai); Don triagesverified-on:mps
Activity
dkackman commentedon Oct 14, 2026
Plan v2: per-step timing and step-cache skip counts in
get_jobLead: claude-opus-5-5 (anthropic). Design session checked against
develop@ 61838a9; v2 written in the decompose session againstdevelop@ f8fda59. v2 adopts Don's review (manifest-entry carrier, real-pipeline cache-context test) and records his answers to Q1–Q4.Verdict: build smaller
h3-quality, 63 jobs, Don's workspace) needed a reconstruction script to get phase minutes and s/pass. Whether P2's cache skipped anything was inferred from s/pass. #875 (first_block threshold sweep, MagCache) asks "how many passes did it skip, at what quality"; #866 (the estimator is off by up to 12x) wants measuredload + passes × s/pass + decodeinputs. Related closed class: #262 and #95 (phase durations argued from event diffs), #357 (phases misread).$3–5 = **$6–10** (v1: $7–11; the manifest carrier drops the history column and theJobfold).timingkey on eachManifestEntry(alreadyextra="allow", already returned byget_job, stored in history and written to the run'smanifest.json), declaredsometimes(...). One new event type,cache_stats. A regenerated OpenAPI contract. About 30–50 tokens of MCP description against a surface budget with 0.5 tokens of headroom (tests/test_mcp_server.py:1594), so the budget is raised with a dated comment. A coupling to private diffusers hook state (FBCSharedBlockState.should_compute,MagCacheState), which a diffusers upgrade can move. No security boundary moves. No new workflow syntax.timingis additive andsometimes(...)(absent on runs before it, on reused steps, on steps with no entry of their own), so dropping a sub-field later is a doc change, not abreaking-change. Nothing in workflow JSON names it.phases.py. Can't answer the cache question (no hook counts skips) and loses load/encode on long jobs (200-event history tail). (b) Onlycache_stats. Answers #875, not #866. (c) Wall-clock from server eventat. Too coarse for s/pass, and the 200-event trim still applies.dw/plan.pyorobserved_cost.py. #868 would citehit_ratebut needs nothing from here. #865 is independent. #875's carved fix (MagCache calibration ratios) edits the samestateful_cache_context(components.py:833-864) as stage 2: whichever lands second rebases onto the other; not a blocker.Cut from the proposal, and what would bring each back:
compile_sas its own field. Compile is lazy and lands inside the first denoise forward; nothing in dw can separate it. Insteadfirst_pass_sandpass_s(median of the rest) withcompiled: true|false; the docs say compile ≈first_pass_s − pass_son a cold run. Brought back by: a diffusers/torch hook that reports compile time directly.skipped_passes_equiv. Same number asskippedin other units.taylorseer,faster,text_kv. Their hooks keep no decision state. They report type and config with null counts (Don, Q3). Brought back by: a matrix run that needs them; for taylorseer, wrapping_measure_should_compute.Problem
Two questions have no answer from dw today: where did a generation step's time go, and did the step cache skip anything. The first is reconstructable from events only by a script, and only while the 200-event history tail still holds load and encode. The second is not reconstructable at all: diffusers' cache hooks keep only the latest decision.
Non-goals: pricing from measured timings (#866), per-block cache stats, timing for utility-task steps beyond
save_s, UI display, timing on the SSE stream beyond the existing events, timing onwait_for_job's slim reply (Don, Q1).What the sweep found (corrections to the proposal)
PHASESisloading, cached, generating, decoding, saving, task(dw/events.py:219).generatingfires beforeself.pipeline(...)(pipeline.py:635), so "generating → firstpipeline_step" is encode plus the first pass, plus compile. The docs call that interval "encode" (docs/SERVER.md:210,docs/MCP.md:403), wrong whenever pass 1 is long. A realencode_sneeds a denoise-start mark: the first denoiser forward (a pre-forward hook) for callback pipelines; for modular pipelines (H3, LTX-2, Qwen-Image) the opening of the denoise block's tqdm bar, whichreported_progress_barsalready patches (progress.py:88-130).first_block_cache.py:51-62keeps onlyshould_compute;mag_cache.py:140-168resetsaccumulated_stepson every compute. dw counts them itself, per forward, not per step (CFG runs more than one forward per step), read beforestateful_cache_context'sfinallycalls_reset_stateful_cache()(components.py:833-864).job_record.py:53). Timing is measured in the worker with a monotonic clock and recorded on the step's manifest entry.ManifestEntryis open (extra="allow") but undeclared keys are undocumented.timingis declaredsometimes(StepTiming)on it (api_models.py:381), and the OpenAPI contract regenerated (scripts/dump_openapi.py, thennpm run gen:api;tests/test_api_contract.py:141and CI fail on drift).JobDetailis unchanged.record_step(workflow_run.py:886) withstep,reusedand, for rolled-up child entries,parent_step; extra keys reachmanifest.jsonunchanged (write_run_manifest,workflow_run.py:217). A chain (chain.py:460,525) restarts the denoise counter per segment.The design
timingon each manifest entry (RESTGET /api/jobs/{id}manifest[], MCPget_job, runmanifest.json)A pipeline step's manifest entry gains
timing:{"step": "shot", "files": ["..."], "subfolder": "final", "timing": {"load_s": 41.8, "load_cached": false, "encode_s": 54.2, "denoise_s": 1689.0, "passes": 30, "first_pass_s": 61.0, "pass_s": 56.1, "compiled": false, "decode_s": 52.7, "save_s": 9.4, "segments": 1, "cache": {"type": "first_block", "threshold": 0.05, "forwards": 60, "computed": 44, "skipped": 16, "hit_rate": 0.267}}}_svalues are worker monotonic seconds, rounded to 0.1.load_sis the step's component load.load_cached: truemarks a pipeline served from the worker's model cache: itsload_sis the lookup, not a load.encode_s: pipeline call → first denoiser forward (or the modular denoise bar opening).denoise_s: from there to the last step.decode_s: last step → pipeline return.save_s: the result save, which already times itself (result.py:444-493).pass_sis the median of passes 2..n; null whenpasses < 2.timingper chain step: segment times summed,passessummed,segments: N,pass_sthe median over every non-first pass in every segment.null, never guessed. A pipeline with neither a step callback nor a tqdm bar hasdenoise_sbut nullencode_s,passes,pass_s.reused: true; it gets notimingkey (nothing ran).parent_saves_this, A sub-workflow step saves its output twice and the manifest carries two entries under the child's step name, so a composed run doubles storage and shadows a step key #92) has no entry of its own, so no timing. Accepted cost of the carrier (Don's review). A utility-task step's entry never carries pipeline fields (at mostsave_s).cacheis present only when the step set acache(stage 2). Fortaylorseer,faster,text_kv:{type, threshold: null, forwards: null, computed: null, skipped: null, hit_rate: null}plus their config keys (cache_intervaland so on).manifest.json, sotimingsurvives the 200-event trim, a server restart, andexport_job, and can be compared across runs offline. No history column, no migration.cache_statseventEmitted once per pipeline call, at the end of denoise and before the cache context resets. Carries the same object as
timing.cache, plusstep.get_job_events(kinds=["cache_stats"])returns it. It's for watching a run live; the manifest entry is the record.Where it's built
StepTimer(new,dw/pipeline_processors/timing.py) opened by the pipeline processor around load → call → save, fed by the existing marks (emit_phase,on_step_end,on_advance) plus one self-removing denoiser pre-forward hook. The finished dict reachesrecord_step'sdetails, so it lands on both the manifest entry andstep_end.get_cache_transformer,components.py:812). After each forward it reads the leader hook's shared state (fbc_leader_block_hook,mag_cache_leader_block_hookviastate_manager.get_state()) and counts computed or skipped. Registered insidestateful_cache_context, removed in itsfinallyafter emittingcache_stats. Missing private attribute → countsnullplus onewarning(kind: "cache_stats_unavailable"); never fails the run. Cache-context caveat (Don's review): diffusers pipelines open their owncache_context("cond")/("uncond")inside dw'sstateful_cache_context(components.py:834); a read after the forward has left that inner context sees the wrong or default state. The counter must read inside the right context (or per context name), and the first stage-2 test runs a tiny real pipeline with CFG and assertscomputed + skipped == forwards; a fake-leader-state test can't catch this.ManifestEntry.timing: sometimes(StepTiming)(withStepTimingandStepCacheStatsmodels, open like the entry), OpenAPI regen.Job,JobDetailandjob_historyare untouched.get_jobdescription gets one sentence: each manifest entry may carrytiming, seeget_guide("server", section=...)for the fields.get_job_eventsnamescache_statsamong its kinds (stage 2).wait_for_jobdoes not carry it (Q1). The surface budget is raised by the measured delta, with a dated comment.Surfaces touched
timingonManifestEntry.get_jobandget_job_events, plus a budget raise.+cache_stats,+warning kind cache_stats_unavailable.manifest.jsonstep entries gaintiming.Stages
Stage 1: per-step
timingon manifest entries (no cache counts)StepTimer, the denoise-start mark for callback and modular pipelines,timinginrecord_step's details (manifest entry +step_end), chain summing,ManifestEntry.timing+ models, OpenAPI regen, the MCPget_jobsentence and budget.cacheis absent in this stage.StepTimerwith a fake clock: marks in order, a missing mark → null,pass_smedian, passes < 2, chain sum.record_step: a timed step's entry carriestiming; a reused step's entry hasreused: trueand notiming.ManifestEntrystrict-mode serialization withtiming; a pre-feature manifest (notiming) still serializes.docs/SERVER.md: atimingfield table under the manifest entry, plus a correction of "generating → first step is encode" (:210).docs/MCP.md:403: same correction.docs/WORKSPACES.mdmanifest section: entries may carrytiming.docs/ACCELERATION.mdcompile section: readingfirst_pass_s − pass_s.templates/text-to-imageat 20 steps, wait,get_job. The step's manifest entry hastimingwithpasses: 20;load_s,encode_s,denoise_s,decode_s,save_snumbers ≥ 0;first_pass_s/pass_snumbers;denoise_s≈first_pass_s + 19 × pass_swithin 15%; the five phase times sum to no more than the job's wall time.load_cached: trueand aload_swell under the first's.encode_sandpassesequal to its step count.timing. A utility-task-only workflow's entries carry no pipeline timing fields.reused: trueand notiming.get_jobreturns the sametiming; the run'smanifest.json(viaexport_job) carries it. A job from before the deploy returns entries with notimingand no error.timingfor the unfinished step, and never a 500.Stage 2: step-cache counts (
timing.cacheandcache_stats)first_blockandmag, the type-only record fortaylorseer/faster/text_kv, thecache_statsevent, thecache_stats_unavailablewarning, theget_job_eventsdescription.first_blockcache:computed + skipped == forwards,forwards == 2 × passes(Don's review; exercises the nestedcache_context("cond"/"uncond")).docs/ACCELERATION.mdcache section: readinghit_rate, and why a cache with 0 skips can still change output (the P2 finding).docs/SERVER.mdevent table:+cache_stats.cache: {type: first_block, threshold: 0.5}. The entry'stiming.cachehastype: "first_block",threshold: 0.5,computed + skipped == forwards,forwardsa whole multiple ofpasses,skipped > 0,hit_rate == skipped / forwardsto 3 places.threshold: 0.001givesskipped == 0,hit_rate == 0.get_job_events(kinds=["cache_stats"])returns exactly one event per pipeline call, with the same object and the step name.cachekey intiming, nocache_statsevent.mag: amagcache (where the box supports it) reports counts the same way.text_kv:type: "text_kv"with null counts and no warning.first_block0.05 at 30 steps hasskipped > 0(matrix P1 inferred ~25%).Order (Don, Q4): stage 1, then stage 2. #875 is approved as a driving session that starts from wall-clock minutes and needs nothing from here, so the order stays.
Risks
torch.compile: readstime.monotonic()once and removes itself after the first forward; unit-tested. A compile run (CUDA) is a nice-to-have, not a gate.pass_sis wall time at step boundaries, not kernel time; the docs say so.Decisions (Don's review, 2026-10-14)
JobDetail.timing. Adopted.wait_for_jobdoesn't carry timing.Proposed follow-up, not in this plan: #866's estimator and
observed_cost.py's cold/warm split (observed_cost.py:50) could readtiming.load_cachedandload_s. That belongs in #866.dkackman commentedon Oct 14, 2026
Review of plan v1: approve the direction, with one design change for v2 to adopt or reject explicitly.
The code facts were checked against current develop and hold:
PHASEShas no encode phase (dw/events.py:219).generatingfires before the pipeline call (pipeline.py:635).job_record.py:53).FBCSharedBlockStateandMagCacheStatekeep only the latestshould_compute, and MagCache zeroesaccumulated_stepswhenever it computes. Nothing counts skips.The cuts from the proposal are right:
compile_s,skipped_passes_equiv, and skip counts for TaylorSeer,fasterandtext_kv.Design change: carry timing on the step's manifest entry, not as a new top-level
JobDetail.timing.ManifestEntry(dw/server/api_models.py:381) is already one entry per step andextra="allow". It is already returned byget_joband stored in history, and it is written to the run directory'smanifest.json. Puttingtiming(andtiming.cache) on it:step_endintoJob.timing;reusedfor free, since the entry already has both.The cost: a step that saves no files has no entry, so no timing. Declare the field as
sometimes(...)onManifestEntryso the OpenAPI contract documents it. If v2 keeps the top-level list, say why. Expect stage 1 to come out about $1–2 cheaper.Stage 2: test the cache context with a real pipeline.
The counter reads leader state through
state_manager.get_state(), which depends on the active cache context. diffusers pipelines open their owncache_context("cond")/("uncond")inside dw'sstateful_cache_context(components.py:834). If the read happens after the forward has left that inner context, it sees the wrong or default state, and a fake-leader-state unit test can't catch that. The first stage-2 test should run a tiny real pipeline with CFG and check thatcomputed + skipped == forwards.Questions
wait_for_jobdoesn't carry timing.owner:leadwith no plan, so nothing waits on stage 2 yet. Flip the order only if H3 cinema-path speed: follow-up experiments after first_block -22% (threshold, 20 steps, close-up, seeds, MagCache) #875 gets scheduled before stage 1 lands.claude-opus-5-5 / anthropic, for Don
dkackman commentedon Oct 14, 2026
Plan v2: changed since v1
timingnow sits on each step's manifest entry (ManifestEntry.timing: sometimes(StepTiming)), not on a top-levelJobDetail.timing. This adopts Don's review. It drops thejobs.timinghistory column, the migration and theJobfold. Timing now survives in the run'smanifest.jsonand inexport_job. Reused steps get notimingkey, and a step whose parent writes its entry has none.computed + skipped == forwards, which catches nestedcache_context("cond"/"uncond")reads.wait_for_jobtiming, summed chain entries, TaylorSeer type-only, timing first. H3 cinema-path speed: follow-up experiments after first_block -22% (threshold, 20 steps, close-up, seeds, MagCache) #875 is approved as a driving session and doesn't need cache counts, so the order stays.manifest[], and a history/export case was added.claude-opus-5-5 / anthropic
3 remaining items
dkackman commentedon Oct 14, 2026
Spec for plan v2, written from the plan alone. Model: claude-opus-5-5 via anthropic, on the mini-ai loop (mps on mini-ai.lan). I made only read-only MCP calls. All cases are in
regression-suite-complete.md, each carries apending:line, and none asserts an absolute time.#885 — stage 1, per-step
timingon manifest entriespasses: 20, the denoise arithmetic within 15%, the phases summing to no more than wall time, andexport_job'smanifest.jsonmatchingget_job.load_cached: true, and itsload_sis lower than a cold run's.passes: 1andpass_s: null.encode_sandpassesequal to the step count. It is skipped as not applicable on a box with no modular template.sharpenutility step gives onetimingeach, and the utility entry has at mostsave_s.reused: trueand notimingkey.timingis unchanged acrossget_job,export_joband a restart (if one happened), and a pre-deploy job has notimingand no error.timingand gets no 500.#886 — stage 2, cache stats
first_block0.5 at 20 steps. The counts add up,forwardsis a multiple ofpasses,skipped > 0,hit_rateis correct to 3 places, and exactly onecache_statsevent matches the manifest.skipped == 0andhit_rate == 0.timing.cacheand no event.magon a Flux-class base, where the box runs one.text_kv,taylorseerandfasterreport their type and config keys, null counts, no warning, and one event.first_block0.05 at 30 steps hasskipped > 0. It runs only on CUDA with lem's fixtures.Notes (none of them blocks a case):
first_block. The plan's stage-2 base is text-to-image, an SD 1.5 UNet. The acceleration guide saysfirst_block,magandlayer_skipneed a registered transformer block class. C-F439 therefore says to fall back to the smallest transformer image template the box validates, and C-F440–C-F442 and C-F444 use the same base. If the lead knows SD 1.5 is refused, naming the intended base in the plan would pin these cases down.cache_stats_unavailable. A consumer can't make private state go missing, so no case triggers this warning. The cases only check that it does not appear onfirst_block,text_kv,taylorseer,fasteror uncached steps. A pytest in dw should cover the positive path.segments: N, but the acceptance intent lists no chain check, so there is no case for it. Say if one is wanted.get_job's start and finish times or its duration field, whichever the reply carries.dkackman commentedon Oct 14, 2026
Close-out: both stages closed; design record written. Lead: claude-opus-5-5 / anthropic.
timingon manifest entries), verified on mps and cross-checked on CUDA; #867 stage 2: step-cache skip counts (timing.cache, cache_stats) #886 (stage 2:timing.cacheand thecache_statsevent), verified on mps.docs/proposals/complete/step-timing-complete.md. It covers what was built, the cuts with their triggers, thepassesruling (passes that actually ran, notnum_inference_steps), and two bounces per stage. Cost is left out because the stage comments give nousage:figures.todo.mdgains a shipped entry. Commit 1ff87f0, merged todevelopat 0e73254. Docs only, nothing to deploy.first_block0.05 at 30 steps). It is CUDA-only, so this box can't run it; it goes to lem.verify: run every case whose
source:names one of this feature's stages, and close the parent if they all pass.dkackman commentedon Oct 14, 2026
Verified on mps on mini-ai.lan (develop @ 0e73254) by claude-opus-5-5 via anthropic.
I ran every case whose
source:names #885 or #886 (C-F430–C-F445 inregression-suite-complete.md) over MCP in workspaceregression-complete. All applicable cases pass.timingget_jobhas notimingand no errorcancelled, manifest[],export_jobokcachekey, 0 events, no warningscache_interval: 5,max_order: 1), faster 05804e87211d: type correct, all counts null, nocache_stats_unavailable, one matching event eachOn C-F439's fallback: SD1.5 (c91c3bee99cd) and Z-Image (fb19b96cd5a7) both validated, but at run time warned that first_block was "not applied" (no transformer / no
enable_cache()). I moved to FLUX.1-dev, the transformer base the case's fallback allows.On C-F444's
fasterrun: bare{"type":"faster"}on FLUX.1-dev validated clean, then failed at run time (eaa66f569193) because a guidance-distilled model needsis_guidance_distilled: true. That comes from the fallback base being distilled, not from the stats this feature adds. With the flag set, the run passes the case's assertions. I filed the validate gap as #897.Side finding, not covered by any case: on mps, transformer pipelines often report
denoise_s≈ 0.3 andpass_s0.0, with the denoise time indecode_s(probably no device sync). I filed it as #896 (backend:mps). SD1.5 timing is plausible.All outputs from this verify have been deleted.