perf(ui): stop dumping delegate payloads to the console at startup - #570
Open
sanity wants to merge 2 commits into
Open
perf(ui): stop dumping delegate payloads to the console at startup#570sanity wants to merge 2 commits into
sanity wants to merge 2 commits into
Conversation
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
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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:
Then a census of console output grouped by source site found one line is 98.5% of all bytes River emits during startup:
ChatDelegateResponseMsg'sDebugprints aListResponse'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_responsekeeps 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:{} bytesrather than up to 100 decimal bytesDelegateKeylogged as a 4-byte fingerprint rather than a 32-byte decimal array, at both sitesNo 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 theTimeout waiting for delegate responsewarnings 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:
The 39 lines also cost roughly 15.6 MB of
Stringbuilding 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:
ListResponsesummaryDebugdump or the byte-array payload log returns, mutation-verified: restoring{:?}on the response makes it redAlso found while profiling, not fixed here
Startup consistently logs
Failed to store signing key in delegate: Timeout waiting for delegate response - using local signingandSkipping 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
MessageGroupComponentmemoization), #554 (~200 Ed25519 verifies per render viacan_participate()), plus an unconditional ~343 KBRoomDatadeep clone at the top of everyConversationrender and noIntl.DateTimeFormatcache. Those are correctness-adjacent enough to deserve their own review rather than riding along with a logging change.Corrections to my own earlier numbers
MutationObserver. The ~1.75s figure above is from a clean run.Profilers:
framework:~/river-freeze-monitor/{profile_ui.py,ab_startup.py,log_census.py}.Refs #569
[AI-assisted - Claude]