Skip to content

feat(desktop): add temporary renderer profiling harness - #6162

Draft
wpfleger96 wants to merge 5 commits into
mainfrom
duncan/renderer-profiling-harness
Draft

feat(desktop): add temporary renderer profiling harness#6162
wpfleger96 wants to merge 5 commits into
mainfrom
duncan/renderer-profiling-harness

Conversation

@wpfleger96

@wpfleger96 wpfleger96 commented Aug 17, 2026

Copy link
Copy Markdown
Member

This branch is diagnostic and never merges. It exists so Will can build it, drive Buzz for a day of normal usage, and hand back a local JSONL capture that adjudicates where the renderer's felt lag actually goes. When analysis is done, the branch dies. Nothing here is transmitted, no analytics endpoint, no network — the only output is a local file in the app data dir.

What this adds

A passive, always-on renderer profiling harness. Records are ring-buffered in memory and flushed as JSONL to <app-data>/profiling/session-<ts>.jsonl every ~30s and on pagehide. The output lets us produce a ranked breakdown of wall-clock time during felt lag: renderer main-thread stalls vs. waiting on Rust IPC vs. waiting on the relay vs. accumulator growth.

New, self-contained:

  • desktop/src/shared/profiling/{types.ts, drift.ts, recorder.ts, harness.ts, ipc.ts, tauriCoreProxy.ts, viteTauriCoreProxy.ts, harness.test.mjs, viteResolve.test.mjs}
  • desktop/src-tauri/src/commands/profiling_log.rs (append-to-local-file command)

Additive touch points only (no production code restructured):

  • commands/mod.rs, lib.rs — register append_profiling_log
  • App.tsx — one startProfilingHarness(queryClient) call in CommunityQueryProvider
  • observerRelayStore.ts — one additive getObserverStoreCensus() accessor (reads .length/.size only, zero allocation)

