diff --git a/desktop/src-tauri/src/commands/perf_log.rs b/desktop/src-tauri/src/commands/perf_log.rs index 5126639f4a..6ced5b3467 100644 --- a/desktop/src-tauri/src/commands/perf_log.rs +++ b/desktop/src-tauri/src/commands/perf_log.rs @@ -117,7 +117,12 @@ fn append_line_rotating(path: &std::path::Path, line: &str, max_bytes: u64) -> R .append(true) .open(path) .map_err(|e| e.to_string())?; - writeln!(file, "{line}").map_err(|e| e.to_string()) + // One write_all, not writeln!: writeln! issues two write syscalls (line, + // then newline), and PERF_LOG_LOCK is process-local while the path is + // not — a second Buzz process sharing the log dir could interleave + // between them. A single O_APPEND write keeps lines atomic. + file.write_all(format!("{line}\n").as_bytes()) + .map_err(|e| e.to_string()) } /// Appends one switch-perf record to the app-log-dir JSONL file and returns @@ -323,9 +328,10 @@ mod tests { let _ = std::fs::remove_file(&path); let _ = std::fs::remove_file(dir.join("switch-perf.jsonl.1")); - // 8 writers × 4 lines of 16 bytes = 512 bytes against a 384-byte cap: - // exactly one rotation boundary is crossed, so every line must land in - // either the live file or the single rotated generation. Unserialized + // 8 writers × 4 lines of 18 bytes on disk (17 chars + newline) = 576 + // bytes against a 384-byte cap: the rotation boundary is crossed + // exactly once (at the 22nd line), so every line must land in either + // the live file or the single rotated generation. Unserialized // metadata→rename→append interleavings drop lines or fail renames. let threads: Vec<_> = (0..8) .map(|writer| { diff --git a/desktop/src/app/navigation/commitGuardedNavigation.test.mjs b/desktop/src/app/navigation/commitGuardedNavigation.test.mjs index 99ab2084bc..9ed897949d 100644 --- a/desktop/src/app/navigation/commitGuardedNavigation.test.mjs +++ b/desktop/src/app/navigation/commitGuardedNavigation.test.mjs @@ -20,7 +20,12 @@ test("a refused navigation opens no trace; a later history settle records nothin requestAnimationFrame: (cb) => frames.push(cb) && frames.length, cancelAnimationFrame: () => {}, }; - globalThis.document = { querySelector: () => null }; + globalThis.document = { + addEventListener: () => {}, + querySelector: () => null, + removeEventListener: () => {}, + visibilityState: "visible", + }; performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); const unregister = registerNavigationGuard(() => false); try { diff --git a/desktop/src/app/navigation/useAppNavigation.ts b/desktop/src/app/navigation/useAppNavigation.ts index 7ad42560d7..b7452a7d06 100644 --- a/desktop/src/app/navigation/useAppNavigation.ts +++ b/desktop/src/app/navigation/useAppNavigation.ts @@ -319,14 +319,15 @@ export function useAppNavigation() { threadRootId: options.threadRootId ?? null, } : undefined, - // Every channel navigation entry point funnels through here, so this - // is the single click-time anchor for the switch trace; it opens - // inside commitGuardedNavigation only after the navigation guard - // accepts. Re-selecting the already-active channel is a no-op - // navigation: the channel's effects never rerun, nothing would - // settle the trace, and it would squat on the singleton until - // timeout — so don't open one. (History back/forward bypasses - // goChannel entirely and is deliberately untraced.) + // Every channel navigation entry point funnels through here, so + // this is the single click-time anchor for the switch trace; it + // opens inside commitGuardedNavigation only after the navigation + // guard accepts. Navigations that stay on the already-active + // channel (exact re-click is a no-op; jump-to-message/autoSend/ + // force change only search params) never re-run the channel's + // settle effects, so a trace could only time out — they stay + // untraced, as does history back/forward, which bypasses goChannel + // entirely. location.pathname.endsWith(`/channels/${channelId}`) ? undefined : channelId, diff --git a/desktop/src/features/channels/useChannelSwitchTraceMarks.ts b/desktop/src/features/channels/useChannelSwitchTraceMarks.ts index e78bb518fe..dece8ab0aa 100644 --- a/desktop/src/features/channels/useChannelSwitchTraceMarks.ts +++ b/desktop/src/features/channels/useChannelSwitchTraceMarks.ts @@ -10,8 +10,9 @@ import { import type { ChannelType } from "@/shared/api/types"; /** - * Switch-trace stage marks for the channel screen. Route commit fires on the - * first render for the target channel; settle fires once its timeline leaves + * Switch-trace stage marks for the channel screen. Route commit fires in a + * layout effect — before the first paint — of the first commit where the + * target channel object has resolved; settle fires once its timeline leaves * the loading latch. Both are no-ops unless goChannel opened a trace for this * channel. Forum readiness is owned by ForumView's own queries, which the * timeline latch cannot observe — those traces are abandoned instead of @@ -26,7 +27,9 @@ export function useChannelSwitchTraceMarks({ activeChannelType: ChannelType | null; isTimelineLoading: boolean; }): void { - React.useEffect(() => { + // Layout effect: a passive effect flushes after paint, which would report + // "commit" as first-paint time rather than commit time. + React.useLayoutEffect(() => { if (activeChannelId) markChannelSwitchRouteCommit(activeChannelId); }, [activeChannelId]); // Route-exit cancellation: leaving the channel surface before the trace diff --git a/desktop/src/features/messages/lib/projectChannelWindow.test.mjs b/desktop/src/features/messages/lib/projectChannelWindow.test.mjs index 24ea75edc0..a54ad751e2 100644 --- a/desktop/src/features/messages/lib/projectChannelWindow.test.mjs +++ b/desktop/src/features/messages/lib/projectChannelWindow.test.mjs @@ -429,7 +429,12 @@ test("canceled fetch never claims the switch trace's window slot; the accepted o requestAnimationFrame: (cb) => frames.push(cb) && frames.length, cancelAnimationFrame: () => {}, }; - globalThis.document = { querySelector: () => null }; + globalThis.document = { + addEventListener: () => {}, + querySelector: () => null, + removeEventListener: () => {}, + visibilityState: "visible", + }; const { beginChannelSwitchTrace, settleChannelSwitchTrace, diff --git a/desktop/src/features/projects/ui/ProjectsView.tsx b/desktop/src/features/projects/ui/ProjectsView.tsx index 6b85ef46b4..ecf0671e90 100644 --- a/desktop/src/features/projects/ui/ProjectsView.tsx +++ b/desktop/src/features/projects/ui/ProjectsView.tsx @@ -172,8 +172,8 @@ export function ProjectsView() { snapshotProjects, activeCommunity?.reposDir, ); - // Hydration marker for the switch-perf harness: the shell commits long - // before the query fan loads. isLoading so disabled queries never wedge it. + // Switch-perf hydration marker (shell commits long before the fan loads). + // isLoading: first load only — warm refetches/disabled queries stay false. const projectsHydrating = projectsQuery.isLoading || projectsWorkItemsQuery.isLoading || diff --git a/desktop/src/shared/lib/channelSwitchPerf.test.mjs b/desktop/src/shared/lib/channelSwitchPerf.test.mjs index f590ac4fc6..957c86efed 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.test.mjs +++ b/desktop/src/shared/lib/channelSwitchPerf.test.mjs @@ -107,15 +107,28 @@ test("settle drops a trace that has timed out", () => { test("the settle wait records truncated — never as an honest settle — at deadline", () => { // Still pending, before the deadline: keep waiting. - assert.equal(resolveSettleWait(4_999, 5_000, true), "wait"); + assert.equal(resolveSettleWait(4_999, 5_000, true, 0), "wait"); // Render caught up: record cleanly. - assert.deepEqual(resolveSettleWait(1_000, 5_000, false), { + assert.deepEqual(resolveSettleWait(1_000, 5_000, false, 0), { settleWaitTruncated: false, }); // Deadline expired while still pending: the record must say so — a >5s // switch reported as an ordinary settle would hide exactly the tail this // tracer exists to expose. - assert.deepEqual(resolveSettleWait(5_000, 5_000, true), { + assert.deepEqual(resolveSettleWait(5_000, 5_000, true, 0), { + settleWaitTruncated: true, + }); +}); + +test("a frame-starved trace is dropped, not recorded as a clean settle", () => { + // rAF suspends in hidden windows, so a queued settle can fire minutes + // after the click with renderPending long since false — the absence must + // not be charged to the switch. Nothing legitimate can be older than the + // 30s settle-entry timeout plus the 5s render wait. + assert.equal(resolveSettleWait(35_001, 40_000, false, 0), "drop"); + assert.equal(resolveSettleWait(35_001, 40_000, true, 0), "drop"); + // At the bound (a 29.9s settle plus a truncated 5s wait) records survive. + assert.deepEqual(resolveSettleWait(35_000, 34_900, true, 0), { settleWaitTruncated: true, }); }); @@ -145,7 +158,7 @@ test("fetches attribute only when started after the switch began", () => { // --- Settle lifecycle: rapid switches and community resets ---------------- -async function withSettleHarness(run) { +async function withSettleHarness(run, documentOverrides = {}) { const frames = []; const originalWindow = globalThis.window; const originalDocument = globalThis.document; @@ -153,7 +166,13 @@ async function withSettleHarness(run) { requestAnimationFrame: (cb) => frames.push(cb) && frames.length, cancelAnimationFrame: () => {}, }; - globalThis.document = { querySelector: () => null }; + globalThis.document = { + addEventListener: () => {}, + querySelector: () => null, + removeEventListener: () => {}, + visibilityState: "visible", + ...documentOverrides, + }; const { abandonChannelSwitchTrace, beginChannelSwitchTrace, @@ -229,6 +248,44 @@ test("an undisturbed settle records exactly one measure", async () => { }); }); +test("a settle in a hidden window drops the trace instead of recording", async () => { + await withSettleHarness( + async ({ begin, settle, flush, measures }) => { + begin("aaaa1111aaaa1111"); + // rAF is suspended while hidden; the queued chain would only fire when + // the user returns, charging the whole absence to the switch. + settle("aaaa1111aaaa1111"); + flush(); + assert.deepEqual(measures(), []); + // The trace was released, not wedged: a later stale settle is a no-op. + settle("aaaa1111aaaa1111"); + flush(); + assert.deepEqual(measures(), []); + }, + { visibilityState: "hidden" }, + ); +}); + +test("a window hidden during the settle wait drops the record", async () => { + const visibilityListeners = []; + await withSettleHarness( + async ({ begin, settle, flush, measures }) => { + begin("aaaa1111aaaa1111"); + settle("aaaa1111aaaa1111"); + assert.equal(visibilityListeners.length, 1, "wait registers a listener"); + // The user cmd-tabs away mid-wait; frames resume only on return. + visibilityListeners[0](); + flush(); + assert.deepEqual(measures(), []); + }, + { + addEventListener: (type, listener) => { + if (type === "visibilitychange") visibilityListeners.push(listener); + }, + }, + ); +}); + test("a scheduled route-exit abandon canceled in the same task keeps the trace", async () => { await withSettleHarness( async ({ diff --git a/desktop/src/shared/lib/channelSwitchPerf.ts b/desktop/src/shared/lib/channelSwitchPerf.ts index 0daa46890e..163658a05e 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.ts +++ b/desktop/src/shared/lib/channelSwitchPerf.ts @@ -17,6 +17,10 @@ * before the settled paint. A roster fetch that completes after settle is * deliberately not part of the felt switch latency, so such switches report * `members=cache` — by design, not omission. + * + * The settled timestamp lands one rAF after the paint, so `totalMs` includes + * up to one display refresh interval (~17ms at 60Hz, ~8ms at 120Hz) — + * compare before/after runs on the same display. */ import { invoke, isTauri } from "@tauri-apps/api/core"; @@ -263,13 +267,20 @@ const SETTLE_RENDER_WAIT_MS = 5_000; * the wait ends with the render still pending, the record must say so — the * >deadline tail is exactly what this tracer exists to expose, so the * measurement is kept but flagged rather than posing as an honest settled - * paint. Pure for unit testing. + * paint. A trace older than the settle-entry timeout plus the render wait + * is frame-starved (hidden window, display sleep — rAF suspends there) and + * is dropped: nothing legitimate can reach that age, and recording it would + * charge the whole absence to the switch. Pure for unit testing. */ export function resolveSettleWait( now: number, waitDeadline: number, renderPending: boolean, -): "wait" | { settleWaitTruncated: boolean } { + startedAt: number, +): "wait" | "drop" | { settleWaitTruncated: boolean } { + if (now - startedAt > SWITCH_TRACE_TIMEOUT_MS + SETTLE_RENDER_WAIT_MS) { + return "drop"; + } if (renderPending && now < waitDeadline) return "wait"; return { settleWaitTruncated: renderPending }; } @@ -299,6 +310,25 @@ export function settleChannelSwitchTrace(channelId: string): void { activeTrace = null; return; } + // rAF suspends entirely in hidden windows: a queued settle would fire + // only when the user returns, charging the whole absence to the switch as + // a clean record. Drop at settle when already hidden, and poison the wait + // if the window hides before the record lands — better no measurement + // than a fabricated one. + if (document.visibilityState === "hidden") { + activeTrace = null; + return; + } + let hiddenDuringWait = false; + const onVisibilityChange = () => { + hiddenDuringWait = true; + }; + document.addEventListener("visibilitychange", onVisibilityChange, { + once: true, + }); + const stopWatchingVisibility = () => { + document.removeEventListener("visibilitychange", onVisibilityChange); + }; // Keep the trace active through the deferred-commit wait so fetches that // finish inside the measured window still attribute to it. It is released // when the record lands; a newer switch's begin() simply replaces it. @@ -306,6 +336,12 @@ export function settleChannelSwitchTrace(channelId: string): void { const record = (settleWaitTruncated: boolean) => { const settledAt = performance.now(); if (activeTrace === trace) activeTrace = null; + // Keep only the latest switch in the User Timing buffer: desktop + // sessions run for weeks and the buffer is never GC'd. DevTools + // recordings capture entries at emit time, so clearing loses nothing. + performance.clearMarks(CHANNEL_SWITCH_START_MARK); + performance.clearMarks(CHANNEL_SWITCH_SETTLED_MARK); + performance.clearMeasures(CHANNEL_SWITCH_MEASURE); performance.mark(CHANNEL_SWITCH_SETTLED_MARK, { detail: { channelId }, }); @@ -327,6 +363,10 @@ export function settleChannelSwitchTrace(channelId: string): void { buildSwitchPerfLogRecord(trace, settledAt, settleWaitTruncated), ); }; + const dropTrace = () => { + stopWatchingVisibility(); + if (activeTrace === trace) activeTrace = null; + }; const awaitDeferredCommit = () => { if (activeTrace !== trace) { // A newer switch replaced this trace, or a community reset dropped it. @@ -334,19 +374,37 @@ export function settleChannelSwitchTrace(channelId: string): void { // own — recording would charge the replacement's delay to the settled // channel and could manufacture the very regression the tracer exists // to diagnose. Better no measurement than a fabricated one. + stopWatchingVisibility(); + return; + } + if (hiddenDuringWait) { + dropTrace(); return; } const decision = resolveSettleWait( performance.now(), waitDeadline, document.querySelector('[data-render-pending="true"]') !== null, + trace.startedAt, ); if (decision === "wait") { window.requestAnimationFrame(awaitDeferredCommit); return; } + if (decision === "drop") { + dropTrace(); + return; + } window.requestAnimationFrame(() => { - if (activeTrace !== trace) return; + if (activeTrace !== trace) { + stopWatchingVisibility(); + return; + } + if (hiddenDuringWait) { + dropTrace(); + return; + } + stopWatchingVisibility(); record(decision.settleWaitTruncated); }); }; diff --git a/desktop/tests/e2e/member-heavy-switch.perf.ts b/desktop/tests/e2e/member-heavy-switch.perf.ts index 97096f37aa..69efb094ab 100644 --- a/desktop/tests/e2e/member-heavy-switch.perf.ts +++ b/desktop/tests/e2e/member-heavy-switch.perf.ts @@ -7,12 +7,13 @@ import { installMockBridge } from "../helpers/bridge"; * * Isolates how channel MEMBERSHIP SIZE scales the warm-switch cost, holding * message volume constant. Every channel object embeds its full - * member-pubkey array, so membership size inflates (a) the get_channels - * payload parsed on every poll, (b) the per-switch get_channel_members - * response, and (c) every render-path pass over `channel.memberPubkeys` and - * the member list (profile merges, agent-flag merges, mention candidates). - * This spec is the instrument for that scaling: same channels, same rows, - * member count is the only variable. + * member-pubkey array, so membership size inflates every render-path pass + * over `channel.memberPubkeys` and the member list (profile merges, + * agent-flag merges, mention candidates). NOTE: the mock bridge hands the + * app live JS objects — no IPC serialization or JSON parse — so the + * get_channels/get_channel_members parse cost that scales with membership + * in production is NOT exercised here; this instrument measures render-path + * scaling only. Same channels, same rows, member count the only variable. * * Two scenarios per member count: * channel<->channel — general <-> deep-history (150 fixed rows). @@ -21,12 +22,15 @@ import { installMockBridge } from "../helpers/bridge"; * (project enumeration, work items, repo snapshots, * activity summaries) on top of the shell, so this * axis captures the cross-surface switch the felt - * 1-2s report singled out. Readiness gates on the - * surface's data-projects-hydrating marker, not just - * the shell header — a sample whose query fan is - * still loading must not count as settled. After the - * untimed warmup both surfaces are cache-warm, so - * measured samples are warm-switch commits. + * 1-2s report singled out. Readiness requires the + * shell header AND the absence of the surface's + * data-projects-hydrating marker. The marker guards + * cold/invalidated samples whose query fan is still + * on first load; after the untimed warmup the fan is + * cached and renders synchronously, so measured + * samples are warm-switch commits (the marker never + * fires there — that is the warm contract, not a + * gap). * * Method mirrors warm-switch-markdown.perf.ts: in-page click + rAF polling * (CDP latency never pollutes samples), longtask capture per switch, 4x CPU @@ -86,7 +90,10 @@ async function measureSwitch( }, ): Promise { return page.evaluate(async (args) => { - const store = window as unknown as { __LONGTASKS__: number[] }; + const store = window as unknown as { + __LONGTASKS__: number[]; + __LONGTASK_OBSERVER__?: PerformanceObserver; + }; store.__LONGTASKS__ = []; const link = document.querySelector( `[data-testid="${args.targetTestId}"]`, @@ -123,6 +130,11 @@ async function measureSwitch( }); const elapsed = performance.now() - start; + // Observer callbacks are delivered in a later task; drain the queue so + // a longtask ending just before the resolve frame isn't dropped. + for (const entry of store.__LONGTASK_OBSERVER__?.takeRecords() ?? []) { + store.__LONGTASKS__.push(entry.duration); + } const tasks = store.__LONGTASKS__ ?? []; return { ms: elapsed, @@ -255,13 +267,19 @@ for (const memberCount of MEMBER_COUNTS) { // Arm the longtask observer; addInitScript applies on next navigation. await page.addInitScript(() => { - const store = window as unknown as { __LONGTASKS__?: number[] }; + const store = window as unknown as { + __LONGTASKS__?: number[]; + __LONGTASK_OBSERVER__?: PerformanceObserver; + }; store.__LONGTASKS__ = []; - new PerformanceObserver((list) => { + const observer = new PerformanceObserver((list) => { for (const entry of list.getEntries()) { store.__LONGTASKS__?.push(entry.duration); } - }).observe({ type: "longtask", buffered: true }); + }); + observer.observe({ type: "longtask", buffered: true }); + // Exposed so measureSwitch can drain takeRecords() at sample time. + store.__LONGTASK_OBSERVER__ = observer; }); await page.reload(); await page.waitForFunction(