Repository navigation
chore(perf): add deterministic request-body heap benchmark (#7847) - #8549
diegosouzapw merged 1 commit into
Conversation
|
Thanks for this — verified it end to end (checked out the branch, ran the test suite and the benchmark itself). Confirmed:
One small, non-blocking note for later: the migration bootstrap logs ("[Migration] Skipped executing ...") still leak to stdout when running Also worth knowing (not something to change here): #8550, #8553 and #8558 are already open and map 1:1 to the three mechanisms in your table, so this reads as the intended groundwork for that sequence rather than a standalone tool. |
…apw#7847) diegosouzapw#7847 reports a 3.05 MiB request (729 messages / 86 tools) reaching ~12,282 MiB of V8 heap, and asks for "a regression benchmark that records peak heap for representative 500-800-message, tool-rich requests" before any fix lands. There is currently no memory baseline in the repo at all (bench:compression is the only benchmark), so a clone-reduction change could neither be justified nor regression-guarded. npm run bench:heap-body attributes retained heap to each copy the chat path makes: | mechanism | call site | retained | x wire | | cloneLogPayload (unbounded) | chat.ts buildClientRawRequest | 3.18 MiB | 1.04x | | cloneBoundedForLog (bounded) | requestLogger.logClientRawRequest | 0.04 MiB | 0.01x | | structuredClone x3 (combo targets) | combo.ts attemptBody | 9.53 MiB | 3.12x | | JSON.stringify (token estimate) | combo.ts estimateTokens | 3.06 MiB | 1.00x | | per request (sum) | |15.81 MiB | 5.17x | It measures the real production helpers rather than reimplementations, so a change to the log bounds or the clone strategy is reflected directly. Design notes: - Deterministic: fixed-seed LCG, no Math.random(). Verified byte-identical across three consecutive runs — without that, a before/after delta measures noise, not the change. - Corpus lives in its own side-effect-free module so the unit test can import it without booting SQLite (requestLogger transitively opens the DB at import time). - Hermetic: DATA_DIR is redirected to a temp dir before importing, so the benchmark never touches the operator's real ~/.omniroute store. - Node, not bun: --expose-gc and V8 heap accounting are the measurement; another engine's heap number would not describe the production runtime. - --max-retained-mib exits non-zero, so this can become a CI gate once a target is agreed. Reports only; wires nothing into CI and changes no production code.
2e15ff7 to
21c81b4
Compare
…ut building it (diegosouzapw#7847) Two changes with one root cause: several hot paths built a full JSON string only to read its .length, and one of them silently changed the answer. 1. CORRECTNESS -- combo's fallback-compression trigger estimateTokens(JSON.stringify(attemptBody)) took the STRING branch of estimateTokens, which is ceil(length / CHARS_PER_TOKEN) over the raw JSON. An inline base64 image is then charged as if every character of the data URL were prose. Measured on a 200 KB inline image: via string (before) 50,039 tokens via object (after) 1,231 tokens a 40x over-count, tripping fallback compression on requests nowhere near the context window. This is the same class diegosouzapw#8368/diegosouzapw#8401 fixed on the request path; the combo call site was missed. Passing the object routes through extractImageTokens, which charges images structurally. Text-only bodies are unaffected -- verified identical, and pinned by a test. 2. ALLOCATION -- jsonLength() Adds an exact serialized-length walker: same O(n) scan, no string. Used by estimateTokens' object branch and by streamReadinessPolicy (which runs on every streaming request and only ever used .length). Exactness matters because every consumer feeds a threshold, so this is property-tested against JSON.stringify over 4000 generated structures covering escaping, lone surrogates, omitted values, non-finite numbers, toJSON, Date, Map, cycles and BigInt. Anything outside the plain-JSON subset falls back to JSON.stringify for THAT SUBTREE only, so an exotic leaf never forces the message history back onto the allocating path. Honest scoping of the memory win: the string was always transient, and V8 collects it efficiently, so this is not 3 MiB of retained heap. Measured allocation churn over 20 calls on a 3.06 MiB body: 3.1 MiB -> 0.5 MiB, about 6x less. The diegosouzapw#8549 benchmark row for this mechanism measures a HELD string and therefore overstates it; the correctness fix above is the larger deliverable here.
|
Rebased onto On the migration-log leak: confirmed, the console parking doesn't cover the migration bootstrap's own writes. It's outside the measured region so none of the reported numbers move, and I left it rather than widening a benchmark-only PR — say the word if you'd rather it not ship noisy and I'll fold in the fix. And yes, #8550/#8553/#8558 are the three mechanisms from the table — this was the groundwork, not a standalone tool. |
|
Correction to my comment above: I measured it on pristine detached checkouts with an empty working tree: The gate is in |
…ut building it (#7847) (#8558) Two changes with one root cause: several hot paths built a full JSON string only to read its .length, and one of them silently changed the answer. 1. CORRECTNESS -- combo's fallback-compression trigger estimateTokens(JSON.stringify(attemptBody)) took the STRING branch of estimateTokens, which is ceil(length / CHARS_PER_TOKEN) over the raw JSON. An inline base64 image is then charged as if every character of the data URL were prose. Measured on a 200 KB inline image: via string (before) 50,039 tokens via object (after) 1,231 tokens a 40x over-count, tripping fallback compression on requests nowhere near the context window. This is the same class #8368/#8401 fixed on the request path; the combo call site was missed. Passing the object routes through extractImageTokens, which charges images structurally. Text-only bodies are unaffected -- verified identical, and pinned by a test. 2. ALLOCATION -- jsonLength() Adds an exact serialized-length walker: same O(n) scan, no string. Used by estimateTokens' object branch and by streamReadinessPolicy (which runs on every streaming request and only ever used .length). Exactness matters because every consumer feeds a threshold, so this is property-tested against JSON.stringify over 4000 generated structures covering escaping, lone surrogates, omitted values, non-finite numbers, toJSON, Date, Map, cycles and BigInt. Anything outside the plain-JSON subset falls back to JSON.stringify for THAT SUBTREE only, so an exotic leaf never forces the message history back onto the allocating path. Honest scoping of the memory win: the string was always transient, and V8 collects it efficiently, so this is not 3 MiB of retained heap. Measured allocation churn over 20 calls on a 3.06 MiB body: 3.1 MiB -> 0.5 MiB, about 6x less. The #8549 benchmark row for this mechanism measures a HELD string and therefore overstates it; the correctness fix above is the larger deliverable here.
|
Thanks @MumuTW — merged into |
…ut building it (diegosouzapw#7847) (diegosouzapw#8558) Two changes with one root cause: several hot paths built a full JSON string only to read its .length, and one of them silently changed the answer. 1. CORRECTNESS -- combo's fallback-compression trigger estimateTokens(JSON.stringify(attemptBody)) took the STRING branch of estimateTokens, which is ceil(length / CHARS_PER_TOKEN) over the raw JSON. An inline base64 image is then charged as if every character of the data URL were prose. Measured on a 200 KB inline image: via string (before) 50,039 tokens via object (after) 1,231 tokens a 40x over-count, tripping fallback compression on requests nowhere near the context window. This is the same class diegosouzapw#8368/diegosouzapw#8401 fixed on the request path; the combo call site was missed. Passing the object routes through extractImageTokens, which charges images structurally. Text-only bodies are unaffected -- verified identical, and pinned by a test. 2. ALLOCATION -- jsonLength() Adds an exact serialized-length walker: same O(n) scan, no string. Used by estimateTokens' object branch and by streamReadinessPolicy (which runs on every streaming request and only ever used .length). Exactness matters because every consumer feeds a threshold, so this is property-tested against JSON.stringify over 4000 generated structures covering escaping, lone surrogates, omitted values, non-finite numbers, toJSON, Date, Map, cycles and BigInt. Anything outside the plain-JSON subset falls back to JSON.stringify for THAT SUBTREE only, so an exotic leaf never forces the message history back onto the allocating path. Honest scoping of the memory win: the string was always transient, and V8 collects it efficiently, so this is not 3 MiB of retained heap. Measured allocation churn over 20 calls on a 3.06 MiB body: 3.1 MiB -> 0.5 MiB, about 6x less. The diegosouzapw#8549 benchmark row for this mechanism measures a HELD string and therefore overstates it; the correctness fix above is the larger deliverable here.
…apw#7847) (diegosouzapw#8549) diegosouzapw#7847 reports a 3.05 MiB request (729 messages / 86 tools) reaching ~12,282 MiB of V8 heap, and asks for "a regression benchmark that records peak heap for representative 500-800-message, tool-rich requests" before any fix lands. There is currently no memory baseline in the repo at all (bench:compression is the only benchmark), so a clone-reduction change could neither be justified nor regression-guarded. npm run bench:heap-body attributes retained heap to each copy the chat path makes: | mechanism | call site | retained | x wire | | cloneLogPayload (unbounded) | chat.ts buildClientRawRequest | 3.18 MiB | 1.04x | | cloneBoundedForLog (bounded) | requestLogger.logClientRawRequest | 0.04 MiB | 0.01x | | structuredClone x3 (combo targets) | combo.ts attemptBody | 9.53 MiB | 3.12x | | JSON.stringify (token estimate) | combo.ts estimateTokens | 3.06 MiB | 1.00x | | per request (sum) | |15.81 MiB | 5.17x | It measures the real production helpers rather than reimplementations, so a change to the log bounds or the clone strategy is reflected directly. Design notes: - Deterministic: fixed-seed LCG, no Math.random(). Verified byte-identical across three consecutive runs — without that, a before/after delta measures noise, not the change. - Corpus lives in its own side-effect-free module so the unit test can import it without booting SQLite (requestLogger transitively opens the DB at import time). - Hermetic: DATA_DIR is redirected to a temp dir before importing, so the benchmark never touches the operator's real ~/.omniroute store. - Node, not bun: --expose-gc and V8 heap accounting are the measurement; another engine's heap number would not describe the production runtime. - --max-retained-mib exits non-zero, so this can become a CI gate once a target is agreed. Reports only; wires nothing into CI and changes no production code.
…ut building it (diegosouzapw#7847) (diegosouzapw#8558) Two changes with one root cause: several hot paths built a full JSON string only to read its .length, and one of them silently changed the answer. 1. CORRECTNESS -- combo's fallback-compression trigger estimateTokens(JSON.stringify(attemptBody)) took the STRING branch of estimateTokens, which is ceil(length / CHARS_PER_TOKEN) over the raw JSON. An inline base64 image is then charged as if every character of the data URL were prose. Measured on a 200 KB inline image: via string (before) 50,039 tokens via object (after) 1,231 tokens a 40x over-count, tripping fallback compression on requests nowhere near the context window. This is the same class diegosouzapw#8368/diegosouzapw#8401 fixed on the request path; the combo call site was missed. Passing the object routes through extractImageTokens, which charges images structurally. Text-only bodies are unaffected -- verified identical, and pinned by a test. 2. ALLOCATION -- jsonLength() Adds an exact serialized-length walker: same O(n) scan, no string. Used by estimateTokens' object branch and by streamReadinessPolicy (which runs on every streaming request and only ever used .length). Exactness matters because every consumer feeds a threshold, so this is property-tested against JSON.stringify over 4000 generated structures covering escaping, lone surrogates, omitted values, non-finite numbers, toJSON, Date, Map, cycles and BigInt. Anything outside the plain-JSON subset falls back to JSON.stringify for THAT SUBTREE only, so an exotic leaf never forces the message history back onto the allocating path. Honest scoping of the memory win: the string was always transient, and V8 collects it efficiently, so this is not 3 MiB of retained heap. Measured allocation churn over 20 calls on a 3.06 MiB body: 3.1 MiB -> 0.5 MiB, about 6x less. The diegosouzapw#8549 benchmark row for this mechanism measures a HELD string and therefore overstates it; the correctness fix above is the larger deliverable here.
…apw#7847) (diegosouzapw#8549) diegosouzapw#7847 reports a 3.05 MiB request (729 messages / 86 tools) reaching ~12,282 MiB of V8 heap, and asks for "a regression benchmark that records peak heap for representative 500-800-message, tool-rich requests" before any fix lands. There is currently no memory baseline in the repo at all (bench:compression is the only benchmark), so a clone-reduction change could neither be justified nor regression-guarded. npm run bench:heap-body attributes retained heap to each copy the chat path makes: | mechanism | call site | retained | x wire | | cloneLogPayload (unbounded) | chat.ts buildClientRawRequest | 3.18 MiB | 1.04x | | cloneBoundedForLog (bounded) | requestLogger.logClientRawRequest | 0.04 MiB | 0.01x | | structuredClone x3 (combo targets) | combo.ts attemptBody | 9.53 MiB | 3.12x | | JSON.stringify (token estimate) | combo.ts estimateTokens | 3.06 MiB | 1.00x | | per request (sum) | |15.81 MiB | 5.17x | It measures the real production helpers rather than reimplementations, so a change to the log bounds or the clone strategy is reflected directly. Design notes: - Deterministic: fixed-seed LCG, no Math.random(). Verified byte-identical across three consecutive runs — without that, a before/after delta measures noise, not the change. - Corpus lives in its own side-effect-free module so the unit test can import it without booting SQLite (requestLogger transitively opens the DB at import time). - Hermetic: DATA_DIR is redirected to a temp dir before importing, so the benchmark never touches the operator's real ~/.omniroute store. - Node, not bun: --expose-gc and V8 heap accounting are the measurement; another engine's heap number would not describe the production runtime. - --max-retained-mib exits non-zero, so this can become a CI gate once a target is agreed. Reports only; wires nothing into CI and changes no production code.
Groundwork for #7847. Reports only — no production code changes, nothing wired into CI.
Why first
#7847 asks for "a regression benchmark that records peak heap for representative 500–800-message, tool-rich requests". The repo currently has no memory baseline at all (
bench:compressionis the only benchmark), so a clone-reduction change could neither be justified nor regression-guarded. This lands the measurement before the fix.What it measures
npm run bench:heap-bodyreproduces the incident shape (3.05 MiB / 729 messages / 86 tools) and attributes retained V8 heap to each copy the chat path makes:chat.ts buildClientRawRequestrequestLogger.logClientRawRequestcombo.ts attemptBodycombo.ts estimateTokens8 concurrent requests retain 25.42 MiB via the entry clone alone.
It calls the real production helpers, not reimplementations, so changing the log bounds or the clone strategy shows up directly in the numbers.
What the first numbers already say
Two things worth flagging for whoever picks up the fix:
The entry clone is provably oversized.
buildClientRawRequestretains 3.18 MiB; everything downstream of it either discards the value (logClientRawRequestis a no-op when the logger is disabled) or re-clones it bounded into 0.04 MiB. That is ~80x more than any consumer keeps. I traced all three consumers (logClientRawRequest,trackPendingRequestsclientRequest,recordRejectedRequestUsagesrequestBody) — every one is observability; none feeds dispatch, translation or the upstream request.But it is not the biggest mechanism.
combo.tsper-targetattemptBodyclones cost 9.53 MiB at only 3 targets — 3x the entry clone. Any ordering that starts with the entry clone should be honest that it is the cheapest and safest win, not the largest one.Design notes
Math.random(). Verified byte-identical across three consecutive runs; without that a before/after delta measures noise rather than the change.requestLoggertransitively opens the DB at import time).DATA_DIRis redirected to a temp dir before importing, so the benchmark never touches the operator real~/.omniroutestore.--expose-gcand V8 heap accounting are the measurement; another engine heap number would not describe the production runtime. (Per CLAUDE.md, bun stays limited to its allow-listed gate/generator scripts.)--max-retained-mibexits non-zero, so this can become a CI gate once a target is agreed. Left out of CI deliberately for now — there is no agreed budget yet.Verification
tests/unit/heap-benchmark-corpus.test.ts— 5/5 pass: byte-stability across runs and across module instances, incident wire size (~3.05 MiB), agent-request shape, and that the size knobs actually scaletypecheck:core,check:docs-sync,check:any-budget:t11— cleanscripts/is eslint-ignored (same as the existingbench:compression); the new test file is linted and error-freeInherited base-red (not from this PR)
release/v3.8.49is red on two gates this branch does not touch: lint (stale suppression count, fixed by #8544) and file-size (providers/page.tsx,tokenHealthCheck.ts— fixed by #8532 / #8524).