From 31354d52daf3dd43519076be51b46a96617a8c2d Mon Sep 17 00:00:00 2001 From: James Russo Date: Thu, 23 Apr 2026 23:54:56 -0400 Subject: [PATCH] perf(engine): extraction-phase instrumentation (#444) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## What Adds per-phase timings and counters to `extractAllVideoFrames` and surfaces them on the producer's `RenderPerfSummary` as `videoExtractBreakdown` alongside a new `tmpPeakBytes` workDir size sample. ## Why Phase 2 video extraction has five distinct sub-phases (resolve, HDR probe, HDR preflight, VFR probe, VFR preflight, per-video extract) and today they collapse into a single `videoExtractMs` stage timing. That makes every subsequent perf PR in this stack immeasurable — you can't tell whether a win came from cache hits, preflight scope reduction, or pure extraction speed. This PR is foundational for PR #445 (segment-scope HDR preflight) and PR #446 (content-addressed extraction cache). ## How - New `ExtractionPhaseBreakdown` type with `resolveMs`, `hdrProbeMs`, `hdrPreflightMs/Count`, `vfrProbeMs`, `vfrPreflightMs/Count`, `extractMs`, `cacheHits`, `cacheMisses`. Populated inline with `Date.now()` wrappers — overhead is sub-millisecond on every phase. - Returned on `ExtractionResult.phaseBreakdown`. - Producer extends `RenderPerfSummary` with `videoExtractBreakdown?: ExtractionPhaseBreakdown` and `tmpPeakBytes?: number`. `tmpPeakBytes` is sampled from the workDir right before cleanup via a new recursive-size helper that swallows errors (purely observational — a missing workDir must never fail the render). No changes to the capture-lifecycle resource tracking — earlier versions of this instrumentation plumbed injector LRU stats through `RenderOrchestrator`, which conflicted hard with upstream #371 (`buildHdrCaptureOptions` refactor). Dropped that piece for a marginal observability loss. ## Test plan Validation on `packages/producer/tests/vfr-screen-recording`: ```json "videoExtractBreakdown": { "resolveMs": 0, "hdrProbeMs": 0, "hdrPreflightMs": 0, "hdrPreflightCount": 0, "vfrProbeMs": 0, "vfrPreflightMs": 166, "vfrPreflightCount": 1, "extractMs": 97, "cacheHits": 0, "cacheMisses": 0 }, "tmpPeakBytes": 4578598 ``` Total elapsed within noise of pre-PR baseline (2665 → 2673 → 3228ms across hosts). - [x] Unit test: phase-breakdown assertion added to `videoFrameExtractor.test.ts` - [x] Lint + format (oxlint + oxfmt) - [x] Typecheck (engine + producer) - [x] Manual perf validation against VFR fixture --- packages/engine/src/index.ts | 1 + .../src/services/videoFrameExtractor.test.ts | 5 ++ .../src/services/videoFrameExtractor.ts | 59 +++++++++++++++++++ .../src/services/renderOrchestrator.ts | 45 ++++++++++++++ .../src/services/videoFrameExtractor.ts | 1 + 5 files changed, 111 insertions(+) diff --git a/packages/engine/src/index.ts b/packages/engine/src/index.ts index 041418527..0bfc00bcc 100644 --- a/packages/engine/src/index.ts +++ b/packages/engine/src/index.ts @@ -122,6 +122,7 @@ export { type ExtractedFrames, type ExtractionOptions, type ExtractionResult, + type ExtractionPhaseBreakdown, } from "./services/videoFrameExtractor.js"; export { createVideoFrameInjector } from "./services/videoFrameInjector.js"; diff --git a/packages/engine/src/services/videoFrameExtractor.test.ts b/packages/engine/src/services/videoFrameExtractor.test.ts index eab82023e..84f59cff4 100644 --- a/packages/engine/src/services/videoFrameExtractor.test.ts +++ b/packages/engine/src/services/videoFrameExtractor.test.ts @@ -189,6 +189,11 @@ describe.skipIf(!HAS_FFMPEG)("extractAllVideoFrames on a VFR source", () => { // Pre-fix behavior produced ~90 frames (a 25% shortfall). expect(frames.length).toBeGreaterThanOrEqual(119); expect(frames.length).toBeLessThanOrEqual(121); + + expect(result.phaseBreakdown).toBeDefined(); + expect(result.phaseBreakdown.extractMs).toBeGreaterThan(0); + expect(result.phaseBreakdown.vfrPreflightCount).toBe(1); + expect(result.phaseBreakdown.vfrPreflightMs).toBeGreaterThan(0); }, 60_000); // Asserts both frame-count correctness and that we don't emit long runs of diff --git a/packages/engine/src/services/videoFrameExtractor.ts b/packages/engine/src/services/videoFrameExtractor.ts index b16627af9..406d45cf1 100644 --- a/packages/engine/src/services/videoFrameExtractor.ts +++ b/packages/engine/src/services/videoFrameExtractor.ts @@ -46,12 +46,42 @@ export interface ExtractionOptions { format?: "jpg" | "png"; } +/** + * Per-phase timings and counters emitted by `extractAllVideoFrames`. + * + * Used by the producer to surface `perfSummary.videoExtractBreakdown` — without + * this breakdown, a single `videoExtractMs` stage timing hides where cost lives + * (HDR preflight, VFR preflight, per-video ffmpeg extract) when tuning renders. + * + * Field semantics: + * - *Ms fields are wall-clock durations inside each phase. + * - *Count fields report how many sources triggered that phase. + * - extractMs wraps the parallel `extractVideoFramesRange` calls; it + * reflects max-across-parallel-workers, not sum. + * - hdrPreflightMs / vfrPreflightMs both include their probe-time sibling + * (hdrProbeMs / vfrProbeMs) for symmetric semantics. The probe-only fields + * are a finer decomposition, not a separate carve-out. + */ +export interface ExtractionPhaseBreakdown { + resolveMs: number; + hdrProbeMs: number; + hdrPreflightMs: number; + hdrPreflightCount: number; + vfrProbeMs: number; + vfrPreflightMs: number; + vfrPreflightCount: number; + extractMs: number; + cacheHits: number; + cacheMisses: number; +} + export interface ExtractionResult { success: boolean; extracted: ExtractedFrames[]; errors: Array<{ videoId: string; error: string }>; totalFramesExtracted: number; durationMs: number; + phaseBreakdown: ExtractionPhaseBreakdown; } export function parseVideoElements(html: string): VideoElement[] { @@ -375,8 +405,21 @@ export async function extractAllVideoFrames( const extracted: ExtractedFrames[] = []; const errors: Array<{ videoId: string; error: string }> = []; let totalFramesExtracted = 0; + const breakdown: ExtractionPhaseBreakdown = { + resolveMs: 0, + hdrProbeMs: 0, + hdrPreflightMs: 0, + hdrPreflightCount: 0, + vfrProbeMs: 0, + vfrPreflightMs: 0, + vfrPreflightCount: 0, + extractMs: 0, + cacheHits: 0, + cacheMisses: 0, + }; // Phase 1: Resolve paths and download remote videos + const phase1Start = Date.now(); const resolvedVideos: Array<{ video: VideoElement; videoPath: string }> = []; for (const video of videos) { if (signal?.aborted) break; @@ -408,14 +451,19 @@ export async function extractAllVideoFrames( } } + breakdown.resolveMs = Date.now() - phase1Start; + // Phase 2: Probe color spaces and normalize if mixed HDR/SDR + const phase2ProbeStart = Date.now(); const videoColorSpaces = await Promise.all( resolvedVideos.map(async ({ videoPath }) => { const metadata = await extractMediaMetadata(videoPath); return metadata.colorSpace; }), ); + breakdown.hdrProbeMs = Date.now() - phase2ProbeStart; + const hdrPreflightStart = Date.now(); const hdrInfo = analyzeCompositionHdr(videoColorSpaces); if (hdrInfo.hasHdr && hdrInfo.dominantTransfer) { // dominantTransfer is "majority wins" — if a composition mixes PQ and HLG @@ -440,6 +488,7 @@ export async function extractAllVideoFrames( try { await convertSdrToHdr(entry.videoPath, convertedPath, targetTransfer, signal, config); entry.videoPath = convertedPath; + breakdown.hdrPreflightCount += 1; } catch (err) { errors.push({ videoId: entry.video.id, @@ -449,15 +498,19 @@ export async function extractAllVideoFrames( } } } + breakdown.hdrPreflightMs = Date.now() - hdrPreflightStart; // Phase 2b: Re-encode VFR inputs to CFR so the fps filter in Phase 3 produces // the expected frame count. Only the used segment is transcoded. + const vfrPreflightStart = Date.now(); const vfrNormDir = join(options.outputDir, "_vfr_normalized"); for (let i = 0; i < resolvedVideos.length; i++) { if (signal?.aborted) break; const entry = resolvedVideos[i]; if (!entry) continue; + const vfrProbeStart = Date.now(); const metadata = await extractMediaMetadata(entry.videoPath); + breakdown.vfrProbeMs += Date.now() - vfrProbeStart; if (!metadata.isVFR) continue; let segDuration = entry.video.end - entry.video.start; @@ -483,6 +536,7 @@ export async function extractAllVideoFrames( // extraction must seek from 0, not the original mediaStart. Shallow-copy // to avoid mutating the caller's VideoElement. entry.video = { ...entry.video, mediaStart: 0 }; + breakdown.vfrPreflightCount += 1; } catch (err) { errors.push({ videoId: entry.video.id, @@ -490,8 +544,10 @@ export async function extractAllVideoFrames( }); } } + breakdown.vfrPreflightMs = Date.now() - vfrPreflightStart; // Phase 3: Extract frames (parallel) + const phase3Start = Date.now(); const results = await Promise.all( resolvedVideos.map(async ({ video, videoPath }) => { if (signal?.aborted) { @@ -531,6 +587,8 @@ export async function extractAllVideoFrames( }), ); + breakdown.extractMs = Date.now() - phase3Start; + // Collect results and errors for (const item of results) { if ("error" in item && item.error) { @@ -547,6 +605,7 @@ export async function extractAllVideoFrames( errors, totalFramesExtracted, durationMs: Date.now() - startTime, + phaseBreakdown: breakdown, }; } diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index 36911bd1c..115ae13ca 100644 --- a/packages/producer/src/services/renderOrchestrator.ts +++ b/packages/producer/src/services/renderOrchestrator.ts @@ -19,6 +19,7 @@ import { rmSync, readFileSync, readdirSync, + statSync, writeFileSync, copyFileSync, appendFileSync, @@ -28,6 +29,7 @@ import { type EngineConfig, resolveConfig, extractAllVideoFrames, + type ExtractionPhaseBreakdown, createFrameLookupTable, type VideoElement, FrameLookupTable, @@ -150,6 +152,41 @@ function getMaxFrameIndex(frameDir: string): number { return max; } +/** + * Sum file sizes under `dir` recursively. Used to report a `tmpPeakBytes` + * proxy in `RenderPerfSummary` right before workDir cleanup. Swallows errors + * because it's purely observational — a missing workDir or symlink loop must + * not fail the render. + */ +function sampleDirectoryBytes(dir: string): number { + let total = 0; + const stack: string[] = [dir]; + while (stack.length > 0) { + const current = stack.pop(); + if (!current) continue; + let entries: string[] = []; + try { + entries = readdirSync(current); + } catch { + continue; + } + for (const name of entries) { + const full = join(current, name); + try { + const st = statSync(full); + if (st.isDirectory()) { + stack.push(full); + } else if (st.isFile()) { + total += st.size; + } + } catch { + // ignore + } + } + } + return total; +} + // Diagnostic helpers used by the HDR layered compositor when KEEP_TEMP=1 // is set. They are pure (capture no state), so we keep them at module scope // to avoid re-creating closures per frame and to make them callable from @@ -237,6 +274,10 @@ export interface RenderPerfSummary { videoCount: number; audioCount: number; stages: Record; + /** Per-phase breakdown of the Phase 2 video extraction (resolve, HDR probe, HDR preflight, VFR probe/preflight, per-video extract). Undefined when the composition has no videos. */ + 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; captureAvgMs?: number; capturePeakMs?: number; /** @@ -2572,6 +2613,8 @@ export async function executeRenderJob( const totalElapsed = Date.now() - pipelineStart; sampleMemory(); + const tmpPeakBytes = existsSync(workDir) ? sampleDirectoryBytes(workDir) : 0; + const perfSummary: RenderPerfSummary = { renderId: job.id, totalElapsedMs: totalElapsed, @@ -2586,6 +2629,8 @@ export async function executeRenderJob( videoCount: composition.videos.length, audioCount: composition.audios.length, stages: perfStages, + videoExtractBreakdown: extractionResult?.phaseBreakdown, + tmpPeakBytes, hdrDiagnostics: hdrDiagnostics.videoExtractionFailures > 0 || hdrDiagnostics.imageDecodeFailures > 0 ? { ...hdrDiagnostics } diff --git a/packages/producer/src/services/videoFrameExtractor.ts b/packages/producer/src/services/videoFrameExtractor.ts index 224e3b6ed..136c096fd 100644 --- a/packages/producer/src/services/videoFrameExtractor.ts +++ b/packages/producer/src/services/videoFrameExtractor.ts @@ -13,4 +13,5 @@ export { type ExtractedFrames, type ExtractionOptions, type ExtractionResult, + type ExtractionPhaseBreakdown, } from "@hyperframes/engine";