fix(desktop): guard the final paint frame; trace DM entry paths

Three review findings against the tracer's honesty contract:

- The readiness -> paint frame was unguarded. `awaitDeferredCommit` checks
  age, frame gap, and visibility on every frame it drives, but the one rAF
  it queues before `record()` checked neither age nor gap, so a suspension
  in that seam (App Nap fires no visibilitychange) recorded the whole
  absence as a clean switch.
- DM actions await `open_dm` before `goChannel`, so that relay round-trip
  sat outside the measurement; Pulse's note actions used raw `navigate` and
  produced no measurement at all. Callers now capture the click anchor and
  hand it to `goChannel`, and Pulse routes through `goChannel`.
- A `navigate()` rejection left the trace it opened active, so an untraced
  re-entry could settle the failed attempt. Cancellation is by trace
  identity, so a newer same-channel attempt is never erased.

Signed-off-by: Max Lampert <maxwell@squareup.com>
This commit is contained in:
Max Lampert
2026-08-26 15:31:32 -07:00
parent a0a7989022
commit 6e9942f525
9 changed files with 319 additions and 25 deletions

View File

@@ -268,3 +268,89 @@ test("a same-destination navigation carrying router state still commits", async
assert.equal(committed, true);
assert.deepEqual(order, ["guard", "navigate"]);
});
test("a rejected navigate cancels the trace it opened", async () => {
await withTraceHarness(async ({ flush, measures }) => {
// Router/loader rejection: no destination committed, so the trace must
// not survive for a later untraced re-entry to settle with the failed
// attempt plus everything in between.
await assert.rejects(
commitGuardedNavigation({
currentHref: "/channels/aaaa",
nextHref: "/channels/bbbb",
guardedTarget: route("/channels/bbbb"),
traceChannelId: "bbbb",
navigate: async () => {
throw new Error("loader failed");
},
}),
/loader failed/,
);
settleChannelSwitchTrace("bbbb");
flush();
assert.deepEqual(measures(), []);
});
});
test("a rejected navigate never cancels a newer same-channel trace", async () => {
await withTraceHarness(async ({ flush, measures }) => {
// Cancel by identity, not by channel: the retry's trace is a different
// object and must keep its measurement when the first attempt rejects.
let releaseFirst;
const firstGate = new Promise((resolve) => {
releaseFirst = resolve;
});
const failing = assert.rejects(
commitGuardedNavigation({
currentHref: "/channels/aaaa",
nextHref: "/channels/bbbb",
guardedTarget: route("/channels/bbbb"),
traceChannelId: "bbbb",
navigate: async () => {
await firstGate;
throw new Error("loader failed");
},
}),
/loader failed/,
);
// Retry lands while the first attempt is still in flight.
await commitGuardedNavigation({
currentHref: "/channels/aaaa",
nextHref: "/channels/bbbb",
guardedTarget: route("/channels/bbbb"),
force: true,
traceChannelId: "bbbb",
navigate: async () => {},
});
releaseFirst();
await failing;
settleChannelSwitchTrace("bbbb");
flush();
assert.deepEqual(measures(), ["bbbb"]);
});
});
test("a DM caller's click anchor is carried into the trace", async () => {
await withTraceHarness(async () => {
const anchors = [];
await commitGuardedNavigation(
{
currentHref: "/",
nextHref: "/channels/bbbb",
guardedTarget: route("/channels/bbbb"),
traceChannelId: "bbbb",
traceStartedAt: 1234,
navigate: async () => {},
},
{
allow: () => true,
beginTrace: (channelId, anchoredAt) => {
anchors.push([channelId, anchoredAt]);
return null;
},
},
);
// Without this the open_dm round-trip would sit outside the measurement.
assert.deepEqual(anchors, [["bbbb", 1234]]);
});
});

View File

