Skip to content

perf(ui): stop dumping delegate payloads to the console at startup - #570

Open
sanity wants to merge 2 commits into
mainfrom
perf-startup-render
Open

perf(ui): stop dumping delegate payloads to the console at startup#570
sanity wants to merge 2 commits into
mainfrom
perf-startup-render

Conversation

@sanity

@sanity sanity commented Jul 30, 2026

Copy link
Copy Markdown
Contributor

Problem

Users reported the UI feeling slow/laggy. I profiled the published UI (web-container 30000369) on a real NATed peer with Playwright, measuring per interaction rather than in aggregate.

The cost is startup. Everything else measured clean:

phase result
startup ~1.75s main-thread blocking, ~12 long tasks, worst ~270ms; rooms usable at ~1.5-2.4s
idle 30s 0.2% CPU, 0 long tasks, 0 DOM mutations
scroll 0 janky frames of 170, p95 16.7ms
room switch ~0.1-0.7s

Then a census of console output grouped by source site found one line is 98.5% of all bytes River emits during startup:

response_handler.rs  "Successfully deserialized as ChatDelegateResponseMsg: {:?}"

ChatDelegateResponseMsg's Debug prints a ListResponse's keys as decimal byte arrays. On a real account: 39 lines averaging ~401 KB each, 14.93 MB of the 15.15 MB total (1,034 messages).

Approach

Summarise instead of Debug-dumping. describe_delegate_response keeps everything the logs were actually used for — variant, key names, sizes, ok/err — and prints keys as the text they are (outbound_dms, rooms_meta, room:<vk>), falling back to a length for genuinely binary keys. Plus:

  • payload logged as {} bytes rather than up to 100 decimal bytes
  • DelegateKey logged as a 4-byte fingerprint rather than a 32-byte decimal array, at both sites

No log levels changed. My first instinct was to drop release_max_level_info, and the census is why I didn't: that would delete every field diagnostic to fix what turned out to be four call sites — including the Timeout waiting for delegate response warnings that are worth keeping (see below).

Expected effect — a prediction, not a measurement

An A/B that suppressed the app's console entirely removed ~29% of startup blocking (3371ms → 2405ms, mean of 3 paired runs, the counting shim present in both arms so its cost is controlled).

This change removes ~98.5% of the bytes but only 39 of ~1,034 calls. So:

  • if the cost is dominated by bytes and formatting, the gain should be most of that 29%
  • if it is dominated by per-call overhead, considerably less

The 39 lines also cost roughly 15.6 MB of String building inside WASM, which no console setting avoids, so I expect the former. I will re-run the census and the A/B after publish and post the actual numbers here rather than leave the prediction standing.

Testing

Five new tests:

  • key names present and byte arrays absent in a ListResponse summary
  • the summary grows with key-name length, not byte-array length
  • values reported as sizes, never contents
  • binary (non-UTF-8) keys fall back to a length
  • a regression pin that fails if either the Debug dump or the byte-array payload log returns, mutation-verified: restoring {:?} on the response makes it red

Also found while profiling, not fixed here

Startup consistently logs Failed to store signing key in delegate: Timeout waiting for delegate response - using local signing and Skipping EnsureRoomSubscription. Delegate round-trips are timing out during load and the app falls back to local signing. That is correctness-adjacent, not just slow, and is consistent with #425, whose burst is now 78 serial requests (26 legacy generations x 3) and whose localStorage "done" gate cannot persist in the sandboxed gateway iframe (opaque origin), so hosted users may re-arm it on every load.

Interaction-time cost is real but tracked separately and not addressed here: #523 (inline closures defeat MessageGroupComponent memoization), #554 (~200 Ed25519 verifies per render via can_participate()), plus an unconditional ~343 KB RoomData deep clone at the top of every Conversation render and no Intl.DateTimeFormat cache. Those are correctness-adjacent enough to deserve their own review rather than riding along with a logging change.

Corrections to my own earlier numbers

  • An initial profiler run reported 6.8s blocking / 75.8% CPU. Wrong — inflated roughly 4x by my own CPU sampler (200µs) plus a document-wide MutationObserver. The ~1.75s figure above is from a clean run.
  • An initial "~3.1s room switch" was a fixed settle-sleep in my harness, not app cost.

Profilers: framework:~/river-freeze-monitor/{profile_ui.py,ab_startup.py,log_census.py}.

Refs #569

[AI-assisted - Claude]

sanity added 2 commits July 30, 2026 08:22
Users reported the UI feeling slow. Profiling the published UI on a real
NATed peer put the cost in startup, and a census of console output by
source site found ONE line responsible for 98.5% of all bytes River emits
while starting:

  response_handler.rs  "Successfully deserialized as ChatDelegateResponseMsg: {:?}"

