diff --git a/desktop/src/app/navigation/commitGuardedNavigation.test.mjs b/desktop/src/app/navigation/commitGuardedNavigation.test.mjs index 0b836ec20b..5895b9debc 100644 --- a/desktop/src/app/navigation/commitGuardedNavigation.test.mjs +++ b/desktop/src/app/navigation/commitGuardedNavigation.test.mjs @@ -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]]); + }); +}); diff --git a/desktop/src/app/navigation/commitGuardedNavigation.ts b/desktop/src/app/navigation/commitGuardedNavigation.ts index 449442f5c9..2565ed1efa 100644 --- a/desktop/src/app/navigation/commitGuardedNavigation.ts +++ b/desktop/src/app/navigation/commitGuardedNavigation.ts @@ -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; }, deps: { allow?: typeof allowNavigation; beginTrace?: typeof beginChannelSwitchTrace; + cancelTrace?: typeof cancelChannelSwitchTrace; dropActiveTrace?: typeof dropActiveChannelSwitchTrace; } = {}, ): Promise { 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; } diff --git a/desktop/src/app/navigation/useAppNavigation.ts b/desktop/src/app/navigation/useAppNavigation.ts index 822621b5aa..2f08b25925 100644 --- a/desktop/src/app/navigation/useAppNavigation.ts +++ b/desktop/src/app/navigation/useAppNavigation.ts @@ -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], diff --git a/desktop/src/features/channels/ui/useChannelProfilePanel.ts b/desktop/src/features/channels/ui/useChannelProfilePanel.ts index 1a35666478..5631926fe6 100644 --- a/desktop/src/features/channels/ui/useChannelProfilePanel.ts +++ b/desktop/src/features/channels/ui/useChannelProfilePanel.ts @@ -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], ); diff --git a/desktop/src/features/home/ui/HomeView.tsx b/desktop/src/features/home/ui/HomeView.tsx index 893b3c309c..6055ea5b65 100644 --- a/desktop/src/features/home/ui/HomeView.tsx +++ b/desktop/src/features/home/ui/HomeView.tsx @@ -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], ); diff --git a/desktop/src/features/profile/ui/useProfileInteractionActions.ts b/desktop/src/features/profile/ui/useProfileInteractionActions.ts index f5ee47a770..e2af6fe5ec 100644 --- a/desktop/src/features/profile/ui/useProfileInteractionActions.ts +++ b/desktop/src/features/profile/ui/useProfileInteractionActions.ts @@ -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(); } diff --git a/desktop/src/features/pulse/lib/useNoteActions.ts b/desktop/src/features/pulse/lib/useNoteActions.ts index 8178cdc53a..aaac391190 100644 --- a/desktop/src/features/pulse/lib/useNoteActions.ts +++ b/desktop/src/features/pulse/lib/useNoteActions.ts @@ -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 >(() => 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 { diff --git a/desktop/src/shared/lib/channelSwitchPerf.test.mjs b/desktop/src/shared/lib/channelSwitchPerf.test.mjs index 90eadea58f..a08277ce55 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.test.mjs +++ b/desktop/src/shared/lib/channelSwitchPerf.test.mjs @@ -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"); + }); +}); diff --git a/desktop/src/shared/lib/channelSwitchPerf.ts b/desktop/src/shared/lib/channelSwitchPerf.ts index d970e04bb0..97b5f9e9e1 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.ts +++ b/desktop/src/shared/lib/channelSwitchPerf.ts @@ -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); }); };