mirror of
https://github.com/heygen-com/hyperframes.git
synced 2026-09-03 23:03:09 +00:00
perf(producer): gate per-frame debug meta via optional isLevelEnabled (#383)
## Summary
Add an optional `isLevelEnabled(level)` method to `ProducerLogger` and use it to short-circuit per-frame HDR composite metadata construction in `renderOrchestrator` when the log level is above debug.
Closes Chunks 8C and 8D from `plans/hdr-followups.md`.
## Why
`Chunk 8C` of `plans/hdr-followups.md`. The per-frame HDR composite snapshot (every 30 frames) was building an `Array.find` + `toFixed` + struct allocation unconditionally and handing it to a debug logger that immediately discarded it at `level="info"`. On long renders, this is allocation pressure and CPU time wasted on log meta nobody reads.
`Chunk 8D` was investigated in the same pass and found to already be guarded — see below.
## What changed
- New optional `isLevelEnabled(level: ProducerLogLevel): boolean` on `ProducerLogger`.
- `createConsoleLogger` implements it.
- `renderOrchestrator.ts` per-frame HDR composite snapshot is now gated on `i % 30 === 0 && (log.isLevelEnabled?.("debug") ?? true)` — production runs at `level="info"` skip the meta-object construction entirely; custom loggers without the new method keep their existing behavior thanks to the `?? true` fallback.
- New `packages/producer/src/logger.test.ts` (17 tests) covering level filtering, meta formatting, the `isLevelEnabled` path, a hot-loop call-site simulation that asserts zero builder invocations at info level, and the `?? true` fallback for loggers that omit the method.
- `docs/packages/producer.mdx` gains a new "Logging" section documenting `ProducerLogger`, `createConsoleLogger`, `defaultLogger`, and the `isLevelEnabled` gating pattern.
**8D resolution (no code change).** `countNonZeroAlpha` / `countNonZeroRgb48` calls live behind `shouldLog = debugDumpEnabled && debugFrameIndex >= 0`, where `debugDumpEnabled` is itself driven by `KEEP_TEMP=1`. The pixel iteration is fully skipped on production runs already, so 8D needed no fix — verified during the 8C work.
## Test plan
- [x] `bun test` in producer — 17/17 logger tests pass; existing service tests unchanged.
- [x] Hot-loop call-site simulation asserts the meta builder is invoked **zero times** at `level="info"`.
- [x] `?? true` fallback preserves prior behavior for custom logger implementations that don't define the method.
- [x] Re-ran the HDR benchmark from Chunk 8A — no regression on wall-clock, peak heap unchanged at info level.
## Stack
Chunks 8C + 8D of `plans/hdr-followups.md`. Sits on top of the benchmark harness PR (Chunk 8A) so the optimization is measurable.
This commit is contained in:
Vance Ingalls
@@ -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);
|
||||
});
|
||||
});
|
||||
});
|
||||
@@ -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);
|
||||
},
|
||||
};
|
||||
}
|
||||
|
||||
|
||||
@@ -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,
|
||||
|
||||
Reference in New Issue
Block a user