From a1478c303ffe702bae61632da9022daed43ce581 Mon Sep 17 00:00:00 2001 From: Miguel Angel Simon Sierra Date: Sat, 24 Oct 2026 03:05:26 -0400 Subject: [PATCH] perf(producer): the audio task logs where its mix spends its time One line per audio stage: prepare, groups, mix, master, encode and the peak check, in ms. --- .../engine/src/services/audioMixer.test.ts | 37 +++++++++++++++++++ packages/engine/src/services/audioMixer.ts | 17 ++++++++- .../engine/src/services/audioMixer.types.ts | 2 + .../services/render/stages/audioStage.test.ts | 20 ++++++++++ .../src/services/render/stages/audioStage.ts | 8 ++++ 5 files changed, 83 insertions(+), 1 deletion(-) diff --git a/packages/engine/src/services/audioMixer.test.ts b/packages/engine/src/services/audioMixer.test.ts index e2bcdfbbc8..8333ff3574 100644 --- a/packages/engine/src/services/audioMixer.test.ts +++ b/packages/engine/src/services/audioMixer.test.ts @@ -667,6 +667,43 @@ describe("processCompositionAudio", () => { }, ); + it("reports how long each phase of the mix took", async () => { + const baseDir = mkdtempSync(join(tmpdir(), "hf-audio-base-")); + const workDir = mkdtempSync(join(tmpdir(), "hf-audio-work-")); + tempDirs.push(baseDir, workDir); + writeFileSync(join(baseDir, "bed.wav"), "stub"); + + const result = await processCompositionAudio( + [ + { + id: "bed", + src: "bed.wav", + start: 0, + end: 2, + mediaStart: 0, + layer: 0, + volume: 1, + type: "audio", + }, + ], + baseDir, + workDir, + join(baseDir, "out.m4a"), + 2, + undefined, + { masterFxChain: gainChain }, + ); + + expect(result.success).toBe(true); + expect(Object.keys(result.phaseMs ?? {}).sort()).toEqual([ + "encode", + "groups", + "master", + "mix", + "prepare", + ]); + }); + it.each([ ["the master pass", {}, { masterFxChain: gainChain }], ["a group bus", { groupId: "bus", groupFxChain: gainChain }, {}], diff --git a/packages/engine/src/services/audioMixer.ts b/packages/engine/src/services/audioMixer.ts index d141543ddf..9e94f231f8 100644 --- a/packages/engine/src/services/audioMixer.ts +++ b/packages/engine/src/services/audioMixer.ts @@ -1291,9 +1291,11 @@ async function mixThroughFloatSum( }, ): Promise { const sumPath = join(workDir, "master-sum.wav"); + const mixStart = Date.now(); const sum = await mixAudioTracks(tracks, sumPath, totalDuration, signal, config); if (!sum.success) return { ...sum, outputPath }; + const masterStart = Date.now(); const encoderInput = masterChain ? ( await applyAudioFxChain(sumPath, masterChain, join(workDir, "master-fx.wav"), { @@ -1302,6 +1304,7 @@ async function mixThroughFloatSum( }) ).path : sumPath; + const encodeStart = Date.now(); const encoded = await encodeAac(encoderInput, outputPath, totalDuration, { signal, timeout: config?.ffmpegProcessTimeout ?? DEFAULT_CONFIG.ffmpegProcessTimeout, @@ -1322,7 +1325,16 @@ async function mixThroughFloatSum( }; } if (config?.keepEncoderInputAt) renameSync(encoderInput, config.keepEncoderInputAt); - return { ...sum, outputPath, durationMs: sum.durationMs + encoded.durationMs }; + return { + ...sum, + outputPath, + durationMs: sum.durationMs + encoded.durationMs, + phaseMs: { + mix: masterStart - mixStart, + master: encodeStart - masterStart, + encode: Date.now() - encodeStart, + }, + }; } export async function processCompositionAudio( @@ -1689,6 +1701,7 @@ export async function processCompositionAudio( failures, }; }; + const prepareMs = Date.now() - startMs; if (failures.length > 0) return bail(); // Parsed before any group is mixed, so a malformed master chain fails fast and @@ -1836,6 +1849,7 @@ export async function processCompositionAudio( } if (failures.length > 0) return bail(); + const groupsMs = Date.now() - startMs - prepareMs; let mixResult: MixResult; try { mixResult = @@ -1865,6 +1879,7 @@ export async function processCompositionAudio( return { ...mixResult, durationMs: Date.now() - startMs, + phaseMs: { prepare: prepareMs, groups: groupsMs, ...mixResult.phaseMs }, // Both, when both degraded. `mixResult.error ?? degradedNote` reported only // the outer mix and dropped the one that names which GROUPS lost their // members' automation — two different losses, and the operator needs to diff --git a/packages/engine/src/services/audioMixer.types.ts b/packages/engine/src/services/audioMixer.types.ts index bf2aca08f7..e29ad4111a 100644 --- a/packages/engine/src/services/audioMixer.types.ts +++ b/packages/engine/src/services/audioMixer.types.ts @@ -112,4 +112,6 @@ export interface MixResult { tracksProcessed: number; error?: string; failures?: AudioProcessingFailure[]; + /** Wall ms per phase of the mix, for the render log. */ + phaseMs?: Partial>; } diff --git a/packages/producer/src/services/render/stages/audioStage.test.ts b/packages/producer/src/services/render/stages/audioStage.test.ts index bdaefcf7c0..75c1bf4ba0 100644 --- a/packages/producer/src/services/render/stages/audioStage.test.ts +++ b/packages/producer/src/services/render/stages/audioStage.test.ts @@ -237,6 +237,26 @@ describe("runAudioStage", () => { expect(result.audioError).toBeUndefined(); }); + it("logs the mixer's phase times and the peak check's as one line", async () => { + const phaseMs = { prepare: 11, groups: 2, mix: 30, master: 4, encode: 20 }; + processCompositionAudioMock.mockResolvedValue({ + success: true, + outputPath: "audio.m4a", + durationMs: 1, + tracksProcessed: 1, + phaseMs, + }); + const info = vi.fn(); + + await runAudioStage(makeInput({ log: { info } as never })); + + expect(info).toHaveBeenCalledTimes(1); + expect(info).toHaveBeenCalledWith( + "[audio] phases", + expect.objectContaining({ ...phaseMs, guard: expect.any(Number) }), + ); + }); + it("throws a structured retry signal when audio ffmpeg is externally interrupted", async () => { processCompositionAudioMock.mockResolvedValue({ success: false, diff --git a/packages/producer/src/services/render/stages/audioStage.ts b/packages/producer/src/services/render/stages/audioStage.ts index 6c3dc2f067..1df2e19cfc 100644 --- a/packages/producer/src/services/render/stages/audioStage.ts +++ b/packages/producer/src/services/render/stages/audioStage.ts @@ -25,6 +25,7 @@ import { audioFailureDiagnostics, processCompositionAudio, type AudioProcessingFailure, + type MixResult, } from "@hyperframes/engine"; import type { CompositionMetadata } from "../shared.js"; import type { ProducerLogger } from "../../../logger.js"; @@ -71,6 +72,8 @@ export interface AudioStageResult { audioError?: string; /** Bounded typed causes for policy, telemetry, and caller classification. */ audioFailures?: AudioProcessingFailure[]; + /** Wall ms per phase of the audio mix. */ + audioPhaseMs?: MixResult["phaseMs"]; } function assertAudioNotInterrupted(failures: readonly AudioProcessingFailure[] | undefined): void { @@ -94,6 +97,7 @@ export async function runAudioStage(input: AudioStageInput): Promise 0) { // processCompositionAudio reports per-track failures in its result, but an FX @@ -193,6 +199,7 @@ async function mixAudioForDelivery( hasAudio = audioResult.success; audioFailures = audioResult.failures; + audioPhaseMs = audioResult.phaseMs; // processCompositionAudio's error (per-element failures or the mix's own // error) used to be discarded here — the caller only saw hasAudio flip to // false with no explanation, so a real audio failure looked identical to @@ -221,5 +228,6 @@ async function mixAudioForDelivery( hasAudio, audioError, audioFailures, + audioPhaseMs, }; }