Skip to content

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

Open
vanceingalls wants to merge 1 commit intovance/hdr-benchmark-harnessfrom
vance/logger-level-gating
Open

perf(producer): gate per-frame debug meta via optional isLevelEnabled#383
vanceingalls wants to merge 1 commit intovance/hdr-benchmark-harnessfrom
vance/logger-level-gating

Conversation

@vanceingalls
Copy link
Copy Markdown
Collaborator

@vanceingalls vanceingalls commented Apr 21, 2026

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

  • bun test in producer — 17/17 logger tests pass; existing service tests unchanged.
  • Hot-loop call-site simulation asserts the meta builder is invoked zero times at level="info".
  • ?? true fallback preserves prior behavior for custom logger implementations that don't define the method.
  • 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.

Copy link
Copy Markdown
Collaborator Author

vanceingalls commented Apr 21, 2026

Warning

This pull request is not mergeable via GitHub because a downstack PR is open. Once all requirements are satisfied, merge this PR as a stack on Graphite.
Learn more

This stack of pull requests is managed by Graphite. Learn more about stacking.

Copy link
Copy Markdown
Collaborator

@jrusso1020 jrusso1020 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

isLevelEnabled-gated per-frame debug metadata is a textbook perf fix for a hot-path logger call. Any per-frame logger.debug({ ... }) was paying the cost of constructing the metadata object (JSON serialization, heap allocation, GC pressure) on every frame even when the debug level was off and the message would never be written. Adding an optional isLevelEnabled check before the object construction makes it a no-op when the level is disabled — which is the common case in production.

Two things worth calling out:

  1. This pattern scales beyond debug. Same treatment should probably be applied to any per-frame logger.info or logger.trace calls that construct non-trivial metadata — the if (logger.isLevelEnabled("debug")) { logger.debug({...}) } idiom is more verbose but saves real per-frame work. Worth a one-time audit across renderOrchestrator.ts to catch other instances.

  2. Testing isLevelEnabled being optional. The PR's "optional" qualifier is interesting — if a host logger doesn't implement isLevelEnabled, the code should fall back to constructing + emitting. Worth a unit test confirming both branches (with and without the method) work correctly, since the perf win is only realized when hosts actually implement the method.

Approved.

Rames Jusso

@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 6d2f104 to 6a9fcf1 Compare April 22, 2026 03:03
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch 2 times, most recently from 092e9ba to fdbbfd2 Compare April 22, 2026 03:34
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 24db6e0 to 2c11740 Compare April 22, 2026 04:46
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from fdbbfd2 to 3f90688 Compare April 22, 2026 04:46
@vanceingalls
Copy link
Copy Markdown
Collaborator Author

Thanks for the approval @jrusso1020. Both follow-ups landed in this PR.

1. One-time audit across renderOrchestrator.ts — done.

Audited every per-frame `log.{info,debug,trace}` site in the streaming HDR encode loop. Findings, with the audit committed inline as a comment at `packages/producer/src/services/renderOrchestrator.ts:1970-1982` so the next person to add a hot-path log site doesn't have to redo the work:

  • `[diag] compositeToBuffer plan` (line 687), `[diag] hdr layer blit` (line 744 / 762), `[diag] dom layer blit` (line 832), `[diag] compositeToBuffer end` (line 855) — all four are already gated by `shouldLog = debugDumpEnabled && debugFrameIndex >= 0` (line 685), where `debugDumpEnabled` is driven by `KEEP_TEMP=1`. That gate is strictly stricter than an `isLevelEnabled("info")` check (KEEP_TEMP is off in production, info is on), so they're already allocation-free on the hot path.
  • `HDR blit failed for ${el.id}` (line 507) and `HDR image blit failed for ${el.id}` (line 591) — only fire on caught exceptions, not the happy path. Per-frame allocation cost only paid when something is actively broken.
  • `Cleanup failed` / `Debug log write failed` / `Failed to write perf summary` — once-per-render error paths, not per-frame.

The only happy-path per-frame log that constructed metadata was the one at line 1985 (`[Render] HDR layer composite frame`), which is now both `i % 30 === 0` and `isLevelEnabled` gated. Net result: in production (level=info, KEEP_TEMP unset) the streaming HDR encode loop performs zero allocations for logging metadata.

