fix(producer): report render progress from the first frame, at most four times a second

[miguel-heygen]

What changes for a person watching a render

Export progress now moves from the first frame. Before, a render sat at 25% "Starting frame capture" with no report at all while the browsers started and the first 30 frames were captured: about 3 s on a quiet machine and over 30 s on a busy one. Then it jumped in 30-frame steps. The sequential capture paths had the opposite problem and reported every single frame, so a piped CLI printed one line per frame.

Now every capture stage reports the first frame, the last frame, and at most one update every 250 ms in between. The warm-up steps before frame 1 each report their own label:

• Checking browser GPU (the GPU probe launches a throwaway Chrome in auto mode)
• Measuring capture speed (capture calibration, when worker count is auto)
• Starting browsers (k/n ready) (parallel workers, from the engine's existing worker phase events)

How

• reportFrameProgress in packages/producer/src/services/render/shared.ts is the one owner of capture-loop cadence. The job's fields still update on every frame; only the callback is throttled (per job, WeakMap). It replaces the % 30, % 10 and every-frame checks in the disk, streaming, segmented and both HDR loops.
• reportWorkerStartup counts workers that reached their first capture. Worker ids past a smaller retry's worker count are ignored. Start-up and frame reports keep separate timers, so the first captured frame is always reported.
• Frame labels (Streaming frame N/M, Capturing frame N/M, Layered composite frame N/M) are unchanged, so parsers that read them keep working.

Before / after

Same 300-frame project, --quality draft --workers auto, piped (non-TTY) CLI, one Linux machine at the same load, run back to back; both took the six-worker streaming route. Seconds since spawn. Before is the published 0.8.71, which is this branch's base.

Before (0.8.71):

17.6   25% Starting frame capture
27.7   31% Streaming frame 30/300 (6 workers)     <- 10.1 s with no report
29.0   36% Streaming frame 60/300 (6 workers)
30.5   42% Streaming frame 90/300 (6 workers)
...    13 reports after 25% in total
42.3   80% Streaming frame 300/300 (6 workers)

After (this branch):

 4.6   25% Starting frame capture
 4.6   25% Checking browser GPU
 5.8   25% Measuring capture speed
 7.0   25% Starting browsers (0/6 ready)
 8.6   25% Starting browsers (1/6 ready)
 8.9   25% Starting browsers (6/6 ready)
 8.9   25% Streaming frame 1/300 (6 workers)
 9.3   27% Streaming frame 12/300 (6 workers)
 9.7   29% Streaming frame 24/300 (6 workers)
10.0   31% Streaming frame 33/300 (6 workers)
...    76 reports after 25% in total
41.1   80% Streaming frame 300/300 (6 workers)

Longest gap between reports after 25%: 10.1 s before, 5.1 s after. The remaining 5.1 s is a stretch around frame 160 of this project where no worker finished any frame, so there was nothing to report (the same stretch is hidden inside a 30-frame step before).

Under much heavier load on the same machine the difference grows: 32.6 s of silence after 25% before, 6.5 s after (same frame-160 stretch).

Tests

• captureStreamingStage.test.ts: a slow fake parallel capture (400 ms per frame) must report browser start-up, then frame 1 and frame 2, then every frame; a fast one (300 frames at 1 ms) must report fewer than 5 frame lines and end on 300/300. Both fail on main (main reports frames 30 and 60 only, and 10 lines for the fast run).
• shared.test.ts: ready count across a retry with fewer workers.

Consequences worth knowing

• Render-failure telemetry takes its stage code from the current label. A failure during warm-up used to be filed under starting_frame_capture; it is now filed under the step that failed: checking_browser_gpu, measuring_capture_speed or starting_browsers (the CLI's normalizeStageCode keeps one code for the counted label).
• Not in this change: the disk-frame encode path reports nothing between Encoding video (75%) and Assembling (90%). That is one ffmpeg call with no progress parsing; separate follow-up.

Independent review

Two passes by a reviewer that did not write the code (first head, then the fix-up). Mutations run against every new assertion (interval to 0, no first-call report, no last-frame force, no worker-id filter, start-up call removed, shared timer, telemetry prefix removed): each one fails a test. Lint and format clean on changed files; each changed test file passes alone.

• Should fix (fixed): a counted Starting browsers (k/n ready) label would have split the CLI's failure stage code per count. normalizeStageCode now maps it to starting_browsers.
• Should fix (fixed, found in the live trace): frame 1 was swallowed when it landed within 250 ms of the last start-up report. Start-up and frame reports now keep separate timers.
• Note (left as is): after a transient capture retry with the same worker count, the first start-up line can count a worker from the failed attempt as ready until that worker's fresh launch event arrives (milliseconds). Display only; it corrects itself.
• Note (pre-existing): Studio's render-error event sends the raw stage text with no bucketed code, so it already varies with frame counts on main.

[terencecho]

Approved at 74548b5c. Progress-reporting refactor with the right shape: one owner of cadence (reportFrameProgress), independent timer for start-up, telemetry codes bounded, and every migrated call-site preserves first + last frame reports.

Scope — 11 files, ~200 line delta.

• packages/producer/src/services/render/shared.ts +60/-0 — new module surface: reportFrameProgress, reportWorkerStartup, private reportThrottled helper, three WeakMaps keyed by RenderJob.
• 5 stage files (captureStreamingStage, captureStage, captureSegmentedStage, captureHdrHybridLoop, captureHdrSequentialLoop) — every capture-loop updateJobStatus migrated to reportFrameProgress.
• renderOrchestrator.ts +2 — two new labels Checking browser GPU (before resolveBrowserGpuMode) and Measuring capture speed (before capture_calibration observable stage).
• render.ts +2 — normalizeStageCode gains a startsWith("Starting browsers") guard so per-count labels collapse to one telemetry code.
• captureStreamingStage.test.ts +70/-1, shared.test.ts +40/-2, render.test.ts +5/-0 — pins.

Cadence primitive (Home's overhead ask). reportThrottled per call: one Date.now(), one WeakMap.get, one subtraction, one comparison, at most one WeakMap.set. Zero I/O, zero async, zero per-frame allocations on the throttled path (the phases Map only mutates on worker-phase changes, not per frame). Against a per-frame cost of ~50-500ms of GPU/CPU capture work, the instrumentation is sub-microsecond noise. No render-path overhead concern.

"Not faking progress" audit.

• updateJobStatus is called on every reportThrottled invocation regardless of throttle. It mutates job.progress + job.stage unconditionally and passes undefined for onProgress when the interval hasn't elapsed. So consumers reading job.* directly see live per-frame state; only the callback stream is throttled. Not lying about state.
• Frame labels unchanged (Streaming frame N/M, Capturing frame N/M, Layered composite frame N/M) — external log parsers keep working, per Miguel's contract.
• Warm-up labels map to real code sites: Checking browser GPU fires immediately before resolveBrowserGpuMode in renderOrchestrator.ts; Measuring capture speed immediately before the capture_calibration observable stage; Starting browsers (k/n ready) derives from progress.latestWorkerPhase events emitted by the engine's parallel-workers module (not fabricated).
• Ready count filter (phase === "frame_capture" || "frame_encode") is honest: a worker is "ready" only when it has genuinely reached the capture/encode phase, not merely launched.

Ponytail retry semantics — the id < activeWorkers filter. After a transient retry that drops from n workers to a smaller n', workerPhasesByJob still holds cached entries for workerId ∈ [0, n) from the failed attempt. Filtering on id < progress.activeWorkers (= n') drops the stale ids from the "ready" tally without needing an explicit reset. shared.test.ts walks this exactly: 5-step sequence exercises the (0→2, 3-workers) → (0→1, 2-workers) transition and the expected "Starting browsers (0/2 ready)" after the retry starts, confirming the stale worker-2 phase is excluded once activeWorkers === 2. Miguel's "display only, corrects itself" caveat on the fresh-launch race is a fair scope call — the correctness invariant (ready count never misrepresents the finished capture) holds.

Separate startup/frame timers (the fix-up commit 74548b5c). The initial commit b4908bc4 used one shared lastReportAt. That would swallow frame 1 if it landed within 250ms of the last Starting browsers (n/n ready) report — exactly the race Miguel found on live trace. Fix: two WeakMaps (lastFrameReportAt, lastStartupReportAt), each consulted independently in reportThrottled(lastReportAt, ...). The < 5 fast-test explicitly pins this: Frame 1 lands 1 ms after the start-up report and is still reported — this asserts frame 1 must appear, and it does because the frame-side timer is undefined at that point so due=true via the last === undefined branch. Structural pin.

First-frame / last-frame invariants preserved at every migrated call-site. Every call passes X === totalFrames (or equivalent) as isLastFrame → force=true → always reported. First call also always reported (last === undefined in reportThrottled). Verified per file:

• captureHdrHybridLoop.ts:191: framesWritten === totalFrames ✓
• captureHdrSequentialLoop.ts:220: i + 1 === totalFrames ✓
• captureSegmentedStage.ts:212: i + 1 === ctx.totalFrames ✓
• captureStage.ts:364, 572: progress.capturedFrames === progress.totalFrames, fileIndex + 1 === rangeFrames ✓
• captureStreamingStage.ts:489, 516, 822, 966: all four sites correctly pass ... === totalFrames ✓

And job.framesRendered = X runs before every reportFrameProgress call in every path — so the throttled callback and the direct read agree at the moment of firing.

Telemetry-code bound. normalizeStageCode:

• KNOWN_STAGE_CODES map unchanged for existing labels.
• "Checking browser GPU" and "Measuring capture speed" slug via the fallback (checking_browser_gpu, measuring_capture_speed) — a "distinct, readable code without needing this map updated first" per the function's own docstring intent.
• "Starting browsers (k/n ready)" gets an explicit prefix guard → starting_browsers regardless of counts. render.test.ts:2024-2025 pins both (0/6 ready) and (5/6 ready) collapse to the same code.
• The consequence Miguel names — "a failure during warm-up used to be filed under starting_frame_capture; it is now filed under the step that failed" — is a bucket-refinement, not a regression. New codes are strictly finer-grained.

Worker startup guard. Both captureStreamingStage.ts:812 and captureStage.ts:364 bracket the latestWorkerPhase branch with if (progress.capturedFrames === 0) reportWorkerStartup(...); return;. So (a) startup events after captures begin don't spam late reports, and (b) the frame-progress path is skipped when the callback is a phase event, not a capture event. Correct short-circuit.

GC hygiene. All three module-level maps are WeakMap<RenderJob, ...>. When a render job is no longer reachable, its entries are eligible for GC. No cross-render memory retention.

Tests — thorough structural pins.

• captureStreamingStage.test.ts slow path (400 ms/frame): asserts exact first-3 sequence [Starting browsers, frame 1, frame 2] and total count 41 (= 1 startup + 40 frames). Pins first-frame-always-reported plus the ordering invariant.
• Fast path (1 ms/frame, 300 frames): frames.length < 5 bounds the throttle; explicit frames[0] = Streaming frame 1/300 pins the separate-timer race; frames.at(-1) = Streaming frame 300/300 pins the force-last branch.
• shared.test.ts walks the ponytail-filter retry sequence in 5 steps with the setSystemTime bump to bypass the interval — exercises activeWorkers shrink correctly.
• render.test.ts — 4 normalizeStageCode assertions including both count variants → the starting_browsers code stays stable regardless of (k/n).
• Each mutation Miguel names (interval=0, no first-call, no last-force, no worker-id filter, no startup call, shared timer, telemetry prefix removed) fails one of the above tests. Correct pin coverage for the primary invariants.

Not in scope, correctly named. Disk-frame encode gap (Encoding video 75% → Assembling 90%) is one ffmpeg call with no progress parsing — deferred as follow-up. Studio's raw-stage-text render-error event is pre-existing behavior. Fresh-launch race after retry corrects itself in ms. All three called out in the PR body's "Consequences worth knowing" / "Independent review" sections — no hidden regressions.

require_last_push_approval gate cleared. Head author + committer both miguel-heygen (fix-up commit 74548b5c); tai ≠ last pusher.

— Review by tai (pr-review)