The four probes

  1. Main-thread stalls + input latency. A 500ms drift timer records stall when observed-minus-expected fire exceeds 50ms (WebKit has no Long Tasks API). Drift is scored only for intervals that both begin and end in the visible, focused foreground — a hidden/occluded/asleep webview defers timers, and that deferral must never be attributed to renderer work; the baseline is re-armed across background windows so the first foreground interval after a return cannot manufacture a phantom stall. A capture-phase keydown/pointerdown listener records input when total felt latency exceeds 100ms. The listener captures its own receipt clock (performance.now()) synchronously, so latency is receipt → next painted frame on a single clock basis; the pre-dispatch/OS-queue delay (event.timeStamp → receipt) is split into a separate queued field, dropped to null when that delta is implausible (a cross-clock basis mismatch). These directly measure Will's felt symptoms.
  2. IPC / Rust backend. Records ipc (name + duration + outcome) for every invoke, and ipc_pending for any invoke outstanding >10s — the deadlock detector Will asked for.
  3. Relay waits. Records relay_req (REQ→EOSE) for history fetches and relay_pub (send→ack) for publishes.
  4. Accumulator census. Every ~2 min, records census: observer store sizes, archive totals, transcript count, React Query cache entry count, DOM node count. Retroactively adjudicates whether accumulator growth correlates with lag (i.e. whether the deferred perf(desktop): bound renderer in-memory retention with LRU eviction #5596 was the root cause).

Probe 2 interception mechanism + coverage

invokeTauri() in shared/api/tauri.ts is not the only IPC path — ~30 files import raw invoke/isTauri/Channel from @tauri-apps/api/core directly (heaviest: relayClientSession.ts, terminalClient.ts, huddle files, hostedCommunityApi.ts), every bundled Tauri plugin (plugin-opener, plugin-process, …) imports invoke from that same specifier, and Tauri's own API submodules (@tauri-apps/api/{event,app,window,webview}, ~35 source sites — plugin:event|*, plugin:app|*, plugin:window|*, plugin:webview|*) reach core through the relative import ./core.js. The harness intercepts at the module layer, not the window property: a pre-enforced Vite resolveId hook (shared/profiling/viteTauriCoreProxy.ts) redirects both the bare @tauri-apps/api/core specifier and the relative ./core.js reached from inside @tauri-apps/api/* to shared/profiling/tauriCoreProxy.ts, which re-exports the real core surface (export *) and overrides only invoke with a profiling wrapper. The proxy reaches the real module through the @tauri-core-impl specifier, which the same hook maps straight to the actual core.js — the non-recursive escape hatch. A bare alias could not see the relative form, so submodule IPC would silently bypass the probe; the resolver closes that. One hook covers all raw importers, invokeTauri(), every bundled plugin, and every built-in submodule.

This seam is mandatory on native: Tauri 2.11.5's injected core.js defines window.__TAURI_INTERNALS__.invoke with Object.defineProperty(..., { value: fn }) and no flags, so it is non-configurable and non-writable — any redefine or assignment throws TypeError and (through the harness's catch) would silently abort every probe. The real core module dereferences window.__TAURI_INTERNALS__.invoke per call (core.js:202), so the module wrapper closes over the real invoke function and never writes the window property at all — passive against native, terminal-accessor, and mockIPC shapes alike. The wrapper reports to the harness's observer once startProfilingHarness registers it, and is a transparent pass-through until then (the proxy loads before the harness starts). The IPC probe's own invoke("append_profiling_log", ...) also routes through it, so flush writes appear in the capture (trivially filterable by cmd). The pure decision logic lives in shared/profiling/ipc.ts (import-light, unit-tested against the native non-configurable descriptor shape) and shared/profiling/viteTauriCoreProxy.ts (the resolver predicate, unit-tested plus a real Vite resolve-graph test that proves a raw-core import, an external-plugin import, and a built-in submodule's relative ./core.js each resolve through the proxy once, with the escape resolving to the real module).

Each probe now installs under its own guard in startProfilingHarness, so one probe failing to install can never abort the others.

Relay probe: singleton wrap, not source edits

The relay probe wraps the relayClient singleton's public methods from harness.ts rather than editing relayClientSession.ts. Two reasons: (1) relayClientSession.ts is grandfathered over the desktop file-size cap and may not grow, and (2) an instance-property wrap keeps all probe code out of production request paths. The instance wrap shadows the prototype, so internal this.publishEvent calls are captured — which is why only publishEvent is wrapped for relay_pub (all send* funnel through it; wrapping the wrappers too would double-count). Fetch methods wrapped for relay_req: fetchChannelHistory, fetchChannelHistoryBefore, fetchAuxEventsByReference, fetchAuxDeletionEventsForAuxEvents, fetchEvents, fetchFirstEvent.

Dropped probe: the event-buffer-depth-at-flush measurement from the original brief. It has no external seam on the singleton (it lives inside relayClientSession.ts, which can't grow), and it was the lowest-value of the relay signals. REQ→EOSE and send→ack round-trips carry the "starved by the relay" signal on their own.

Overhead and how it is bounded

  • Ring buffer capped at 4096 records (RING_CAPACITY); oldest are dropped on overflow and the drop count is stamped on the next flush's first line so the analyzer can detect self-pressure. An unflushed or failed sink can never grow the harness into the thing it measures.
  • High-frequency probes are sampled or thresholded: the drift timer fires at 2Hz; input latency is only recorded above 100ms; the census runs every 2 min.
  • No per-frame allocation: the input probe uses double-rAF with a numeric subtraction, no object churn per frame.
  • No synchronous main-thread I/O: the Rust command appends on a spawn_blocking thread; the renderer only awaits the invoke, which is already async.
  • Fully try/catch-wrapped and idempotent: harness setup can never crash the app it measures.

Estimated overhead: negligible relative to the multi-second stalls being measured — a handful of records per second in the common case, one bounded array shift on overflow, one 2Hz timer, one 5s watchdog scan.

Sink safety

append_profiling_log validates file_stem strictly to session-<digits> (path-traversal-safe), creates <app-data>/profiling/ on demand, and rotates the file aside with a millisecond suffix once it crosses 50 MiB so a long session cannot grow unbounded. The analyzer globs session-<ts>*.jsonl and concatenates.

Tests

harness.test.mjs (7 tests): ring-buffer bounds, drop-count stamping, sink-rejection resilience, drift math. profiling_log.rs (2 tests): stem validation accepts session-<digits>, rejects traversal and malformed stems.

Record schema

Every record carries a shared envelope: t (performance.now(), monotonic), wall (Date.now()), sid (per-launch session id), up (ms since harness start), plus a type discriminant. One JSONL line per record. Full field definitions in desktop/src/shared/profiling/types.ts.

type Fields
stall dur (main-thread block ms; foreground-only)
input kind (keydown/pointerdown), latency (receipt → paint ms), queued (pre-dispatch delay ms, or null)
ipc cmd, dur (ms), ok
ipc_pending cmd, age (ms)
relay_req op (fetch method), dur (ms), ok
relay_pub op (publish method), dur (ms), ok
census observerEvents, observerAgents, observerMaxPerAgent, archiveEvents, transcripts, queryCache, domNodes

The first line of any flush that dropped records carries an extra dropped field.

@wpfleger96
wpfleger96 force-pushed the duncan/renderer-profiling-harness branch 3 times, most recently from 0553ae3 to 437fe18 Compare August 18, 2026 00:12
Duncan and others added 5 commits August 18, 2026 15:49
Passive, always-on harness that ring-buffers timing records and flushes
JSONL to a local file in the app data dir. Four probes attribute felt
renderer lag: main-thread stalls (timer drift) plus input latency, Tauri
IPC duration/outcome with a >10s pending-invoke watchdog, relay
REQ->EOSE and publish send->ack round-trips, and a periodic accumulator
census. Nothing is transmitted; the JSONL file is the only output.

This branch is a measurement instrument and is not intended to merge.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
Two measurement-validity fixes to the profiling harness (review pass):

- Stall probe scored timer deferral from a hidden/occluded/asleep webview
  as a main-thread block, so a single wake could emit an arbitrarily large
  dur dominating the ranked total. Gate drift records on continuous
  visible+focused foreground and re-arm the baseline across background
  windows so the first post-return interval cannot manufacture a phantom
  stall.
- Input latency used performance.now() - event.timeStamp, folding
  pre-dispatch/OS-queue delay into the figure on a cross-clock assumption.
  Capture the listener's own receipt clock synchronously; latency is now
  receipt to next painted frame on one clock, with the pre-dispatch queue
  delay split into a separate queued field (dropped when the clock basis
  is implausible).

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
… bridges

The invoke probe read internals.invoke then reassigned it via internals.invoke = wrapper. The terminal E2E backend defines invoke as an accessor whose setter reassigns the dispatcher's fallback closure, so the assignment routed the bridge's fallback back into the wrapper and overflowed the stack on the first non-terminal invoke, taking down app startup under the harness. Redefine invoke as a data property via Object.defineProperty (never the setter) and extract the logic to an import-light ipc.ts so it is unit-testable against the real bridge descriptor shape.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
Native Tauri 2.11.5 defines window.__TAURI_INTERNALS__.invoke as a non-configurable, non-writable value property, so the prior Object.defineProperty install threw TypeError and the broad catch in startProfilingHarness silently aborted all four probes — a production drive day would capture nothing. Move interception to the @tauri-apps/api/core module layer via a Vite alias proxy that re-exports the real surface and wraps only invoke; the real core derefs the window property per call, so the seam never writes it and stays passive against native, terminal-accessor, and mockIPC shapes alike. Isolate each probe install so one failure cannot abort the rest.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
The bare-specifier `@tauri-apps/api/core` Vite alias only caught direct core imports and external plugins. Tauri's own submodules (event, app, window, webview) reach core via the relative import `./core.js`, which an alias never sees, so their plugin:event|*, plugin:window|* … invoke traffic bypassed the profiling wrapper entirely — undercounting Rust wait time and letting the harness exonerate the very bucket it failed to observe.

Replace the alias with a pre-enforced Vite resolveId hook (pure decision in viteTauriCoreProxy.ts) that redirects both the bare specifier and the relative ./core.js from inside @tauri-apps/api to the proxy, while the proxy's @tauri-core-impl escape resolves to the real module without looping. Add a real Vite resolve-graph test proving all three call shapes route through the proxy once, plus pure-predicate unit tests.

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
@wpfleger96
wpfleger96 force-pushed the duncan/renderer-profiling-harness branch from cbfb2d6 to 29362ef Compare August 18, 2026 19:49
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