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.

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 }, {}],

packages/engine/src/services/audioMixer.ts

@@ -1291,9 +1291,11 @@ async function mixThroughFloatSum(
   },
 ): Promise<MixResult> {
   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

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<Record<"prepare" | "groups" | "mix" | "master" | "encode", number>>;
 }

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,

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<AudioStageR
     const result = await mixAudioForDelivery(input, duration, pcmSourcePath);
     let audioLoweredDb: number | undefined;
     if (result.hasAudio) {
+      const guardStart = Date.now();
       const peak = await constrainAacTruePeak({
         audioPath: result.audioOutputPath,
         sourcePath: pcmSourcePath,
@@ -103,6 +107,7 @@ export async function runAudioStage(input: AudioStageInput): Promise<AudioStageR
       });
       if (!peak.success) throw encoderFailureError("Audio true-peak check failed", peak);
       audioLoweredDb = peak.loweredDb;
+      input.log?.info("[audio] phases", { ...result.audioPhaseMs, guard: Date.now() - guardStart });
     }
     return { ...result, audioLoweredDb, audioProcessMs: Date.now() - stageStart };
   } finally {
@@ -134,6 +139,7 @@ async function mixAudioForDelivery(
   let hasAudio = false;
   let audioError: string | undefined;
   let audioFailures: AudioProcessingFailure[] | undefined;
+  let audioPhaseMs: MixResult["phaseMs"];
 
   if (audios.length > 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,
   };
 }