@@ -4,6 +4,7 @@ import {
} from "@/app/navigation/navigationGuard";
import {
beginChannelSwitchTrace,
cancelChannelSwitchTrace,
dropActiveChannelSwitchTrace,
} from "@/shared/lib/channelSwitchPerf";
@@ -18,8 +19,12 @@ import {
* navigation (deliberately untraced) would settle with the refused click's
* inflated wall time. When `leavesChannelSurface` is set, any active trace is
* dropped instead: the trace may be live with no channel screen mounted
* (route still resolving), so this is the only reliable exit hook. Returns
* whether the navigation was performed. `deps` exists for unit tests.
* (route still resolving), so this is the only reliable exit hook. A
* `navigate()` rejection cancels the trace this call opened — by identity, so
* a newer same-channel attempt is never erased — because no destination
* committed and an untraced re-entry would otherwise settle the failed
* attempt. Returns whether the navigation was performed. `deps` exists for
* unit tests.
*/
export async function commitGuardedNavigation(
input: {
@@ -30,16 +35,20 @@ export async function commitGuardedNavigation(
hasStateUpdate?: boolean;
leavesChannelSurface?: boolean;
traceChannelId?: string;
/** Click-time anchor for callers that await before `goChannel`. */
traceStartedAt?: number;
navigate: () => Promise<unknown>;
},
deps: {
allow?: typeof allowNavigation;
beginTrace?: typeof beginChannelSwitchTrace;
cancelTrace?: typeof cancelChannelSwitchTrace;
dropActiveTrace?: typeof dropActiveChannelSwitchTrace;
} = {},
): Promise<boolean> {
const allow = deps.allow ?? allowNavigation;
const beginTrace = deps.beginTrace ?? beginChannelSwitchTrace;
const cancelTrace = deps.cancelTrace ?? cancelChannelSwitchTrace;
const dropActiveTrace = deps.dropActiveTrace ?? dropActiveChannelSwitchTrace;
if (
input.currentHref === input.nextHref &&
@@ -54,9 +63,15 @@ export async function commitGuardedNavigation(
if (input.leavesChannelSurface) {
dropActiveTrace();
}
let handle = null;
if (input.traceChannelId !== undefined) {
beginTrace(input.traceChannelId);
handle = beginTrace(input.traceChannelId, input.traceStartedAt) ?? null;
}
try {
await input.navigate();
} catch (error) {
cancelTrace(handle);
throw error;
}
await input.navigate();
return true;
}

View File

@@ -42,6 +42,7 @@ export function useAppNavigation() {
behavior: NavigationBehavior = {},
guardedTarget?: GuardedNavigation,
traceChannelId?: string,
traceStartedAt?: number,
) => {
const nextLocation = router.buildLocation(next as never);
return commitGuardedNavigation({
@@ -66,6 +67,7 @@ export function useAppNavigation() {
} as never),
nextHref: nextLocation.href,
traceChannelId,
traceStartedAt,
});
},
[location.href, navigate, router],
@@ -281,6 +283,13 @@ export function useAppNavigation() {
preserveSearchHighlight?: boolean;
searchHighlight?: SearchHighlightNavigation;
replace?: boolean;
/**
* Click-time anchor from `captureSwitchTraceAnchor()`, for callers
* that must await before they know the channel id (DM actions await
* `open_dm`). Without it the trace would start after that relay
* round-trip and exclude felt click latency.
*/
traceStartedAt?: number;
/** Open this thread panel directly without waiting for a timeline row. */
thread?: string;
threadRootId?: string | null;
@@ -327,9 +336,10 @@ export function useAppNavigation() {
: undefined,
// 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
// accepts. Coverage: sidebar, search, notification, and DM-open
// navigations all funnel through here; DM callers pass traceStartedAt
// so the open_dm round-trip stays inside the measurement. History
// back/forward is deliberately 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
@@ -337,6 +347,7 @@ export function useAppNavigation() {
location.pathname.endsWith(`/channels/${channelId}`)
? undefined
: channelId,
options?.traceStartedAt,
);
},
[commitNavigation, location.pathname],

View File

@@ -1,6 +1,7 @@
import * as React from "react";
import { useAppNavigation } from "@/app/navigation/useAppNavigation";
import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf";
import { useOpenDmMutation } from "@/features/channels/hooks";
import type { ProfilePanelOpenOptions } from "@/shared/context/ProfilePanelContext";
@@ -60,8 +61,10 @@ export function useChannelProfilePanel({
const openDmMutateAsync = openDmMutation.mutateAsync;
const handleOpenDm = React.useCallback(
async (pubkeys: string[]) => {
// Anchor before awaiting open_dm; see captureSwitchTraceAnchor.
const traceStartedAt = captureSwitchTraceAnchor();
const dm = await openDmMutateAsync({ pubkeys });
await goChannel(dm.id);
await goChannel(dm.id, { traceStartedAt });
},
[goChannel, openDmMutateAsync],
);

View File

@@ -3,6 +3,7 @@ import { RefreshCcw } from "lucide-react";
import { useAppShell } from "@/app/AppShellContext";
import { useAppNavigation } from "@/app/navigation/useAppNavigation";
import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf";
import { useKnownAgentPubkeys } from "@/features/agents/useKnownAgentPubkeys";
import { useChannelsQuery, useOpenDmMutation } from "@/features/channels/hooks";
import { RightAuxiliaryPane } from "@/features/channels/ui/RightAuxiliaryPane";
@@ -221,8 +222,10 @@ export function HomeView({
const [isSendingReply, setIsSendingReply] = React.useState(false);
const handleOpenDm = React.useCallback(
async (pubkeys: string[]) => {
// Anchor before awaiting open_dm; see captureSwitchTraceAnchor.
const traceStartedAt = captureSwitchTraceAnchor();
const dm = await openDm({ pubkeys });
await goChannel(dm.id);
await goChannel(dm.id, { traceStartedAt });
},
[goChannel, openDm],
);

View File

@@ -3,6 +3,7 @@ import * as React from "react";
import { toast } from "sonner";
import { useAppNavigation } from "@/app/navigation/useAppNavigation";
import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf";
import {
channelsQueryKey,
useChannelsQuery,
@@ -152,9 +153,12 @@ export function useProfileInteractionActions({
return;
}
// Anchor before awaiting open_dm: that relay round-trip is felt click
// latency and belongs inside the switch measurement.
const traceStartedAt = captureSwitchTraceAnchor();
void runAction("message", async (targetPubkey) => {
const dm = await openDm({ pubkeys: [targetPubkey] });
await goChannel(dm.id);
await goChannel(dm.id, { traceStartedAt });
if (isMountedRef.current) {
onClose();
}

View File

@@ -1,5 +1,6 @@
import * as React from "react";
import { useNavigate } from "@tanstack/react-router";
import { useAppNavigation } from "@/app/navigation/useAppNavigation";
import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf";
import { useQueryClient } from "@tanstack/react-query";
import { toast } from "sonner";
@@ -47,7 +48,7 @@ export function usePulseNoteActions({
const [pendingUpvoteNoteIds, setPendingUpvoteNoteIds] = React.useState<
ReadonlySet<string>
>(() => new Set());
const navigate = useNavigate();
const { goChannel } = useAppNavigation();
const queryClient = useQueryClient();
const replyMutation = usePublishNoteMutation(currentPubkey);
const toggleReactionMutation = useToggleReactionMutation();
@@ -154,21 +155,22 @@ export function usePulseNoteActions({
const startDm = React.useCallback(
async (pubkey: string) => {
// goChannel, not raw navigate: this is a first-class channel entry and
// must produce a switch measurement like every other one. Anchor before
// awaiting open_dm; see captureSwitchTraceAnchor.
const traceStartedAt = captureSwitchTraceAnchor();
try {
const directMessage = await openDmMutation.mutateAsync({
pubkeys: [pubkey],
});
await navigate({
to: "/channels/$channelId",
params: { channelId: directMessage.id },
});
await goChannel(directMessage.id, { traceStartedAt });
} catch (error) {
toast.error(
error instanceof Error ? error.message : "Failed to open DM",
);
}
},
[navigate, openDmMutation],
[goChannel, openDmMutation],
);
return {

View File

@@ -5,7 +5,12 @@ import {
shouldAttributeFetch,
buildSwitchPerfLogRecord,
resolveSettleAction,
CHANNEL_SWITCH_MEASURE,
beginChannelSwitchTrace,
resetChannelSwitchTrace,
resolveFinalFrame,
resolveSettleWait,
settleChannelSwitchTrace,
summarizeChannelSwitchTrace,
} from "./channelSwitchPerf.ts";
@@ -536,3 +541,97 @@ test("leaving the channel surface abandons the trace; history-back records nothi
},
);
});
test("suspension between readiness and the paint frame drops the record", () => {
// The reviewer's repro: readiness at t=10ms, final frame at t=20_000ms.
// Recording here would emit total=20000ms as an ordinary clean switch —
// App Nap fires no visibilitychange, so the hidden-window guard cannot see
// it and the frame-gap guard in awaitDeferredCommit has already run.
assert.equal(resolveFinalFrame(20_000, 10, 0), "drop");
// A normal paint frame one refresh interval after readiness still records.
assert.equal(resolveFinalFrame(27, 10, 0), "record");
// Boundary: exactly the frame-gap cap is still a record; one past it drops.
assert.equal(resolveFinalFrame(3_010, 10, 0), "record");
assert.equal(resolveFinalFrame(3_011, 10, 0), "drop");
});
test("the final frame also honors the overall trace age cap", () => {
// Readiness landed just under the age cap and the paint frame is prompt,
// so the frame gap is innocent — only the age check can catch this.
assert.equal(resolveFinalFrame(35_001, 35_000, 0), "drop");
assert.equal(resolveFinalFrame(35_000, 34_999, 0), "record");
});
// Drives the real settle lifecycle with a controllable clock and rAF queue so
// a stall can be injected at one exact seam. Offsets are rebased above the
// real clock: earlier tests in this file fire visibilitychange, and a trace
// back-dated below those timestamps is (correctly) dropped at settle entry —
// which would make every assertion here vacuous.
function withClockedFrames(run) {
const frames = [];
const originalWindow = globalThis.window;
const originalDocument = globalThis.document;
const originalNow = performance.now;
const base = originalNow.call(performance) + 1_000;
let clock = base;
performance.now = () => clock;
globalThis.window = {
requestAnimationFrame: (cb) => frames.push(cb) && frames.length,
cancelAnimationFrame: () => {},
};
globalThis.document = {
addEventListener: () => {},
// No pending marker: readiness is reached on the first settle frame.
querySelector: () => null,
removeEventListener: () => {},
visibilityState: "visible",
};
performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE);
const at = (offset) => {
clock = base + offset;
};
const step = (offset) => {
at(offset);
for (const cb of frames.splice(0, frames.length)) cb();
};
const measures = () =>
performance.getEntriesByName(CHANNEL_SWITCH_MEASURE).length;
try {
run({ at, step, measures });
} finally {
performance.now = originalNow;
resetChannelSwitchTrace();
performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE);
if (originalWindow === undefined) delete globalThis.window;
else globalThis.window = originalWindow;
if (originalDocument === undefined) delete globalThis.document;
else globalThis.document = originalDocument;
}
}
test("a stall between readiness and the paint frame records nothing", () => {
withClockedFrames(({ at, step, measures }) => {
at(0);
beginChannelSwitchTrace("aaaa");
at(10);
settleChannelSwitchTrace("aaaa");
// Readiness frame: no pending marker, inside the wait deadline.
step(10);
// Process suspended here (App Nap): no visibilitychange fires, so only
// the final-frame guard can catch it.
step(20_000);
assert.equal(measures(), 0, "a 20s suspension must not record a switch");
});
});
test("a prompt paint frame after readiness still records", () => {
withClockedFrames(({ at, step, measures }) => {
at(0);
beginChannelSwitchTrace("aaaa");
at(10);
settleChannelSwitchTrace("aaaa");
step(10);
step(26);
assert.equal(measures(), 1, "the guard must not drop healthy switches");
});
});

View File

@@ -9,6 +9,14 @@
* traces and settles for non-active channels are ignored, so background
* refetches never pollute a switch measurement.
*
* Traced entry paths: every navigation that reaches `goChannel` — sidebar,
* search, notification activation, and the DM actions, which capture
* `captureSwitchTraceAnchor()` at the click so their `open_dm` round-trip is
* inside the interval rather than before it. Deliberately untraced: history
* back/forward (no click to anchor on) and navigations that stay on the
* already-active channel (nothing re-runs the settle, so a trace could only
* time out).
*
* Output per switch: a `[switch-perf]` console line plus User Timing
* marks/measures (`buzz:channel-switch:*`) so Playwright perf specs and the
* Performance panel can read the same numbers.
@@ -245,8 +253,42 @@ function traceOverlapsHiddenWindow(trace: ChannelSwitchTrace): boolean {
);
}
export function beginChannelSwitchTrace(channelId: string): void {
if (typeof performance === "undefined") return;
/**
* Timestamp to anchor a switch trace on, read during synchronous event
* dispatch. Callers that must await before they know the target channel (DM
* actions await `open_dm` for its id) capture this at the click and hand it to
* `goChannel`, so the relay round-trip stays inside the measured interval
* instead of silently preceding it.
*/
export function captureSwitchTraceAnchor(): number {
if (typeof performance === "undefined") return 0;
const now = performance.now();
const dispatchingEvent =
typeof window === "undefined" ? undefined : window.event;
return dispatchingEvent && typeof dispatchingEvent.timeStamp === "number"
? Math.min(dispatchingEvent.timeStamp, now)
: now;
}
/** Opaque identity for one opened trace; see `cancelChannelSwitchTrace`. */
export type ChannelSwitchTraceHandle = { readonly trace: ChannelSwitchTrace };
/**
* Cancels `handle`'s trace, and only that one. A later begin for the same
* channel installs a different trace object, so a failed navigation can never
* erase a newer attempt's measurement.
*/
export function cancelChannelSwitchTrace(
handle: ChannelSwitchTraceHandle | null,
): void {
if (handle && activeTrace === handle.trace) activeTrace = null;
}
export function beginChannelSwitchTrace(
channelId: string,
anchoredAt?: number,
): ChannelSwitchTraceHandle | null {
if (typeof performance === "undefined") return null;
ensureVisibilityWatcher();
// A same-task unmount-then-renavigate to this channel leaves the exit
// cleanup's scheduled abandon pending; it must not kill the fresh trace
@@ -256,14 +298,13 @@ export function beginChannelSwitchTrace(channelId: string): void {
// can sit queued behind a long task before its handler runs, and that
// input delay is felt switch latency. window.event is set only during
// synchronous dispatch, so a stale timestamp can never leak in from async
// continuations; min() guards against skewed event clocks.
// continuations; min() guards against skewed event clocks and against a
// caller-supplied anchor that a monotonic-clock skew put in the future.
const now = performance.now();
const dispatchingEvent =
typeof window === "undefined" ? undefined : window.event;
const startedAt =
dispatchingEvent && typeof dispatchingEvent.timeStamp === "number"
? Math.min(dispatchingEvent.timeStamp, now)
: now;
anchoredAt === undefined
? captureSwitchTraceAnchor()
: Math.min(anchoredAt, now);
activeTrace = {
channelId,
startedAt,
@@ -271,6 +312,7 @@ export function beginChannelSwitchTrace(channelId: string): void {
windowFetch: null,
membersFetch: null,
};
const handle: ChannelSwitchTraceHandle = { trace: activeTrace };
// 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 — weeks-long sessions would accumulate a
@@ -287,6 +329,7 @@ export function beginChannelSwitchTrace(channelId: string): void {
detail: { channelId },
startTime: startedAt,
});
return handle;
}
export function markChannelSwitchRouteCommit(channelId: string): void {
@@ -417,6 +460,26 @@ export function resolveSettleWait(
return { settleWaitTruncated: renderPending };
}
/**
* Decides whether the post-readiness paint frame may still be recorded.
* `awaitDeferredCommit` guards every frame it drives, but the readiness →
* paint frame is a starvation seam of its own: process suspension (App Nap,
* a suspended VM) can land there with no `visibilitychange`, and the resumed
* frame would record the whole absence as an ordinary clean switch. Pure for
* unit testing.
*/
export function resolveFinalFrame(
now: number,
readyAt: number,
startedAt: number,
): "record" | "drop" {
if (now - readyAt > MAX_SETTLE_FRAME_GAP_MS) return "drop";
if (now - startedAt > SWITCH_TRACE_TIMEOUT_MS + SETTLE_RENDER_WAIT_MS) {
return "drop";
}
return "record";
}
/**
* Closes the active trace once the settled frame has painted. The timeline
* renders rows through a deferred snapshot that exposes
@@ -526,12 +589,20 @@ export function settleChannelSwitchTrace(channelId: string): void {
dropTrace();
return;
}
const readyAt = now;
window.requestAnimationFrame(() => {
if (activeTrace !== trace) return;
if (traceOverlapsHiddenWindow(trace)) {
dropTrace();
return;
}
if (
resolveFinalFrame(performance.now(), readyAt, trace.startedAt) ===
"drop"
) {
dropTrace();
return;
}
record(decision.settleWaitTruncated);
});
};