fix(producer): split capture average timing (#1657)

Author: miguel-heygen

packages/cli/src/commands/render.ts

@@ -1459,6 +1459,8 @@ function trackRenderMetrics(
     stageVideoExtractMs: stages.videoExtractMs,
     stageAudioProcessMs: stages.audioProcessMs,
     stageCaptureMs: stages.captureMs,
+    stageCaptureSetupMs: stages.captureSetupMs,
+    stageCaptureFrameMs: stages.captureFrameMs,
     stageEncodeMs: stages.encodeMs,
     stageAssembleMs: stages.assembleMs,
     extractResolveMs: extract?.resolveMs,

packages/cli/src/server/studioRenderTelemetry.test.ts

@@ -93,6 +93,8 @@ const fullPerf: RenderPerfSummary = {
     videoExtractMs: 200,
     audioProcessMs: 50,
     captureMs: 4000,
+    captureSetupMs: 750,
+    captureFrameMs: 3250,
     encodeMs: 500,
     assembleMs: 150,
   },
@@ -161,6 +163,8 @@ describe("studioRenderTelemetry", () => {
       expect(p.stageVideoExtractMs).toBe(200);
       expect(p.stageAudioProcessMs).toBe(50);
       expect(p.stageCaptureMs).toBe(4000);
+      expect(p.stageCaptureSetupMs).toBe(750);
+      expect(p.stageCaptureFrameMs).toBe(3250);
       expect(p.stageEncodeMs).toBe(500);
       expect(p.stageAssembleMs).toBe(150);
       // video-extract breakdown

packages/cli/src/server/studioRenderTelemetry.ts

@@ -41,6 +41,8 @@ function stagesPayload(stages: Record<string, number>): Partial<RenderCompletePr
     stageVideoExtractMs: stages.videoExtractMs,
     stageAudioProcessMs: stages.audioProcessMs,
     stageCaptureMs: stages.captureMs,
+    stageCaptureSetupMs: stages.captureSetupMs,
+    stageCaptureFrameMs: stages.captureFrameMs,
     stageEncodeMs: stages.encodeMs,
     stageAssembleMs: stages.assembleMs,
   };

packages/cli/src/telemetry/events.test.ts

@@ -5,8 +5,13 @@ vi.mock("./client.js", () => ({
   trackEvent: (...args: unknown[]) => trackEvent(...args),
 }));
 
-const { trackRenderError, trackRenderObservation, trackCommandFailure, trackCliError } =
-  await import("./events.js");
+const {
+  trackRenderComplete,
+  trackRenderError,
+  trackRenderObservation,
+  trackCommandFailure,
+  trackCliError,
+} = await import("./events.js");
 
 describe("render telemetry events", () => {
   beforeEach(() => {
@@ -49,6 +54,31 @@ describe("render telemetry events", () => {
     );
   });
 
+  it("sends split capture-stage timing fields on render_complete", () => {
+    trackRenderComplete({
+      durationMs: 6000,
+      fps: 30,
+      quality: "standard",
+      docker: false,
+      gpu: false,
+      stageCaptureMs: 5100,
+      stageCaptureSetupMs: 1860,
+      stageCaptureFrameMs: 3240,
+      captureAvgMs: 27,
+    });
+
+    expect(trackEvent).toHaveBeenCalledWith(
+      "render_complete",
+      expect.objectContaining({
+        stage_capture_ms: 5100,
+        stage_capture_setup_ms: 1860,
+        stage_capture_frame_ms: 3240,
+        capture_avg_ms: 27,
+      }),
+      undefined,
+    );
+  });
+
   it("redacts render_observation messages and includes renderJobId for correlation", () => {
     trackRenderObservation({
       renderJobId: "render-123",

packages/cli/src/telemetry/events.ts

@@ -129,6 +129,8 @@ export function trackRenderComplete(
     stageVideoExtractMs?: number;
     stageAudioProcessMs?: number;
     stageCaptureMs?: number;
+    stageCaptureSetupMs?: number;
+    stageCaptureFrameMs?: number;
     stageEncodeMs?: number;
     stageAssembleMs?: number;
     // Video-extraction breakdown (from RenderPerfSummary.videoExtractBreakdown)
@@ -176,6 +178,8 @@ export function trackRenderComplete(
       stage_video_extract_ms: props.stageVideoExtractMs,
       stage_audio_process_ms: props.stageAudioProcessMs,
       stage_capture_ms: props.stageCaptureMs,
+      stage_capture_setup_ms: props.stageCaptureSetupMs,
+      stage_capture_frame_ms: props.stageCaptureFrameMs,
       stage_encode_ms: props.stageEncodeMs,
       stage_assemble_ms: props.stageAssembleMs,
       extract_resolve_ms: props.extractResolveMs,

packages/producer/src/services/render/perfSummary-dedup.test.ts

@@ -3,7 +3,10 @@ import type { CapturePerfSummary } from "@hyperframes/engine";
 import { buildRenderPerfSummary } from "./perfSummary.js";
 import { createRenderJob } from "../renderOrchestrator.js";
 
-function baseInput(dedupPerfs: CapturePerfSummary[]) {
+function baseInput(
+  dedupPerfs: CapturePerfSummary[],
+  overrides: Partial<Parameters<typeof buildRenderPerfSummary>[0]> = {},
+) {
   return {
     job: createRenderJob({ fps: { num: 30, den: 1 }, quality: "high" }),
     workerCount: dedupPerfs.length || 1,
@@ -24,6 +27,7 @@ function baseInput(dedupPerfs: CapturePerfSummary[]) {
     peakRssBytes: 0,
     peakHeapUsedBytes: 0,
     dedupPerfs,
+    ...overrides,
   };
 }
 
@@ -128,3 +132,33 @@ describe("buildRenderPerfSummary static-dedup aggregation", () => {
     });
   });
 });
+
+describe("buildRenderPerfSummary capture average attribution", () => {
+  it("uses frame-capture time for captureAvgMs instead of setup-inclusive captureMs", () => {
+    const summary = buildRenderPerfSummary(
+      baseInput([], {
+        totalFrames: 120,
+        perfStages: {
+          captureMs: 5_100,
+          captureSetupMs: 1_860,
+          captureFrameMs: 3_240,
+        },
+      }),
+    );
+
+    expect(summary.captureAvgMs).toBe(27);
+  });
+
+  it("falls back to legacy captureMs when captureFrameMs is absent", () => {
+    const summary = buildRenderPerfSummary(
+      baseInput([], {
+        totalFrames: 120,
+        perfStages: {
+          captureMs: 5_100,
+        },
+      }),
+    );
+
+    expect(summary.captureAvgMs).toBe(43);
+  });
+});

packages/producer/src/services/render/perfSummary.ts

@@ -122,7 +122,10 @@ export function buildRenderPerfSummary(input: {
     observability: input.observability,
     captureAvgMs:
       input.totalFrames > 0
-        ? Math.round((input.perfStages.captureMs ?? 0) / input.totalFrames)
+        ? Math.round(
+            (input.perfStages.captureFrameMs ?? input.perfStages.captureMs ?? 0) /
+              input.totalFrames,
+          )
         : undefined,
     peakRssMb: Math.round(input.peakRssBytes / (1024 * 1024)),
     peakHeapUsedMb: Math.round(input.peakHeapUsedBytes / (1024 * 1024)),

packages/producer/src/services/renderOrchestrator.ts

@@ -293,6 +293,14 @@ export interface RenderPerfSummary {
   videoExtractBreakdown?: ExtractionPhaseBreakdown;
   /** Bytes on disk in the render's workDir at assembly time (sampled before cleanup). Lets callers correlate peak temp usage with render duration. */
   tmpPeakBytes?: number;
+  /**
+   * Average wall-clock capture time per output frame.
+   *
+   * Uses `stages.captureFrameMs` when present so fixed Stage 4 setup costs
+   * (file server creation, calibration, readiness/session init, strategy
+   * resolution) do not get amortized into a per-frame metric. Older summaries
+   * without the split fall back to `stages.captureMs`.
+   */
   captureAvgMs?: number;
   capturePeakMs?: number;
   captureCalibration?: {
@@ -1488,6 +1496,8 @@ export async function executeRenderJob(
       lastBrowserConsole = hdrRes.lastBrowserConsole;
       hdrPerf = hdrRes.hdrPerf;
       perfStages.captureMs = hdrRes.captureDurationMs;
+      perfStages.captureFrameMs = hdrRes.captureDurationMs;
+      perfStages.captureSetupMs = Math.max(0, Date.now() - stage4Start - hdrRes.captureDurationMs);
       perfStages.encodeMs = hdrRes.encodeMs;
     } else {
       // ── Standard capture paths (SDR or DOM-only HDR) ──────────────────
@@ -1497,6 +1507,7 @@ export async function executeRenderJob(
       // and we fall back to the disk path below.
       let streamingHandled = false;
       if (useStreamingEncode) {
+        const captureFrameStart = Date.now();
         const streamingRes = await observeRenderStage(
           observability,
           "capture_streaming",
@@ -1537,13 +1548,16 @@ export async function executeRenderJob(
               dedupPerfs,
             }),
         );
+        const captureFrameMs = Date.now() - captureFrameStart;
         if (streamingRes.success) {
           streamingHandled = true;
           workerCount = streamingRes.workerCount;
           updateCaptureObservability({ workerCount });
           probeSession = streamingRes.probeSession;
           lastBrowserConsole = streamingRes.lastBrowserConsole;
           perfStages.captureMs = Date.now() - stage4Start;
+          perfStages.captureFrameMs = captureFrameMs;
+          perfStages.captureSetupMs = Math.max(0, perfStages.captureMs - captureFrameMs);
           perfStages.encodeMs = streamingRes.encodeMs; // Overlapped with capture
         } else {
           useStreamingEncode = false;
@@ -1554,6 +1568,7 @@ export async function executeRenderJob(
 
       if (!streamingHandled) {
         // ── Disk-based capture (original flow) ────────────────────────────
+        const captureFrameStart = Date.now();
         const captureRes = await observeRenderStage(
           observability,
           "capture_disk",
@@ -1580,12 +1595,15 @@ export async function executeRenderJob(
               onProgress,
             }),
         );
+        const captureFrameMs = Date.now() - captureFrameStart;
         workerCount = captureRes.workerCount;
         updateCaptureObservability({ workerCount });
         probeSession = captureRes.probeSession;
         lastBrowserConsole = captureRes.lastBrowserConsole;
 
         perfStages.captureMs = Date.now() - stage4Start;
+        perfStages.captureFrameMs = captureFrameMs;
+        perfStages.captureSetupMs = Math.max(0, perfStages.captureMs - captureFrameMs);
 
         const encodeRes = await observeRenderStage(
           observability,