Skip to content

perf(logs): skip the log-payload PII walk when PII sanitization is off - #14918

Closed
QuangBlue wants to merge 1 commit into
cheaper-inference:release/v3.8.51from
QuangBlue:perf/pii-walk-short-circuit
Closed

QuangBlue wants to merge 1 commit into
cheaper-inference:release/v3.8.51from
QuangBlue:perf/pii-walk-short-circuit

Conversation

@QuangBlue

Copy link
Copy Markdown
Contributor

Problem

On a busy instance the event loop stalled for 0.3–2 s per large request (300–800 KB bodies). A production inspector CPU profile taken at peak (4 × 90 s) showed:

  • 32% of main-thread busy time went to isFeatureFlagEnabled("PII_RESPONSE_SANITIZATION"), called from sanitizePayloadPII.
  • The same walk deep-copied the whole payload, which was about 40% of all allocations.

Fix

  • sanitizePayloadPII resolves the flag once per payload and returns the payload untouched when it is off.
  • redactPayload still copies the payload and describes binary values, so the logged output is byte-for-byte the same.
  • With the flag on, behavior is unchanged.

Result in production (same profile method, after deploy)

  • protectPayloadForLog: 43.2% → 7.0% of main-thread busy time; flag lookups: 32.2% → 0.8%.
  • Main-thread CPU per 1M input tokens: 24.1 s → 12.4 s.
  • At matched load (same request MB/min bins as the morning peak):
    • time spent in event-loop stalls fell from 42% to 11%;
    • streams of 512 KB or more now open at the 1 s keepalive, with header p90 going from 5.6 s to 1.3 s.

Tests

  • New tests/unit/log-payload-pii-short-circuit.test.ts: with the flag off, the payload is returned without being walked and the logged output is unchanged; enabling the flag through env or the DB override still sanitizes. 2 of its 4 tests fail on release/v3.8.51 @ 7d23bcf8e; all 4 pass with the fix.
  • 47 related log, PII and usage files (354 tests) pass, except 2 failures that are identical on the base: the call-log orphan cleanup test and fix(backend): usage_history stores provider aliases verbatim, splitting telemetry between alias and canonical id #13459.
  • typecheck:core, check-open-sse-typecheck and check-api-typecheck show only the errors already present on the base.

⚠️ base-red inherited: #14866

sanitizePayloadPII deep-copied every log payload and resolved the
PII_RESPONSE_SANITIZATION flag from SQLite once per string, even though the
flag is off by default (Hard Rule cheaper-inference#20). The live pending-request preview runs
protectPayloadForLog on the full request body at every stage update, so in a
production inspector profile (4 x 90 s at peak) these per-string flag lookups
were ~32% of the router's main-thread busy time, blocking the event loop for
0.3-2 s on 300-800 KB requests.

Resolve the flag once per payload and return the payload untouched when it is
off; redactPayload still copies it and describes binary values, so the logged
output is unchanged. After deploying this, the same profile showed
protectPayloadForLog at 7% of busy time (was 43%) and time spent in event-loop
stalls fell from 42% to 11% at matched load.
@QuangBlue
QuangBlue force-pushed the perf/pii-walk-short-circuit branch from 765a609 to 5c93fc2 Compare September 27, 2026 04:48
@QuangBlue

Copy link
Copy Markdown
Contributor Author

Closing: superseded by #14535, which landed on release/v3.8.51 after the base I branched from and fixes the same per-string flag lookup. The regression tests from this PR pass against #14535 unchanged.

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.

1 participant