diff --git a/desktop/src/app/navigation/useAppNavigation.ts b/desktop/src/app/navigation/useAppNavigation.ts index b7452a7d06..913f51a2de 100644 --- a/desktop/src/app/navigation/useAppNavigation.ts +++ b/desktop/src/app/navigation/useAppNavigation.ts @@ -319,15 +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. 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. + // goChannel is the click-time anchor for the switch trace; it opens + // inside commitGuardedNavigation only after the navigation guard + // accepts. Coverage: sidebar/search/notification navigations funnel + // through here — direct navigate() callers (Pulse startDm) and + // history back/forward are untraced. Navigations that stay on the + // already-active channel (exact re-click only rewrites router state; + // jump-to-message/autoSend/force change only search params) never + // re-run the channel's settle effects, so a trace could only time out + // — also untraced. location.pathname.endsWith(`/channels/${channelId}`) ? undefined : channelId, diff --git a/desktop/src/shared/lib/channelSwitchPerf.test.mjs b/desktop/src/shared/lib/channelSwitchPerf.test.mjs index a83471a129..4a54c33763 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.test.mjs +++ b/desktop/src/shared/lib/channelSwitchPerf.test.mjs @@ -133,6 +133,19 @@ test("a frame-starved trace is dropped, not recorded as a clean settle", () => { }); }); +test("a not-pending frame landing past the wait deadline is starvation, not a settle", () => { + // Settle entered at t=1s (deadline 6s), render caught up, then frames + // stalled (system suspend, App Nap — no visibilitychange): the next frame + // lands at t=20s with nothing pending. The gap is starvation; recording + // it would fabricate a clean 20s switch well under the 35s age guard. + assert.equal(resolveSettleWait(20_000, 6_000, false, 0), "drop"); + // Still-pending arrivals past the deadline remain truncated records: the + // render genuinely wasn't done, which is the tail the tracer must keep. + assert.deepEqual(resolveSettleWait(6_001, 6_000, true, 0), { + settleWaitTruncated: true, + }); +}); + test("a truncated settle is flagged in the summary and the log record", () => { const summary = summarizeChannelSwitchTrace(trace(), 1_412, true); assert.ok(summary.endsWith(" settle=truncated"), summary); @@ -248,6 +261,51 @@ test("an undisturbed settle records exactly one measure", async () => { }); }); +test("beginning a switch clears the previous switch's settled mark and measure", async () => { + await withSettleHarness(async ({ begin, settle, flush, measures }) => { + const { CHANNEL_SWITCH_SETTLED_MARK } = await import( + "./channelSwitchPerf.ts" + ); + begin("aaaa1111aaaa1111"); + settle("aaaa1111aaaa1111"); + flush(); + assert.deepEqual(measures(), ["aaaa1111aaaa1111"]); + // A consumer polling the buffer mid-switch (the Playwright specs, the + // Performance panel) must never read the PREVIOUS switch's entries as + // the current one's. + begin("bbbb2222bbbb2222"); + assert.deepEqual(measures(), []); + assert.equal( + performance.getEntriesByName(CHANNEL_SWITCH_SETTLED_MARK).length, + 0, + ); + }); +}); + +test("a window hidden between click and settle entry drops the trace", async () => { + const visibilityListeners = []; + await withSettleHarness( + async ({ begin, settle, flush, measures }) => { + begin("aaaa1111aaaa1111"); + assert.ok(visibilityListeners.length >= 1, "watcher armed at begin"); + // The window hides while the fetch is in flight (cmd-H / minimize), + // then the user returns and the settle runs with the window visible + // again: the absence sits inside totalMs, so the trace must drop. + globalThis.document.visibilityState = "hidden"; + for (const listener of visibilityListeners) listener(); + globalThis.document.visibilityState = "visible"; + settle("aaaa1111aaaa1111"); + flush(); + assert.deepEqual(measures(), []); + }, + { + addEventListener: (type, listener) => { + if (type === "visibilitychange") visibilityListeners.push(listener); + }, + }, + ); +}); + test("abandoned switches never accumulate start marks", async () => { await withSettleHarness(async ({ abandon, begin }) => { const { CHANNEL_SWITCH_START_MARK } = await import( diff --git a/desktop/src/shared/lib/channelSwitchPerf.ts b/desktop/src/shared/lib/channelSwitchPerf.ts index bbe09bd09a..a5fa935a90 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.ts +++ b/desktop/src/shared/lib/channelSwitchPerf.ts @@ -192,8 +192,35 @@ export function cancelRouteExitAbandon(channelId: string): void { pendingRouteExitAbandons.delete(channelId); } +/** + * Timestamp of the most recent visibilitychange. rAF suspends and network + * work throttles while the window is hidden, so any visibility transition + * inside a trace window means an off-screen interval overlaps the + * measurement — such traces are dropped rather than charged with the + * absence. One listener per document (tests swap documents). + */ +let lastVisibilityChangeAt = Number.NEGATIVE_INFINITY; +const watchedDocuments = new WeakSet(); + +function ensureVisibilityWatcher(): void { + if (typeof document === "undefined" || !document.addEventListener) return; + if (watchedDocuments.has(document)) return; + watchedDocuments.add(document); + document.addEventListener("visibilitychange", () => { + lastVisibilityChangeAt = performance.now(); + }); +} + +function traceOverlapsHiddenWindow(trace: ChannelSwitchTrace): boolean { + return ( + document.visibilityState === "hidden" || + lastVisibilityChangeAt >= trace.startedAt + ); +} + export function beginChannelSwitchTrace(channelId: string): void { if (typeof performance === "undefined") return; + ensureVisibilityWatcher(); activeTrace = { channelId, startedAt: performance.now(), @@ -201,12 +228,15 @@ export function beginChannelSwitchTrace(channelId: string): void { windowFetch: null, membersFetch: null, }; - // Clear the previous start mark here, not only in record(): traces that + // Clear the whole previous switch here, not only in record(): traces that // die without recording (forum visits, route exits, drops) never reach - // record()'s buffer clearing, and weeks-long sessions would accumulate a - // stray mark per abandon. Clearing at begin bounds the buffer to one - // start mark no matter how the previous trace ended. + // record()'s buffer clearing — weeks-long sessions would accumulate a + // stray start mark per abandon — and a consumer polling the buffer + // mid-switch (Playwright specs, Performance panel) must never read the + // previous switch's settled mark or measure as the current one's. performance.clearMarks(CHANNEL_SWITCH_START_MARK); + performance.clearMarks(CHANNEL_SWITCH_SETTLED_MARK); + performance.clearMeasures(CHANNEL_SWITCH_MEASURE); performance.mark(CHANNEL_SWITCH_START_MARK, { detail: { channelId } }); } @@ -273,10 +303,15 @@ 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. 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. + * paint. Frame starvation is dropped, not recorded: a healthy chain with + * nothing pending records within a frame or two of settle entry, so a + * not-pending frame landing past the wait deadline means the gap was rAF + * suspension (system suspend, App Nap — cases that fire no + * visibilitychange), not render time. A trace older than the settle-entry + * timeout plus the render wait is dropped on the same grounds regardless of + * pending state. The rare honest render that catches up within one frame of + * the deadline is sacrificed by the first rule — better no measurement than + * a fabricated one. Pure for unit testing. */ export function resolveSettleWait( now: number, @@ -287,6 +322,7 @@ export function resolveSettleWait( if (now - startedAt > SWITCH_TRACE_TIMEOUT_MS + SETTLE_RENDER_WAIT_MS) { return "drop"; } + if (!renderPending && now > waitDeadline) return "drop"; if (renderPending && now < waitDeadline) return "wait"; return { settleWaitTruncated: renderPending }; } @@ -316,25 +352,16 @@ 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") { + // rAF suspends and network work throttles in hidden windows: a hidden + // interval anywhere between the click and the recorded settle would be + // charged to the switch as a clean record. Drop when the window is hidden + // now or any visibility transition happened since the click — better no + // measurement than a fabricated one. + ensureVisibilityWatcher(); + if (traceOverlapsHiddenWindow(trace)) { 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. @@ -370,7 +397,6 @@ export function settleChannelSwitchTrace(channelId: string): void { ); }; const dropTrace = () => { - stopWatchingVisibility(); if (activeTrace === trace) activeTrace = null; }; const awaitDeferredCommit = () => { @@ -380,10 +406,9 @@ 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) { + if (traceOverlapsHiddenWindow(trace)) { dropTrace(); return; } @@ -402,15 +427,11 @@ export function settleChannelSwitchTrace(channelId: string): void { return; } window.requestAnimationFrame(() => { - if (activeTrace !== trace) { - stopWatchingVisibility(); - return; - } - if (hiddenDuringWait) { + if (activeTrace !== trace) return; + if (traceOverlapsHiddenWindow(trace)) { dropTrace(); return; } - stopWatchingVisibility(); record(decision.settleWaitTruncated); }); };