2. Both branches of `isLevelEnabled`-optional are tested — done.

`packages/producer/src/logger.test.ts`:

  • `"call-site gate using ?? true short-circuits expensive meta build at info level"` (line 170) — `createConsoleLogger("info")`, runs 100 iterations of the call-site pattern, asserts `buildCount === 0` and zero `console.log` calls. Pins the perf win.
  • `"call-site gate runs the meta builder when debug is enabled"` (line 191) — same pattern at `createConsoleLogger("debug")`, asserts metadata builder ran 5/5 times and 5 log entries written. Pins correctness.
  • `"custom logger without isLevelEnabled falls back to running the meta builder (?? true)"` (line 209) — constructs a `ProducerLogger` literal that omits `isLevelEnabled` entirely. Asserts the meta builder runs and the host receives the call. Pins the no-silent-drop guarantee for third-party loggers.

The third test is the one that mattered most — without it, a refactor that changed `?? true` to `?? false` would silently drop diagnostics for any host whose logger doesn't implement the optional method, with no test failure to catch it.

No outstanding action items.

@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from 3f90688 to bd86b42 Compare April 22, 2026 18:01
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 29ab461 to a4873ca Compare April 22, 2026 18:35
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch 2 times, most recently from a549e46 to 8d9641b Compare April 22, 2026 18:50
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from a4873ca to 35fee67 Compare April 22, 2026 18:50
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from 8d9641b to 3fcaa60 Compare April 22, 2026 18:59
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 35fee67 to 2159cf0 Compare April 22, 2026 18:59
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from 3fcaa60 to e675bd9 Compare April 22, 2026 19:34
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 2159cf0 to d746856 Compare April 22, 2026 19:34
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from e675bd9 to f73328c Compare April 22, 2026 20:45
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 2217a93 to 8610f7e Compare April 22, 2026 20:48
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from f73328c to 55a41a8 Compare April 22, 2026 20:48
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 8610f7e to 0d2175b Compare April 22, 2026 22:13
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from 55a41a8 to 349f0f6 Compare April 22, 2026 22:13
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 0d2175b to cd40e4b Compare April 22, 2026 22:53
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from 349f0f6 to cd65ab0 Compare April 22, 2026 22:54
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from cd40e4b to 5594d94 Compare April 22, 2026 23:26
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from cd65ab0 to 5409b1a Compare April 22, 2026 23:26
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 5594d94 to 4ea0021 Compare April 23, 2026 00:06
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from 5409b1a to c6a8280 Compare April 23, 2026 00:07
@vanceingalls vanceingalls force-pushed the vance/hdr-benchmark-harness branch from 4ea0021 to c95ffe5 Compare April 23, 2026 00:11
Add an optional `isLevelEnabled(level)` method to `ProducerLogger` so call
sites can short-circuit expensive metadata construction in hot loops
before handing it to a debug logger. Implement it in
`createConsoleLogger` and gate the per-frame HDR composite snapshot in
`renderOrchestrator` (every 30 frames) on
`log.isLevelEnabled?.("debug") ?? true`, so production runs at
`level="info"` skip the `Array.find` + `toFixed` + struct allocation
entirely while custom loggers without the new method keep their
existing behavior.

Also add unit coverage in `packages/producer/src/logger.test.ts` (17
tests) for level filtering, meta formatting, the new `isLevelEnabled`
path including a hot-loop call-site simulation that asserts zero
builder invocations at info level, and the `?? true` fallback for
loggers that omit the method.

Update `docs/packages/producer.mdx` with a new "Logging" section
documenting `ProducerLogger`, `createConsoleLogger`, `defaultLogger`,
and the `isLevelEnabled` gating pattern.

This closes 8C in `plans/hdr-followups.md`. 8D (gating the
`countNonZeroAlpha` / `countNonZeroRgb48` diagnostic counters) was
verified during the same work to already be guarded by
`shouldLog = debugDumpEnabled && debugFrameIndex >= 0`, where
`debugDumpEnabled` is itself driven by `KEEP_TEMP=1`, so the pixel
iteration is fully skipped on production runs and no code change was
needed.

Made-with: Cursor
@vanceingalls vanceingalls force-pushed the vance/logger-level-gating branch from c6a8280 to 2ce89a5 Compare April 23, 2026 00:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants