perf(log): batch stdout writes and cache the timestamp - #266
Conversation
`log()` called `console.log` once per request and rebuilt an Intl-backed timestamp every time. Instead, buffer lines and flush once per event loop turn via `setImmediate`, and cache the formatted time for the second it is valid for (two timestamps in the same second always format identically). Colors are now also resolved once per `log()` call rather than per request. Under load this is 61 lines per stdout write instead of 1, worth +23% RPS (14,616 -> 17,992; oha -c 64, 3s, median of 9 interleaved runs across /dev/null, pipe and file sinks). Against a no-logger baseline the logger's overhead drops from 28% to ~10%. Output is byte-identical. Buffering means a line can be pending when the process exits, so flush what is left synchronously from an `exit` hook. Colors are additionally disabled when `NODE_ENV` is `production`: escapes are noise once logs reach a file or a collector, and a container started with a tty was still getting them. `FORCE_COLOR` overrides. This is resolved per `log()` call, not at module scope, because the CLI assigns `NODE_ENV` after this module is imported. Adds the `log()` tests F46 asks for. Partially addresses the `log.ts:4` item (colors gated, `console.log` no longer hard-coded); `LogOptions` still has no sink option, so that item stays open. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
📝 WalkthroughWalkthroughThe request logger now supports conditional colors, cached formatting, batched stdout writes, backpressure handling, exit-time flushing, and fallback output. Tests cover these behaviors, while a benchmark compares logger throughput across implementations and output sinks. ChangesRequest logging
Estimated code review effort: 4 (Complex) | ~60 minutes Possibly related PRs
Suggested reviewers: Poem
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
commit: |
![coderabbitai[bot]](https://avatars.github.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/log.ts`:
- Around line 93-98: Update the exit-time write logic around
proc.getBuiltinModule and fs.writeSync to encode chunk once and repeatedly call
fs.writeSync with the remaining byte range, advancing by each returned byte
count until all bytes are flushed. Preserve the existing proc.stdout fallback
when the filesystem module is unavailable.
- Around line 31-38: Update the stdout handling around the write helper to
register a shared error handler on process.stdout that safely absorbs
broken-pipe errors, including EPIPE, outside the existing try/catch flow. Reuse
that handler for the stdout stream and add a regression test using a pipe that
closes before writing, verifying the process remains stable.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro
Run ID: a4ac02f6-6cf6-411a-92a5-4dda5d9bc944
📒 Files selected for processing (3)
docs/1.guide/4.middleware.mdsrc/log.tstest/log.test.ts
Honor stdout.write()'s return value: when the buffer is over its high-water mark, stop writing and wait for `drain` instead of letting Node's internal buffer grow unbounded. On exit, encode via TextEncoder (runtime-agnostic; `Buffer` is Node-only) and loop writeSync until all bytes land, guarding against partial writes. Adds a backpressure/drain test. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
There was a problem hiding this comment.
Actionable comments posted: 2
🧹 Nitpick comments (2)
test/bench-log/README.md (1)
28-30: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low valueAlign documentation with the suggested formatting refactor.
If you opt to rename the "overhead" column to "change" in
_run.mjsto resolve the double-negative formatting, you can update this paragraph to match.📝 Proposed update
-| `file` | logs appended to a file on disk | - -`overhead` is the throughput given up by adding the logger, relative to the -no-logger baseline for that same sink. The run order of the cells is shuffled so +| `file` | logs appended to a file on disk | + +`change` is the relative difference in throughput caused by adding the logger, compared +to the no-logger baseline for that same sink. The run order of the cells is shuffled so🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@test/bench-log/README.md` around lines 28 - 30, Align the benchmark README paragraph with the formatting refactor in _run.mjs: if the overhead column is renamed to “change,” update this paragraph to describe the “change” column and its meaning while preserving the explanation of the same-sink no-logger baseline and shuffled run order.test/bench-log/_run.mjs (1)
142-152: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low valueStandardize the throughput change formatting.
If the logger implementation happens to improve throughput (e.g., due to caching improvements or natural machine variance),
overheadevaluates to a negative number. Due to the hardcoded-prefix in the string template, this results in an awkward double-negative display (e.g.,--5.0%).Calculating the standard relative difference and formatting the sign dynamically makes the output much clearer.
✨ Proposed refactor
- // Overhead = throughput given up by adding the logger, relative to no logger. - const overhead = ((none - withLog) / none) * 100; - return [name, none.toLocaleString(), withLog.toLocaleString(), `-${overhead.toFixed(1)}%`]; + // Difference = relative throughput change caused by adding the logger. + const diff = ((withLog - none) / none) * 100; + const sign = diff > 0 ? "+" : ""; + return [name, none.toLocaleString(), withLog.toLocaleString(), `${sign}${diff.toFixed(1)}%`]; }); -const table = markdownTable(["sink", "no logger", "log()", "overhead"], rows, [ +const table = markdownTable(["sink", "no logger", "log()", "change"], rows, [ "left", "right", "right",🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@test/bench-log/_run.mjs` around lines 142 - 152, Update the throughput formatting in the rows mapping to avoid hardcoding a negative sign for overhead. Calculate the relative difference consistently and format its sign dynamically, so performance regressions and improvements display as single, clear signed percentages while preserving the existing table output.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@test/bench-log/_run.mjs`:
- Around line 106-110: Update the cleanup logic in the benchmark runner’s
finally block to await the child process’s "exit" event only when the process is
still running; skip the wait when it has already terminated, while preserving
the existing SIGKILL and file-descriptor cleanup behavior.
- Around line 51-55: Update the imports used by the benchmark sink setup to
include the devNull export from node:os, then change the devnull sink in SINKS
to open devNull instead of hardcoding /dev/null. Preserve the existing sink
names and opening behavior.
---
Nitpick comments:
In `@test/bench-log/_run.mjs`:
- Around line 142-152: Update the throughput formatting in the rows mapping to
avoid hardcoding a negative sign for overhead. Calculate the relative difference
consistently and format its sign dynamically, so performance regressions and
improvements display as single, clear signed percentages while preserving the
existing table output.
In `@test/bench-log/README.md`:
- Around line 28-30: Align the benchmark README paragraph with the formatting
refactor in _run.mjs: if the overhead column is renamed to “change,” update this
paragraph to describe the “change” column and its meaning while preserving the
explanation of the same-sink no-logger baseline and shuffled run order.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro
Run ID: 6f1012e5-c1aa-4dcf-a341-2c7b7193ce6e
📒 Files selected for processing (6)
package.jsonsrc/log.tstest/bench-log/README.mdtest/bench-log/_run.mjstest/bench-log/_server.mjstest/log.test.ts
🚧 Files skipped from review as they are similar to previous changes (2)
- test/log.test.ts
- src/log.ts
There was a problem hiding this comment.
Actionable comments posted: 2
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (2)
src/log.ts (2)
21-24: 🎯 Functional Correctness | 🟠 Major | ⚡ Quick winFix
FORCE_COLORevaluation to correctly disable colors.If
FORCE_COLORis explicitly set to"0"or"false"to disable colors,!!env?.FORCE_COLORwill still evaluate totruebecause non-empty strings are truthy. This results in colors being enabled when they were explicitly requested to be disabled.🐛 Proposed fix
function colorsEnabled(): boolean { const env = globalThis.process?.env; - return !!env?.FORCE_COLOR || env?.NODE_ENV !== "production"; + if (env?.FORCE_COLOR !== undefined) { + return env.FORCE_COLOR !== "0" && env.FORCE_COLOR !== "false" && env.FORCE_COLOR !== ""; + } + return env?.NODE_ENV !== "production"; }🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@src/log.ts` around lines 21 - 24, Update colorsEnabled() so FORCE_COLOR values "0" and "false" explicitly disable colors rather than being treated as truthy strings. Preserve the existing non-production default when FORCE_COLOR is unset, and continue enabling colors for other explicitly enabled values.
36-36: 🩺 Stability & Availability | 🟠 Major | ⚡ Quick winHandle broken stdout writes outside
try/catch.
process.stdout.write()can surfaceEPIPEas an'error'event, so catching synchronous errors won't prevent a closed pipe from crashing the process. Add a shared stdout error handler to safely absorb broken-pipe errors.🔧 Proposed fix
const encoder = /* `@__PURE__` */ new TextEncoder(); const stdout = globalThis.process?.stdout; +stdout?.on?.("error", () => {}); const write: (chunk: string) => boolean = /* `@__PURE__` */ (() => {🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@src/log.ts` at line 36, Update the stdout setup around the `stdout` symbol to register a shared `'error'` event handler that safely absorbs broken-pipe (`EPIPE`) errors, including errors emitted asynchronously by `process.stdout.write()`. Preserve the existing optional-process behavior and avoid relying solely on synchronous try/catch handling.
♻️ Duplicate comments (1)
test/bench-log/_run.mjs (1)
118-122: 🩺 Stability & Availability | 🟠 Major | ⚡ Quick winPrevent the benchmark runner from deadlocking on server crashes.
If the child process crashes prematurely (e.g., port 3000 is already in use, or there is a syntax error in the server),
waitReady()correctly throws after exhausting its retries, routing execution into thisfinallyblock. However, because the child process has already terminated,await once(child, "exit")will wait forever for an event that has already fired, deadlocking the benchmark runner instead of failing gracefully.Check if the process is still running before awaiting its exit.
🔒️ Proposed fix to prevent deadlocks
finally { - child.kill("SIGKILL"); - await once(child, "exit"); // free port 3000 before the next cell + if (child.exitCode === null && child.signalCode === null) { + child.kill("SIGKILL"); + await once(child, "exit"); // free port 3000 before the next cell + } if (fd !== null) closeSync(fd); }🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@test/bench-log/_run.mjs` around lines 118 - 122, Update the cleanup logic in the finally block around child.kill and once(child, "exit") to await the exit event only when the child process is still running; skip the wait when it has already terminated, while preserving the existing kill and file-descriptor cleanup behavior.
🧹 Nitpick comments (1)
src/log.ts (1)
159-159: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low valueStandardize the time string locale.
toLocaleTimeString()without a specified locale uses the system locale, which can result in inconsistent log formats across different environments (e.g., 12-hour vs. 24-hour clock, AM/PM, or non-English characters). Consider using a fixed locale like"en-US"with{ hour12: false }for consistent, predictable log outputs.🛠️ Proposed fix
- cachedTime = gray(`[${new Date(now).toLocaleTimeString()}]`); + cachedTime = gray(`[${new Date(now).toLocaleTimeString("en-US", { hour12: false })}]`);🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@src/log.ts` at line 159, Update the cachedTime assignment in the log timestamp formatting path to call toLocaleTimeString with a fixed locale and hour12: false, ensuring consistent 24-hour log output across environments while preserving the existing gray wrapper and timestamp format.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/log.ts`:
- Line 164: Update the status formatter in the log() flow so each status code’s
formatted chunk is resolved once and reused for the remainder of that log()
call. Cache the result of paint(paintForStatus(code))(code + "") keyed by status
code, while preserving the existing output and per-call cache scope.
In `@test/bench-log/_run.mjs`:
- Around line 60-63: Replace the hardcoded "/dev/null" path in the devnull sink
definition with the cross-platform devNull export from node:os, adding that
import alongside the existing imports while preserving the current openSync
behavior.
---
Outside diff comments:
In `@src/log.ts`:
- Around line 21-24: Update colorsEnabled() so FORCE_COLOR values "0" and
"false" explicitly disable colors rather than being treated as truthy strings.
Preserve the existing non-production default when FORCE_COLOR is unset, and
continue enabling colors for other explicitly enabled values.
- Line 36: Update the stdout setup around the `stdout` symbol to register a
shared `'error'` event handler that safely absorbs broken-pipe (`EPIPE`) errors,
including errors emitted asynchronously by `process.stdout.write()`. Preserve
the existing optional-process behavior and avoid relying solely on synchronous
try/catch handling.
---
Duplicate comments:
In `@test/bench-log/_run.mjs`:
- Around line 118-122: Update the cleanup logic in the finally block around
child.kill and once(child, "exit") to await the exit event only when the child
process is still running; skip the wait when it has already terminated, while
preserving the existing kill and file-descriptor cleanup behavior.
---
Nitpick comments:
In `@src/log.ts`:
- Line 159: Update the cachedTime assignment in the log timestamp formatting
path to call toLocaleTimeString with a fixed locale and hour12: false, ensuring
consistent 24-hour log output across environments while preserving the existing
gray wrapper and timestamp format.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro
Run ID: 5f00a5cf-76e0-4a61-a779-3eb1cd433074
📒 Files selected for processing (5)
src/log.tstest/bench-log/README.mdtest/bench-log/_before.mjstest/bench-log/_run.mjstest/bench-log/_server.mjs
🚧 Files skipped from review as they are similar to previous changes (1)
- test/bench-log/_server.mjs
| process.stdout.isTTY && { name: "terminal", stdio: "inherit" }, | ||
| { name: "pipe", stdio: "pipe" }, | ||
| { name: "devnull", open: () => openSync("/dev/null", "w") }, | ||
| ].filter(Boolean); |
There was a problem hiding this comment.
🩺 Stability & Availability | 🟡 Minor | ⚡ Quick win
Avoid hardcoding /dev/null for better cross-platform compatibility.
Opening /dev/null throws ENOENT on Windows. You can use the built-in devNull export from node:os to seamlessly resolve the correct discard path (/dev/null on POSIX, \\.\NUL on Windows).
🛠️ Proposed fix for cross-platform compatibility
First, update the imports at the top of the file to include devNull:
import { devNull } from "node:os";Then, update the sink definition:
- { name: "devnull", open: () => openSync("/dev/null", "w") },
+ { name: "devnull", open: () => openSync(devNull, "w") },🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@test/bench-log/_run.mjs` around lines 60 - 63, Replace the hardcoded
"/dev/null" path in the devnull sink definition with the cross-platform devNull
export from node:os, adding that import alongside the existing imports while
preserving the current openSync behavior.
2 participants
The
log()middleware calledconsole.logonce per request and rebuilt anIntl-backed timestamp every time. This buffers lines and flushes once per event-loop turn, caches the timestamp, and stops emitting colors in production.Changes
setImmediate, orqueueMicrotaskwhere it's unavailable) instead of oneconsole.logper request. Under real concurrency many requests completing in the same turn share a single write. Adrain-based backpressure path keeps a slow stdout from growing the buffer without bound.toLocaleTimeString()is Intl-backed and cost more than the rest of the line combined, yet its second-resolution output changes only once a second — so it's built once per second, not once per request.docker -t, systemd) still got them. Resolved perlog()call (the CLI setsNODE_ENVafter this module is imported);FORCE_COLORoverrides.Output is byte-identical to before. A line still buffered at process exit is flushed synchronously from an
exithook.Benchmark
(removed in 78875ce to simplify diff)
pnpm bench:logdrives a real server withohaat 64 connections and compares three servers — no logger, the previousconsole.log-per-request logger (vendored verbatim from the pre-change commit,_before.mjs), and the currentlog()— across the sinks logs actually go to. Batching only shows under real concurrency, so an in-process loop can't measure it.RPS for each logger, with its overhead versus
no loggerin parentheses:terminalpipedevnullterminal(a real TTY) is the worst case for the old logger — a synchronous coloredconsole.logper request blocks on the terminal's rendering. It gave up 34% of throughput; the current logger gives up 12%.pipe(logs streamed to a collector) is the production shape: +16.7%.devnullisolates the CPU/formatting cost — the timestamp cache — from any I/O: +22.6%.The
terminalfigure depends on the terminal emulator's rendering speed, so it's less reproducible thanpipe/devnull; run-to-run noise is a few percent throughout.Notes
log()call, not at module scope — the CLI assignsNODE_ENVafter importing this module, so a module-level check reads it too early.process.stdout; workers fall back toconsole.log.log()tests F46 asks for (the module had zero coverage).log.ts:4item — colors are gated andconsole.logis no longer hard-coded;LogOptionsstill has no sink option, so that item stays open.pnpm testgreen, lint and types clean.🤖 Generated with Claude Code