fix(desktop): drop starved settles and hidden-overlap traces; clean buffer at begin

Blind-review round 4 (Opus xhigh) findings:

- A not-pending frame landing past the wait deadline is rAF starvation
  (system suspend, App Nap — no visibilitychange), not render time: a
  fast settle followed by a stall recorded up to 34s as a clean switch
  under the click-anchored 35s age guard. Such frames now drop.
- Visibility accounting now spans the whole trace: one module-level
  visibilitychange watcher timestamps transitions, and any transition
  since the click (not just during the settle wait) drops the trace —
  a window minimized while the fetch was in flight no longer records
  its absence as switch time. Replaces the per-settle listener.
- begin() now clears the previous switch's settled mark and measure
  too, so a consumer polling the User Timing buffer mid-switch can
  never read the prior switch's entries as the current one's.
- The goChannel comment no longer claims every channel navigation
  funnels through it: Pulse startDm navigates to the channel route
  directly and is untraced.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Signed-off-by: Max Lampert <maxwell@squareup.com>
This commit is contained in:
Max Lampert
2026-08-24 21:17:36 -07:00
parent f6d3388ecf
commit 96817abc2b
3 changed files with 121 additions and 42 deletions

View File

@@ -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,

View File

@@ -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(

View File

@@ -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<object>();
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);
});
};