perf(producer): gate per-frame debug meta via optional isLevelEnabled

docs/packages/producer.mdx

@@ -245,6 +245,46 @@ The producer also re-exports key engine functionality for convenience:
 | `resolveRenderPaths()` | Resolve render directory paths |
 | `prepareHyperframeLintBody()` / `runHyperframeLint()` | Linting utilities |
 
+## Logging
+
+The producer ships a small pluggable logger so callers can inject Pino, Winston, or any structured backend without taking a dependency on it.
+
+```ts
+export type LogLevel = "error" | "warn" | "info" | "debug";
+
+export interface ProducerLogger {
+  error(message: string, meta?: Record<string, unknown>): void;
+  warn(message: string, meta?: Record<string, unknown>): void;
+  info(message: string, meta?: Record<string, unknown>): void;
+  debug(message: string, meta?: Record<string, unknown>): void;
+  isLevelEnabled?(level: LogLevel): boolean;
+}
+```
+
+`createConsoleLogger(level)` returns a console-backed implementation that filters by level and JSON-stringifies the optional `meta` object. `defaultLogger` is the singleton at `level="info"`.
+
+### Skipping expensive metadata in hot paths
+
+`isLevelEnabled` is **optional** so existing custom loggers keep working unchanged. When you build a non-trivial meta object in a hot loop just to attach to a debug log, gate the construction with the nullish-coalescing pattern so production runs (`level=info`) pay nothing while loggers without the method behave exactly as before:
+
+```ts
+// Inside a per-frame loop in the encode pipeline:
+if (i % 30 === 0 && (log.isLevelEnabled?.("debug") ?? true)) {
+  const hdrEl = stackingInfo.find((e) => e.isHdr);
+  log.debug("[Render] HDR layer composite frame", {
+    frame: i,
+    time: time.toFixed(2),
+    hdrElement: hdrEl
+      ? { z: hdrEl.zIndex, visible: hdrEl.visible, width: hdrEl.width }
+      : null,
+    stackingCount: stackingInfo.length,
+    activeTransition: activeTransition?.shader,
+  });
+}
+```
+
+The `?? true` fallback means callers using a custom logger that does not implement `isLevelEnabled` continue to build and pass the meta object — the optimization is opt-in for logger implementations that want it.
+
 ## Regression Testing
 
 The producer includes a regression harness for comparing render output against golden baselines. This is useful for catching visual regressions when changing the runtime, engine, or rendering pipeline.

packages/producer/src/logger.test.ts

