From 4976b5e0362e7bf6d49eea8b7b5a7b8addf8ed43 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Miguel=20=C3=81ngel?= Date: Mon, 22 Jun 2026 18:10:05 -0400 Subject: [PATCH] fix(producer): split capture average timing (#1657) --- packages/cli/src/commands/render.ts | 2 ++ .../src/server/studioRenderTelemetry.test.ts | 4 +++ .../cli/src/server/studioRenderTelemetry.ts | 2 ++ packages/cli/src/telemetry/events.test.ts | 34 ++++++++++++++++-- packages/cli/src/telemetry/events.ts | 4 +++ .../services/render/perfSummary-dedup.test.ts | 36 ++++++++++++++++++- .../src/services/render/perfSummary.ts | 5 ++- .../src/services/renderOrchestrator.ts | 18 ++++++++++ 8 files changed, 101 insertions(+), 4 deletions(-) diff --git a/packages/cli/src/commands/render.ts b/packages/cli/src/commands/render.ts index c2ca73ab5..333704f48 100644 --- a/packages/cli/src/commands/render.ts +++ b/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, diff --git a/packages/cli/src/server/studioRenderTelemetry.test.ts b/packages/cli/src/server/studioRenderTelemetry.test.ts index c8eefb573..c44fa6f0f 100644 --- a/packages/cli/src/server/studioRenderTelemetry.test.ts +++ b/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 diff --git a/packages/cli/src/server/studioRenderTelemetry.ts b/packages/cli/src/server/studioRenderTelemetry.ts index f7da6fd01..f6d44d5a0 100644 --- a/packages/cli/src/server/studioRenderTelemetry.ts +++ b/packages/cli/src/server/studioRenderTelemetry.ts @@ -41,6 +41,8 @@ function stagesPayload(stages: Record): Partial ({ 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", diff --git a/packages/cli/src/telemetry/events.ts b/packages/cli/src/telemetry/events.ts index 7762e4d8f..e9e8e8d7e 100644 --- a/packages/cli/src/telemetry/events.ts +++ b/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, diff --git a/packages/producer/src/services/render/perfSummary-dedup.test.ts b/packages/producer/src/services/render/perfSummary-dedup.test.ts index 7c3898f2c..a2b9685d1 100644 --- a/packages/producer/src/services/render/perfSummary-dedup.test.ts +++ b/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[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); + }); +}); diff --git a/packages/producer/src/services/render/perfSummary.ts b/packages/producer/src/services/render/perfSummary.ts index bb847cc1f..bdb38a770 100644 --- a/packages/producer/src/services/render/perfSummary.ts +++ b/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)), diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index db2f22020..d96272870 100644 --- a/packages/producer/src/services/renderOrchestrator.ts +++ b/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,6 +1548,7 @@ export async function executeRenderJob( dedupPerfs, }), ); + const captureFrameMs = Date.now() - captureFrameStart; if (streamingRes.success) { streamingHandled = true; workerCount = streamingRes.workerCount; @@ -1544,6 +1556,8 @@ export async function executeRenderJob( 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,