`ChatDelegateResponseMsg`'s Debug prints a `ListResponse`'s keys as decimal
byte arrays. Measured on a real account: 39 of those lines averaging
~401 KB each, 14.93 MB of the 15.15 MB total. The per-key bytes were never
what anyone read; the variant, the key NAMES and the sizes are.

Replaced with `describe_delegate_response`, which keeps all of that and
prints keys as the text they actually are (`outbound_dms`, `rooms_meta`,
`room:<vk>`), falling back to a length for genuinely binary keys. Also:

- payload logged as `{} bytes` instead of up to 100 decimal bytes
- `DelegateKey` logged as a 4-byte fingerprint instead of a 32-byte
  decimal array, at both sites that did it

No log LEVELS changed. An earlier plan was to drop
`release_max_level_info`, but the census showed that would delete every
field diagnostic to fix what is really four call sites -- including the
`Timeout waiting for delegate response` warnings that are worth keeping.

Expected effect, stated as a prediction to verify after publish rather
than a claim: an A/B that suppressed the app's console entirely removed
~29% of startup main-thread blocking (3371ms -> 2405ms, mean of 3 paired
runs). This removes ~98.5% of the bytes but only 39 of ~1034 calls, so if
the cost is per-byte and per-format the gain should be most of that 29%;
if it is per-call, less. The 39 lines also cost ~15.6 MB of String
building inside WASM, which no console setting avoids.

Testing: 5 new tests. Four behavioural (key names present, bytes absent,
values reported as sizes, binary keys fall back to a length, and the
summary grows with name length rather than byte-array length), plus a
regression pin that fails if the Debug dump or the byte-array payload log
returns. The pin is mutation-verified: restoring `{:?}` on the response
makes it red.

Refs #569
Review of PR #570 found the fix reintroduced the defect it removes, plus
several sharper points. All acted on.

BLOCKING, and it was real: the `CasStoreResponse` arm still Debug-formatted
`CasStoreResult`, whose `Conflict` variant carries `current_value:
Option<Vec<u8>>` -- the FULL stored blob. A per-room blob is ~343 KB in
memory, so ~4x that as a decimal array: a BIGGER line than the ~383 KB one
being removed, and `cas_write_delegate_key` retries, so a contended save
emits several. The adjacent processing code already destructures this
correctly; it now matches. My first attempt at this fix silently failed to
apply (whitespace drift after rustfmt) and the new test caught it, which is
the test earning its place.

Also:

- Removed the catch-all match arm. It was reachable TODAY --
  `EnsureRoomSubscriptionResponse` is a tenth variant and is live in this
  file -- so the "future variants only log a discriminant" comment was
  false in the present tense. Worse, `format!("{other:?}")` builds the
  whole Debug string in WASM before discarding it, which is the cost this
  PR argues matters. The match is now exhaustive, so the next
  blob-carrying variant is a COMPILE error rather than a silent regression.
  A source pin cannot see a variant that does not exist yet; the compiler
  can.

- Corrected the causal attribution. I wrote that the 39 huge lines were
  `ListResponse` key arrays. The arithmetic does not support that: a
  `room:<bs58>` key Debug is ~210 chars, so 401 KB would need ~1,900 keys
  on one line, and `ListRequest` fires once per delegate, not 39 times.
  Startup fires one GetRequest PER ROOM, so ~39 `GetResponse`s each
  carrying a per-room blob fits the line count and size far better. Every
  variant logs at that one site; the census grouped by source line, not by
  variant. Comment and PR body corrected. The average is ~383 KB
  (14.93 MB / 39), not the ~401 KB I stated.

- Kept a short hex head on the deser-FAILURE branch only. That was the one
  genuine diagnostic loss: when decode fails there is no variant summary,
  and size alone cannot distinguish a wire-format break from a corrupt
  frame -- the exact class bug-prevention-patterns.md records from the
  v0.2.11 incident. Zero happy-path cost.

- Bounded the worst case structurally: key text capped at 128 chars, key
  lists at 50 names plus "and N more". Unbounded-in-the-same-variable is
  what this PR exists to fix.

- Downgraded per-value developer tracing to `debug!` (compiles out under
  `release_max_level_info`). That addresses the OTHER branch of my own
  caveat -- per-call overhead across ~1,034 calls -- at zero release cost,
  without touching the global log level.

- One `delegate_key_fp`, `pub(crate)`, used at both sites instead of a
  duplicated inline hex head; dropped the always-"32B" suffix. Hex not
  base58 so a fingerprint greps against `legacy_delegates.toml`.

- Tests: added the CAS-blob regression test (mutation-verified), switched
  the scaling test to compare against the Debug length rather than an
  absolute bound (which would also pass for a helper that dropped names
  entirely), fixed 39->42 chars, pinned the payload log on `payload_str`
  rather than a format string that a reformat could evade, and moved the
  source cut to this file's `mod tests {` idiom.

Refs #569
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