@@ -0,0 +1,254 @@
+import { afterEach, beforeEach, describe, expect, it, mock } from "bun:test";
+import { createConsoleLogger, defaultLogger } from "./logger.js";
+import type { LogLevel, ProducerLogger } from "./logger.js";
+
+describe("createConsoleLogger", () => {
+  // We capture calls to console.{log,warn,error} via `mock` so we can
+  // assert what would have been printed without polluting test output.
+  let logSpy: ReturnType<typeof mock>;
+  let warnSpy: ReturnType<typeof mock>;
+  let errorSpy: ReturnType<typeof mock>;
+  let origLog: typeof console.log;
+  let origWarn: typeof console.warn;
+  let origError: typeof console.error;
+
+  beforeEach(() => {
+    origLog = console.log;
+    origWarn = console.warn;
+    origError = console.error;
+    logSpy = mock(() => {});
+    warnSpy = mock(() => {});
+    errorSpy = mock(() => {});
+    console.log = logSpy as unknown as typeof console.log;
+    console.warn = warnSpy as unknown as typeof console.warn;
+    console.error = errorSpy as unknown as typeof console.error;
+  });
+
+  afterEach(() => {
+    console.log = origLog;
+    console.warn = origWarn;
+    console.error = origError;
+  });
+
+  describe("level filtering", () => {
+    it("level=info drops debug, keeps info/warn/error", () => {
+      const log = createConsoleLogger("info");
+      log.debug("debug-msg");
+      log.info("info-msg");
+      log.warn("warn-msg");
+      log.error("error-msg");
+
+      expect(logSpy.mock.calls.length).toBe(1);
+      expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] info-msg");
+      expect(warnSpy.mock.calls.length).toBe(1);
+      expect(warnSpy.mock.calls[0]?.[0]).toBe("[WARN] warn-msg");
+      expect(errorSpy.mock.calls.length).toBe(1);
+      expect(errorSpy.mock.calls[0]?.[0]).toBe("[ERROR] error-msg");
+    });
+
+    it("level=debug keeps all four levels", () => {
+      const log = createConsoleLogger("debug");
+      log.debug("d");
+      log.info("i");
+      log.warn("w");
+      log.error("e");
+
+      // info + debug both go to console.log
+      expect(logSpy.mock.calls.length).toBe(2);
+      expect(logSpy.mock.calls[0]?.[0]).toBe("[DEBUG] d");
+      expect(logSpy.mock.calls[1]?.[0]).toBe("[INFO] i");
+      expect(warnSpy.mock.calls.length).toBe(1);
+      expect(errorSpy.mock.calls.length).toBe(1);
+    });
+
+    it("level=warn drops info and debug, keeps warn/error", () => {
+      const log = createConsoleLogger("warn");
+      log.debug("d");
+      log.info("i");
+      log.warn("w");
+      log.error("e");
+
+      expect(logSpy.mock.calls.length).toBe(0);
+      expect(warnSpy.mock.calls.length).toBe(1);
+      expect(errorSpy.mock.calls.length).toBe(1);
+    });
+
+    it("level=error drops everything except error", () => {
+      const log = createConsoleLogger("error");
+      log.debug("d");
+      log.info("i");
+      log.warn("w");
+      log.error("e");
+
+      expect(logSpy.mock.calls.length).toBe(0);
+      expect(warnSpy.mock.calls.length).toBe(0);
+      expect(errorSpy.mock.calls.length).toBe(1);
+    });
+
+    it("default level is info", () => {
+      const log = createConsoleLogger();
+      log.debug("d");
+      log.info("i");
+
+      expect(logSpy.mock.calls.length).toBe(1);
+      expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] i");
+    });
+  });
+
+  describe("meta formatting", () => {
+    it("appends JSON-stringified meta when provided", () => {
+      const log = createConsoleLogger("info");
+      log.info("hello", { a: 1, b: "two" });
+
+      expect(logSpy.mock.calls[0]?.[0]).toBe('[INFO] hello {"a":1,"b":"two"}');
+    });
+
+    it("emits message only when meta is omitted", () => {
+      const log = createConsoleLogger("info");
+      log.info("plain");
+
+      expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] plain");
+    });
+
+    it("does not invoke JSON.stringify when level is filtered out", () => {
+      const log = createConsoleLogger("info");
+      // A getter that throws would be invoked by JSON.stringify if the
+      // logger built the meta string before the level check. We rely on
+      // the call-site `isLevelEnabled` gate plus the internal `shouldLog`
+      // short-circuit to prevent that.
+      const trap = {
+        get problem() {
+          throw new Error("meta should not be stringified when level is filtered");
+        },
+      };
+      // Should not throw — debug is below the info threshold.
+      log.debug("trap", trap as unknown as Record<string, unknown>);
+      expect(logSpy.mock.calls.length).toBe(0);
+    });
+  });
+
+  describe("isLevelEnabled", () => {
+    const cases: ReadonlyArray<{
+      threshold: LogLevel;
+      enabled: ReadonlyArray<LogLevel>;
+      disabled: ReadonlyArray<LogLevel>;
+    }> = [
+      {
+        threshold: "error",
+        enabled: ["error"],
+        disabled: ["warn", "info", "debug"],
+      },
+      {
+        threshold: "warn",
+        enabled: ["error", "warn"],
+        disabled: ["info", "debug"],
+      },
+      {
+        threshold: "info",
+        enabled: ["error", "warn", "info"],
+        disabled: ["debug"],
+      },
+      {
+        threshold: "debug",
+        enabled: ["error", "warn", "info", "debug"],
+        disabled: [],
+      },
+    ];
+
+    for (const { threshold, enabled, disabled } of cases) {
+      it(`level=${threshold} reports enabled levels correctly`, () => {
+        const log = createConsoleLogger(threshold);
+        for (const lvl of enabled) {
+          expect(log.isLevelEnabled?.(lvl)).toBe(true);
+        }
+        for (const lvl of disabled) {
+          expect(log.isLevelEnabled?.(lvl)).toBe(false);
+        }
+      });
+    }
+
+    it("call-site gate using `?? true` short-circuits expensive meta build at info level", () => {
+      // Mirrors the hot-path pattern used in renderOrchestrator: callers
+      // wrap meta construction in `if (log.isLevelEnabled?.('debug') ?? true)`
+      // so production (level=info) skips the work entirely.
+      const log = createConsoleLogger("info");
+      let buildCount = 0;
+      const buildMeta = (): Record<string, unknown> => {
+        buildCount += 1;
+        return { expensive: true };
+      };
+
+      for (let i = 0; i < 100; i++) {
+        if (log.isLevelEnabled?.("debug") ?? true) {
+          log.debug("hot-loop", buildMeta());
+        }
+      }
+
+      expect(buildCount).toBe(0);
+      expect(logSpy.mock.calls.length).toBe(0);
+    });
+
+    it("call-site gate runs the meta builder when debug is enabled", () => {
+      const log = createConsoleLogger("debug");
+      let buildCount = 0;
+      const buildMeta = (): Record<string, unknown> => {
+        buildCount += 1;
+        return { iter: buildCount };
+      };
+
+      for (let i = 0; i < 5; i++) {
+        if (log.isLevelEnabled?.("debug") ?? true) {
+          log.debug("loop", buildMeta());
+        }
+      }
+
+      expect(buildCount).toBe(5);
+      expect(logSpy.mock.calls.length).toBe(5);
+    });
+
+    it("custom logger without isLevelEnabled falls back to running the meta builder (`?? true`)", () => {
+      // A user-provided logger that doesn't implement isLevelEnabled — the
+      // call-site fallback must preserve the prior behavior of always
+      // building meta (so we don't silently drop diagnostics for them).
+      const calls: Array<{ msg: string; meta?: Record<string, unknown> }> = [];
+      const customLog: ProducerLogger = {
+        error: (msg, meta) => calls.push({ msg, meta }),
+        warn: (msg, meta) => calls.push({ msg, meta }),
+        info: (msg, meta) => calls.push({ msg, meta }),
+        debug: (msg, meta) => calls.push({ msg, meta }),
+      };
+
+      let buildCount = 0;
+      const buildMeta = (): Record<string, unknown> => {
+        buildCount += 1;
+        return { i: buildCount };
+      };
+
+      for (let i = 0; i < 3; i++) {
+        if (customLog.isLevelEnabled?.("debug") ?? true) {
+          customLog.debug("evt", buildMeta());
+        }
+      }
+
+      expect(buildCount).toBe(3);
+      expect(calls).toHaveLength(3);
+      expect(calls[0]?.msg).toBe("evt");
+      expect(calls[0]?.meta).toEqual({ i: 1 });
+    });
+  });
+
+  describe("defaultLogger", () => {
+    it("is a singleton at level=info", () => {
+      defaultLogger.info("default-info");
+      defaultLogger.debug("default-debug");
+
+      expect(logSpy.mock.calls.length).toBe(1);
+      expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] default-info");
+    });
+
+    it("exposes isLevelEnabled gating debug at info threshold", () => {
+      expect(defaultLogger.isLevelEnabled?.("info")).toBe(true);
+      expect(defaultLogger.isLevelEnabled?.("debug")).toBe(false);
+    });
+  });
+});

packages/producer/src/logger.ts

@@ -15,6 +15,26 @@ export interface ProducerLogger {
   warn(message: string, meta?: Record<string, unknown>): void;
   info(message: string, meta?: Record<string, unknown>): void;
   debug(message: string, meta?: Record<string, unknown>): void;
+
+  /**
+   * Optional fast level check used to skip expensive metadata construction
+   * at the call site. When the call site needs to build a non-trivial meta
+   * object (e.g. snapshot a struct, format numbers, run `Array.find` over
+   * scene state) just to attach to a debug log, gate it with this method:
+   *
+   * ```ts
+   * if (log.isLevelEnabled?.("debug") ?? true) {
+   *   const meta = buildExpensiveMeta();
+   *   log.debug("hot-path event", meta);
+   * }
+   * ```
+   *
+   * The default coalescence (`?? true`) preserves today's behavior for
+   * loggers that omit this method — they keep building the meta object as
+   * before. Custom integrations (Pino, Winston, structured loggers) should
+   * implement this to enable the optimization.
+   */
+  isLevelEnabled?(level: LogLevel): boolean;
 }
 
 const LOG_LEVEL_PRIORITY: Record<LogLevel, number> = {
@@ -59,6 +79,9 @@ export function createConsoleLogger(level: LogLevel = "info"): ProducerLogger {
         console.log(`[DEBUG] ${message}${formatMeta(meta)}`);
       }
     },
+    isLevelEnabled(msgLevel) {
+      return shouldLog(msgLevel);
+    },
   };
 }
 

packages/producer/src/services/renderOrchestrator.ts

@@ -1972,7 +1972,27 @@ export async function executeRenderJob(
               (t) => i >= t.startFrame && i <= t.endFrame,
             );
 
-            if (i % 30 === 0) {
+            // Per-frame debug snapshot (every 30 frames). The meta object
+            // requires `Array.find` over `stackingInfo` plus a number-format
+            // and conditional struct allocation — non-trivial work to do
+            // every 30 frames in the encode hot loop. Gate the entire block
+            // on the logger's level check so production runs (level=info)
+            // pay nothing.
+            //
+            // Audit note (PR #383 review): this is the only per-frame log
+            // site in the streaming HDR encode loop that constructs
+            // non-trivial metadata. The `[diag]` log.info calls inside
+            // compositeToBuffer (compositeToBuffer plan, hdr layer blit,
+            // dom layer blit, compositeToBuffer end) are already gated by
+            // `shouldLog = debugDumpEnabled && debugFrameIndex >= 0`, where
+            // debugDumpEnabled is driven by KEEP_TEMP=1 — strictly stricter
+            // than an isLevelEnabled check. The HDR blit error-path
+            // log.debugs only fire on caught failures, not on the happy
+            // path. Any new per-frame log site that builds meta should
+            // follow the same `if (log.isLevelEnabled?.("level") ?? true)`
+            // pattern (or stay behind `shouldLog`) so production stays
+            // allocation-free in the hot loop.
+            if (i % 30 === 0 && (log.isLevelEnabled?.("debug") ?? true)) {
               const hdrEl = stackingInfo.find((e) => e.isHdr);
               log.debug("[Render] HDR layer composite frame", {
                 frame: i,