diff --git a/desktop/playwright.config.ts b/desktop/playwright.config.ts index be15c75587..9e1a75929d 100644 --- a/desktop/playwright.config.ts +++ b/desktop/playwright.config.ts @@ -109,6 +109,7 @@ export default defineConfig({ "**/overscroll-boundary.spec.ts", "**/terminal-wheel.spec.ts", "**/cold-switch-longtask.perf.ts", + "**/switch-settle-after-paint.spec.ts", "**/timeline-no-shift.spec.ts", "**/human-edit-agent-content.spec.ts", "**/empty-edit-delete.spec.ts", diff --git a/desktop/src-tauri/build.rs b/desktop/src-tauri/build.rs index 2cdd785c73..63dfa91dc6 100644 --- a/desktop/src-tauri/build.rs +++ b/desktop/src-tauri/build.rs @@ -8,6 +8,34 @@ include!("src/managed_agents/reserved_env_keys.rs"); use base64::Engine as _; fn main() { + // Bake the source git revision into the binary so diagnostics (the + // switch-perf JSONL sink) can attribute records to the build that wrote + // them. Reruns key off the reflog, which updates on every checkout, + // commit, and rebase. `--dirty` marks uncommitted worktrees but is only + // as fresh as the last build-script run: plain source edits between + // builds do not re-stamp it. Checkout-based A/B flows (the intended use) + // always update the reflog and re-stamp. + if let Ok(git_dir) = std::process::Command::new("git") + .args(["rev-parse", "--absolute-git-dir"]) + .output() + { + if git_dir.status.success() { + let dir = String::from_utf8_lossy(&git_dir.stdout).trim().to_string(); + println!("cargo:rerun-if-changed={dir}/HEAD"); + println!("cargo:rerun-if-changed={dir}/logs/HEAD"); + } + } + if let Some(git_sha) = std::process::Command::new("git") + .args(["describe", "--always", "--dirty", "--abbrev=12"]) + .output() + .ok() + .filter(|output| output.status.success()) + .map(|output| String::from_utf8_lossy(&output.stdout).trim().to_string()) + .filter(|sha| !sha.is_empty()) + { + println!("cargo:rustc-env=BUZZ_DESKTOP_BUILD_GIT_SHA={git_sha}"); + } + println!("cargo:rerun-if-env-changed=BUZZ_RELAY_URL"); println!("cargo:rerun-if-env-changed=BUZZ_RELAY_HTTP"); println!("cargo:rerun-if-env-changed=BUZZ_UPDATER_PUBLIC_KEY"); diff --git a/desktop/src-tauri/src/commands/mod.rs b/desktop/src-tauri/src/commands/mod.rs index 7cb2d8e3b8..0389c20ece 100644 --- a/desktop/src-tauri/src/commands/mod.rs +++ b/desktop/src-tauri/src/commands/mod.rs @@ -44,6 +44,7 @@ mod notifications; mod observer_archive; mod os_idle; pub mod pairing; +mod perf_log; mod personas; mod prevent_sleep; mod profile; @@ -105,6 +106,7 @@ pub use notifications::*; pub use observer_archive::*; pub use os_idle::*; pub use pairing::*; +pub use perf_log::*; pub use personas::*; pub use prevent_sleep::*; pub use profile::*; diff --git a/desktop/src-tauri/src/commands/perf_log.rs b/desktop/src-tauri/src/commands/perf_log.rs new file mode 100644 index 0000000000..ff493ac413 --- /dev/null +++ b/desktop/src-tauri/src/commands/perf_log.rs @@ -0,0 +1,268 @@ +//! Append-only JSONL sink for channel-switch perf traces. +//! +//! The desktop's `[switch-perf]` console traces vanish with the session; this +//! sink persists one JSON line per settled switch to +//! `{app_log_dir}/switch-perf.jsonl` so before/after builds can be compared +//! offline. Every line is stamped with the build's git revision (baked by +//! build.rs) and, when set at launch, the `BUZZ_PERF_LOG_LABEL` run label — +//! e.g. `BUZZ_PERF_LOG_LABEL=before just production`. + +use std::io::Write; + +use tauri::Manager; + +const PERF_LOG_FILENAME: &str = "switch-perf.jsonl"; + +/// Defensive cap: one record is a small trace object; anything larger is a +/// caller bug and must not grow the log unbounded. +const MAX_RECORD_BYTES: usize = 4 * 1024; + +/// Rotation threshold. The sink is always on, so without a cap the JSONL +/// grows for the life of the install; one rotated generation preserves +/// enough history for before/after comparisons. +const MAX_LOG_BYTES: u64 = 10 * 1024 * 1024; + +/// Validates and shapes one JSONL line: the record must be a JSON object +/// (which also guarantees the stored line is newline-free), then the build +/// revision and optional run label are folded in. Pure for unit testing. +fn shape_perf_log_line( + record_json: &str, + git_sha: Option<&str>, + label: Option<&str>, +) -> Result { + if record_json.len() > MAX_RECORD_BYTES { + return Err("perf log record too large".to_string()); + } + let mut value: serde_json::Value = + serde_json::from_str(record_json).map_err(|e| format!("invalid perf log record: {e}"))?; + let object = value + .as_object_mut() + .ok_or_else(|| "perf log record must be a JSON object".to_string())?; + object.insert( + "gitSha".to_string(), + match git_sha { + Some(sha) => serde_json::Value::String(sha.to_string()), + None => serde_json::Value::Null, + }, + ); + if let Some(label) = label { + object.insert( + "label".to_string(), + serde_json::Value::String(label.to_string()), + ); + } + serde_json::to_string(&value).map_err(|e| e.to_string()) +} + +/// Serializes the whole metadata→rename→append transaction. Appends run on +/// independent `spawn_blocking` threads; without this, two writers at the +/// rotation boundary can both decide to rotate — the loser's rename fails and +/// its record is dropped. One global lock suffices: the app writes a single +/// log path. +static PERF_LOG_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(()); + +/// Appends one line, rotating the file to `.1` (replacing the previous +/// generation) once it exceeds `max_bytes`. Factored for unit testing. +fn append_line_rotating(path: &std::path::Path, line: &str, max_bytes: u64) -> Result<(), String> { + let _guard = PERF_LOG_LOCK + .lock() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + if let Ok(metadata) = std::fs::metadata(path) { + if metadata.len() >= max_bytes { + let mut rotated = path.as_os_str().to_owned(); + rotated.push(".1"); + let rotated = std::path::PathBuf::from(rotated); + // Remove the retained generation before renaming over it: on + // Windows, rename does not replace an existing destination, and a + // failed rotation here would silently drop every subsequent trace + // (the frontend deliberately swallows sink errors). Same platform + // rule as managed_agents::storage::start_install_log_session. + if rotated.exists() { + std::fs::remove_file(&rotated).map_err(|e| e.to_string())?; + } + std::fs::rename(path, &rotated).map_err(|e| e.to_string())?; + } + } + let mut file = std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(path) + .map_err(|e| e.to_string())?; + writeln!(file, "{line}").map_err(|e| e.to_string()) +} + +/// Appends one switch-perf record to the app-log-dir JSONL file and returns +/// the file's path so the frontend can announce where the log lives. +/// +/// Async so Tauri runs it on the async runtime rather than the main thread: +/// a perf sink must not add main-thread filesystem stalls to the switches it +/// measures. +#[tauri::command] +pub async fn append_switch_perf_log( + app: tauri::AppHandle, + record_json: String, +) -> Result { + let label = std::env::var("BUZZ_PERF_LOG_LABEL").ok(); + let line = shape_perf_log_line( + &record_json, + option_env!("BUZZ_DESKTOP_BUILD_GIT_SHA"), + label.as_deref(), + )?; + let dir = app.path().app_log_dir().map_err(|e| e.to_string())?; + let path = dir.join(PERF_LOG_FILENAME); + let result = tauri::async_runtime::spawn_blocking(move || { + std::fs::create_dir_all(path.parent().unwrap_or(&path)).map_err(|e| e.to_string())?; + append_line_rotating(&path, &line, MAX_LOG_BYTES)?; + Ok::(path.display().to_string()) + }) + .await + .map_err(|e| e.to_string())?; + result +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn shape_folds_in_git_sha_and_label() { + let line = shape_perf_log_line(r#"{"totalMs":412}"#, Some("abc123-dirty"), Some("before")) + .expect("shape"); + let value: serde_json::Value = serde_json::from_str(&line).expect("parse"); + assert_eq!(value["totalMs"], 412); + assert_eq!(value["gitSha"], "abc123-dirty"); + assert_eq!(value["label"], "before"); + assert!(!line.contains('\n')); + } + + #[test] + fn shape_without_label_or_sha_keeps_record_and_null_sha() { + let line = shape_perf_log_line(r#"{"totalMs":1}"#, None, None).expect("shape"); + let value: serde_json::Value = serde_json::from_str(&line).expect("parse"); + assert_eq!(value["gitSha"], serde_json::Value::Null); + assert!(value.get("label").is_none()); + } + + #[test] + fn shape_rejects_non_objects_and_oversized_records() { + assert!(shape_perf_log_line("[1,2]", None, None).is_err()); + assert!(shape_perf_log_line("not json", None, None).is_err()); + let oversized = format!(r#"{{"pad":"{}"}}"#, "x".repeat(MAX_RECORD_BYTES)); + assert!(shape_perf_log_line(&oversized, None, None).is_err()); + } + + #[test] + fn append_rotates_once_over_the_cap_and_keeps_one_generation() { + let dir = std::env::temp_dir().join(format!("perf-log-test-{}", std::process::id())); + std::fs::create_dir_all(&dir).expect("tempdir"); + let path = dir.join("switch-perf.jsonl"); + let _ = std::fs::remove_file(&path); + let _ = std::fs::remove_file(dir.join("switch-perf.jsonl.1")); + + append_line_rotating(&path, "first", 16).expect("append"); + append_line_rotating(&path, "second", 16).expect("append"); + // 12 bytes so far — under the cap, same file. + assert_eq!( + std::fs::read_to_string(&path).expect("read"), + "first\nsecond\n" + ); + + // Push past the cap; the next append must rotate. + append_line_rotating(&path, "third-is-long", 16).expect("append"); + append_line_rotating(&path, "fresh", 16).expect("append"); + assert_eq!(std::fs::read_to_string(&path).expect("read"), "fresh\n"); + assert_eq!( + std::fs::read_to_string(dir.join("switch-perf.jsonl.1")).expect("read rotated"), + "first\nsecond\nthird-is-long\n" + ); + + // A second rotation replaces the previous generation, never a third file. + append_line_rotating(&path, "overflow-the-cap!", 16).expect("append"); + append_line_rotating(&path, "newest", 16).expect("append"); + assert_eq!(std::fs::read_to_string(&path).expect("read"), "newest\n"); + assert_eq!( + std::fs::read_to_string(dir.join("switch-perf.jsonl.1")).expect("read rotated"), + "fresh\noverflow-the-cap!\n" + ); + std::fs::remove_dir_all(&dir).ok(); + } + + #[test] + fn rotation_replaces_an_existing_retained_generation() { + let dir = std::env::temp_dir().join(format!( + "perf-log-regen-{}-{:?}", + std::process::id(), + std::thread::current().id() + )); + std::fs::create_dir_all(&dir).expect("tempdir"); + let path = dir.join("switch-perf.jsonl"); + let rotated = dir.join("switch-perf.jsonl.1"); + // Seed BOTH generations, as after any prior rollover. On Windows a + // bare rename onto the existing `.1` fails, which used to kill every + // subsequent append. + std::fs::write(&path, "current-full\n").expect("seed current"); + std::fs::write(&rotated, "old-generation\n").expect("seed rotated"); + + append_line_rotating(&path, "fresh", 8).expect("rotation over existing .1 must succeed"); + + assert_eq!(std::fs::read_to_string(&path).expect("read"), "fresh\n"); + assert_eq!( + std::fs::read_to_string(&rotated).expect("read rotated"), + "current-full\n" + ); + std::fs::remove_dir_all(&dir).ok(); + } + + #[test] + fn concurrent_boundary_appends_lose_no_line_and_rotate_once() { + let dir = std::env::temp_dir().join(format!( + "perf-log-concurrent-{}-{:?}", + std::process::id(), + std::thread::current().id() + )); + std::fs::create_dir_all(&dir).expect("tempdir"); + let path = dir.join("switch-perf.jsonl"); + 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 + // metadata→rename→append interleavings drop lines or fail renames. + let threads: Vec<_> = (0..8) + .map(|writer| { + let path = path.clone(); + std::thread::spawn(move || { + for line_index in 0..4 { + append_line_rotating( + &path, + &format!("writer-{writer:02}-line-{line_index:02}"), + 384, + ) + .expect("append"); + } + }) + }) + .collect(); + for thread in threads { + thread.join().expect("join"); + } + + let mut lines: Vec = std::fs::read_to_string(&path) + .expect("read live") + .lines() + .map(str::to_string) + .collect(); + if let Ok(rotated) = std::fs::read_to_string(dir.join("switch-perf.jsonl.1")) { + lines.extend(rotated.lines().map(str::to_string)); + } + lines.sort(); + let expected: Vec = (0..8) + .flat_map(|writer| { + (0..4).map(move |line_index| format!("writer-{writer:02}-line-{line_index:02}")) + }) + .collect(); + assert_eq!(lines, expected, "every append must survive the boundary"); + std::fs::remove_dir_all(&dir).ok(); + } +} diff --git a/desktop/src-tauri/src/lib.rs b/desktop/src-tauri/src/lib.rs index 613040b809..ac13a22c84 100644 --- a/desktop/src-tauri/src/lib.rs +++ b/desktop/src-tauri/src/lib.rs @@ -591,6 +591,7 @@ pub fn run() { search_users, get_presence, get_os_idle_seconds, + append_switch_perf_log, get_default_relay_url, auto_connect_default_relay_enabled, get_legacy_workspace_storage, diff --git a/desktop/src/app/navigation/useAppNavigation.ts b/desktop/src/app/navigation/useAppNavigation.ts index ade8c9332c..ac2b16a78c 100644 --- a/desktop/src/app/navigation/useAppNavigation.ts +++ b/desktop/src/app/navigation/useAppNavigation.ts @@ -14,6 +14,7 @@ import { traverseHistory, } from "@/app/navigation/navigationGuard"; import type { SearchHit } from "@/shared/api/types"; +import { beginChannelSwitchTrace } from "@/shared/lib/channelSwitchPerf"; type NavigationBehavior = { force?: boolean; @@ -286,6 +287,16 @@ export function useAppNavigation() { threadRootId?: string | null; }, ) => { + // Every channel navigation entry point funnels through here, so this + // is the single click-time anchor for the switch trace. 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.) + if (!location.pathname.endsWith(`/channels/${channelId}`)) { + beginChannelSwitchTrace(channelId); + } return commitNavigation( { to: "/channels/$channelId", @@ -327,7 +338,7 @@ export function useAppNavigation() { : undefined, ); }, - [commitNavigation], + [commitNavigation, location.pathname], ); const goNewMessage = React.useCallback( diff --git a/desktop/src/features/channels/hooks.ts b/desktop/src/features/channels/hooks.ts index 9069b052da..f08842355b 100644 --- a/desktop/src/features/channels/hooks.ts +++ b/desktop/src/features/channels/hooks.ts @@ -42,6 +42,7 @@ import type { } from "@/shared/api/tauriChannels"; import { mergeConcurrentChannelRecency } from "@/features/channels/lib/channelRecencyMerge"; import { useIdentityQuery } from "@/shared/api/hooks"; +import { traceChannelMembersFetch } from "@/shared/lib/channelSwitchPerf"; import { useFocusedRefetchInterval } from "@/shared/lib/useDocumentVisible"; import { useCommunities } from "@/features/communities/useCommunities"; import { @@ -49,6 +50,10 @@ import { type ChannelSnapshot, writeChannelSnapshot, } from "@/features/channels/channelSnapshot"; +import { + markSnapshotDiagnostic, + measureFullSidebarPaint, +} from "@/features/channels/sidebarPerf"; import { CHANNEL_MEMBERS_STALE_TIME_MS, channelMembersQueryKey, @@ -97,73 +102,6 @@ export function sortChannels(channels: Channel[]) { }); } -export const CHANNELS_SNAPSHOT_DIAGNOSTIC_MARK = - "buzz:sidebar:snapshot-diagnostic"; -export const CHANNELS_FULL_SIDEBAR_PAINT_MARK = - "buzz:sidebar:full-list-painted"; -export const CHANNELS_BOOT_TO_FULL_SIDEBAR_MEASURE = - "buzz:sidebar:boot-to-full-list-painted"; - -const markedSnapshotKeys = new Set(); -const measuredSidebarKeys = new Set(); -const scheduledSidebarKeys = new Set(); - -function sidebarMeasurementKey(relayUrl: string, ownerPubkey: string): string { - return `${relayUrl}\u0000${ownerPubkey.toLowerCase()}`; -} - -function markSnapshotDiagnostic( - relayUrl: string, - ownerPubkey: string, - diagnostics: ReturnType["diagnostics"], -): void { - if (typeof performance === "undefined") return; - const key = sidebarMeasurementKey(relayUrl, ownerPubkey); - if (markedSnapshotKeys.has(key)) return; - markedSnapshotKeys.add(key); - performance.mark(CHANNELS_SNAPSHOT_DIAGNOSTIC_MARK, { - detail: { ...diagnostics, relayUrl }, - }); - console.info("[sidebar-perf] snapshot", { ...diagnostics, relayUrl }); -} - -function measureFullSidebarPaint( - relayUrl: string, - ownerPubkey: string, - channelCount: number, -): void { - if (typeof performance === "undefined") return; - const key = sidebarMeasurementKey(relayUrl, ownerPubkey); - if (measuredSidebarKeys.has(key) || scheduledSidebarKeys.has(key)) return; - scheduledSidebarKeys.add(key); - - // The channels have committed to the shared query cache; two animation frames - // put the mark after React's sidebar DOM commit and the browser's next paint. - window.requestAnimationFrame(() => { - window.requestAnimationFrame(() => { - scheduledSidebarKeys.delete(key); - if (measuredSidebarKeys.has(key)) return; - measuredSidebarKeys.add(key); - performance.mark(CHANNELS_FULL_SIDEBAR_PAINT_MARK, { - detail: { channelCount, relayUrl }, - }); - performance.measure(CHANNELS_BOOT_TO_FULL_SIDEBAR_MEASURE, { - detail: { channelCount, relayUrl }, - duration: performance.now(), - start: 0, - }); - const measure = performance - .getEntriesByName(CHANNELS_BOOT_TO_FULL_SIDEBAR_MEASURE) - .at(-1); - console.info("[sidebar-perf] full list painted", { - channelCount, - durationMs: measure?.duration, - relayUrl, - }); - }); - }); -} - export type CachedChannelMember = { membershipAdded: boolean; name: string; @@ -627,7 +565,15 @@ export function useChannelMembersQuery( throw new Error("No channel selected."); } - return getChannelMembers(channelId); + const fetchStartedAt = performance.now(); + const members = await getChannelMembers(channelId); + traceChannelMembersFetch( + channelId, + members.length, + performance.now() - fetchStartedAt, + fetchStartedAt, + ); + return members; }, staleTime: CHANNEL_MEMBERS_STALE_TIME_MS, }); diff --git a/desktop/src/features/channels/sidebarPerf.ts b/desktop/src/features/channels/sidebarPerf.ts new file mode 100644 index 0000000000..e2904fcd09 --- /dev/null +++ b/desktop/src/features/channels/sidebarPerf.ts @@ -0,0 +1,74 @@ +/** + * Sidebar boot-paint measurement: marks the persisted-snapshot read and the + * first fully-painted channel list per relay+identity. Split from hooks.ts to + * keep that file under the per-file line cap; behavior unchanged. + */ + +import type { inspectChannelSnapshot } from "@/features/channels/channelSnapshot"; + +export const CHANNELS_SNAPSHOT_DIAGNOSTIC_MARK = + "buzz:sidebar:snapshot-diagnostic"; +export const CHANNELS_FULL_SIDEBAR_PAINT_MARK = + "buzz:sidebar:full-list-painted"; +export const CHANNELS_BOOT_TO_FULL_SIDEBAR_MEASURE = + "buzz:sidebar:boot-to-full-list-painted"; + +const markedSnapshotKeys = new Set(); +const measuredSidebarKeys = new Set(); +const scheduledSidebarKeys = new Set(); + +function sidebarMeasurementKey(relayUrl: string, ownerPubkey: string): string { + return `${relayUrl}\u0000${ownerPubkey.toLowerCase()}`; +} + +export function markSnapshotDiagnostic( + relayUrl: string, + ownerPubkey: string, + diagnostics: ReturnType["diagnostics"], +): void { + if (typeof performance === "undefined") return; + const key = sidebarMeasurementKey(relayUrl, ownerPubkey); + if (markedSnapshotKeys.has(key)) return; + markedSnapshotKeys.add(key); + performance.mark(CHANNELS_SNAPSHOT_DIAGNOSTIC_MARK, { + detail: { ...diagnostics, relayUrl }, + }); + console.info("[sidebar-perf] snapshot", { ...diagnostics, relayUrl }); +} + +export function measureFullSidebarPaint( + relayUrl: string, + ownerPubkey: string, + channelCount: number, +): void { + if (typeof performance === "undefined") return; + const key = sidebarMeasurementKey(relayUrl, ownerPubkey); + if (measuredSidebarKeys.has(key) || scheduledSidebarKeys.has(key)) return; + scheduledSidebarKeys.add(key); + + // The channels have committed to the shared query cache; two animation frames + // put the mark after React's sidebar DOM commit and the browser's next paint. + window.requestAnimationFrame(() => { + window.requestAnimationFrame(() => { + scheduledSidebarKeys.delete(key); + if (measuredSidebarKeys.has(key)) return; + measuredSidebarKeys.add(key); + performance.mark(CHANNELS_FULL_SIDEBAR_PAINT_MARK, { + detail: { channelCount, relayUrl }, + }); + performance.measure(CHANNELS_BOOT_TO_FULL_SIDEBAR_MEASURE, { + detail: { channelCount, relayUrl }, + duration: performance.now(), + start: 0, + }); + const measure = performance + .getEntriesByName(CHANNELS_BOOT_TO_FULL_SIDEBAR_MEASURE) + .at(-1); + console.info("[sidebar-perf] full list painted", { + channelCount, + durationMs: measure?.duration, + relayUrl, + }); + }); + }); +} diff --git a/desktop/src/features/channels/ui/ChannelScreen.tsx b/desktop/src/features/channels/ui/ChannelScreen.tsx index 9c2d25dd7c..f76768d73f 100644 --- a/desktop/src/features/channels/ui/ChannelScreen.tsx +++ b/desktop/src/features/channels/ui/ChannelScreen.tsx @@ -71,6 +71,7 @@ import { useHuddleReadMarker } from "@/features/channels/ui/useHuddleReadMarker" import { useHuddleThreadIsolation } from "@/features/channels/ui/useHuddleThreadIsolation"; import { AgentSessionProvider } from "@/shared/context/AgentSessionContext"; import { ProfilePanelProvider } from "@/shared/context/ProfilePanelContext"; +import { useChannelSwitchTraceMarks } from "@/features/channels/useChannelSwitchTraceMarks"; import { useMainInsetRef } from "@/shared/layout/MainInsetContext"; import { channelContentTopPaddingMeasurement } from "@/shared/layout/chromeLayout"; import { useMeasuredCssVariable } from "@/shared/layout/useMeasuredCssVariable"; @@ -639,6 +640,11 @@ export function ChannelScreen({ timelineLoadingNow, ); settledChannelIdRef.current = settledChannelId; + useChannelSwitchTraceMarks({ + activeChannelId, + activeChannelType: activeChannel?.channelType ?? null, + isTimelineLoading, + }); const { welcomeKickoffStage, welcomeKickoffSettingUp } = useWelcomeKickoffStagePresence( activeChannel, diff --git a/desktop/src/features/channels/useChannelSwitchTraceMarks.ts b/desktop/src/features/channels/useChannelSwitchTraceMarks.ts new file mode 100644 index 0000000000..bc49f6d2d6 --- /dev/null +++ b/desktop/src/features/channels/useChannelSwitchTraceMarks.ts @@ -0,0 +1,54 @@ +import * as React from "react"; + +import { + abandonChannelSwitchTrace, + markChannelSwitchRouteCommit, + settleChannelSwitchTrace, +} from "@/shared/lib/channelSwitchPerf"; +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 + * 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 + * underreported. + */ +export function useChannelSwitchTraceMarks({ + activeChannelId, + activeChannelType, + isTimelineLoading, +}: { + activeChannelId: string | null; + activeChannelType: ChannelType | null; + isTimelineLoading: boolean; +}): void { + React.useEffect(() => { + if (activeChannelId) markChannelSwitchRouteCommit(activeChannelId); + }, [activeChannelId]); + // Route-exit cancellation: leaving the channel surface before the trace + // settles (Projects, Home, … — none of which call goChannel) must drop the + // trace. Otherwise a history-back into the same channel within the trace + // timeout matches the stale singleton and records the time spent away as + // switch latency. Keyed per channel id: on an A→B switch this cleanup runs + // with A's id after B's trace already began, so it only ever abandons its + // own channel's trace. + React.useEffect(() => { + if (!activeChannelId) return; + const channelId = activeChannelId; + return () => { + abandonChannelSwitchTrace(channelId); + }; + }, [activeChannelId]); + React.useEffect(() => { + if (!activeChannelId) return; + if (activeChannelType === "forum") { + abandonChannelSwitchTrace(activeChannelId); + return; + } + if (!isTimelineLoading) { + settleChannelSwitchTrace(activeChannelId); + } + }, [activeChannelId, activeChannelType, isTimelineLoading]); +} diff --git a/desktop/src/features/communities/useCommunityInit.ts b/desktop/src/features/communities/useCommunityInit.ts index c565ee0f7b..eb98737895 100644 --- a/desktop/src/features/communities/useCommunityInit.ts +++ b/desktop/src/features/communities/useCommunityInit.ts @@ -34,6 +34,7 @@ import { resetAgentObserverStore } from "@/features/agents/observerRelayStore"; import { resetAvatarPresentations } from "@/features/profile/avatarPresentationStore"; import { resetAvatarProfileSync } from "@/features/profile/avatarProfileSync"; import { resetSidebarRelayConnectionCardState } from "@/features/sidebar/ui/useSidebarRelayConnectionCard"; +import { resetChannelSwitchTrace } from "@/shared/lib/channelSwitchPerf"; import { clearMarkdownNodeCache } from "@/shared/ui/markdown/nodeCache"; import { resetMessageLinkMetadataCache } from "@/shared/ui/markdown/useMessageLinkMetadata"; import { resetVideoPlayerState } from "@/shared/ui/videoPlayerState"; @@ -57,6 +58,10 @@ async function resetCommunityState({ resetAvatarState: boolean; }): Promise { relayClient.disconnect(); + // Before the first await: the trace singleton must not survive into the + // async teardown window — queued frame callbacks could still record against + // it, and a rejection below would skip any reset placed after the await. + resetChannelSwitchTrace(); await resetNavigationDeepLinkDrain(); resetRateLimitGate(); clearAllDrafts(); diff --git a/desktop/src/features/messages/hooks.ts b/desktop/src/features/messages/hooks.ts index d28f292608..9a2de67d97 100644 --- a/desktop/src/features/messages/hooks.ts +++ b/desktop/src/features/messages/hooks.ts @@ -44,6 +44,7 @@ import { recordTimeoutFromRejection, } from "@/features/moderation/lib/timeoutStore"; import { relayClient, setVisibleChannel } from "@/shared/api/relayClient"; +import { traceChannelWindowFetch } from "@/shared/lib/channelSwitchPerf"; import { customEmojiQueryKey } from "@/features/custom-emoji/hooks"; import { channelsQueryKey } from "@/features/channels/hooks"; import { reactionEmojiUrl } from "@/shared/api/customEmoji"; @@ -301,14 +302,27 @@ export function useChannelMessagesQuery(channel: Channel | null) { } const previousMessages = queryClient.getQueryData(queryKey) ?? []; + const fetchStartedAt = performance.now(); const events = await getChannelWindowEvents(channel.id); - return reconcileFetchedChannelWindow( + const fetchDurationMs = performance.now() - fetchStartedAt; + const result = reconcileFetchedChannelWindow( queryClient, channel.id, events, previousMessages, signal, ); + // Attribute only ACCEPTED fetches: reconciliation throws for aborted + // requests, and a canceled fetch that claimed the trace's one-shot + // attribution slot would block the accepted replacement from being + // recorded. Duration still measures the fetch alone, captured above. + traceChannelWindowFetch( + channel.id, + events.length, + fetchDurationMs, + fetchStartedAt, + ); + return result; }, staleTime: 5 * 60 * 1_000, gcTime: 60 * 60 * 1_000, diff --git a/desktop/src/features/messages/lib/projectChannelWindow.test.mjs b/desktop/src/features/messages/lib/projectChannelWindow.test.mjs index 618f3fc991..24ea75edc0 100644 --- a/desktop/src/features/messages/lib/projectChannelWindow.test.mjs +++ b/desktop/src/features/messages/lib/projectChannelWindow.test.mjs @@ -416,3 +416,85 @@ test("test_concurrent_refreshes_after_seeded_snapshot_share_one_authoritative_fe unsubscribe(); } }); + +test("canceled fetch never claims the switch trace's window slot; the accepted one does", async () => { + // Mirror of channelMessagesQueryOptions' queryFn contract: reconciliation + // throws for aborted requests BEFORE the fetch is attributed, so a canceled + // request cannot claim the trace's one-shot `windowFetch` slot and block + // the accepted replacement. + const frames = []; + const originalWindow = globalThis.window; + const originalDocument = globalThis.document; + globalThis.window = { + requestAnimationFrame: (cb) => frames.push(cb) && frames.length, + cancelAnimationFrame: () => {}, + }; + globalThis.document = { querySelector: () => null }; + const { + beginChannelSwitchTrace, + settleChannelSwitchTrace, + resetChannelSwitchTrace, + traceChannelWindowFetch, + CHANNEL_SWITCH_MEASURE, + } = await import("../../../shared/lib/channelSwitchPerf.ts"); + performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); + try { + const client = new QueryClient(); + const channelId = "channel"; // matches wirePage's bounds key + beginChannelSwitchTrace(channelId); + + // Canceled-first: the queryFn reconciles BEFORE attributing; the aborted + // signal throws, so trace attribution is never reached. + const canceled = new AbortController(); + canceled.abort(); + const canceledEvents = wirePage([event("stale", 100)]); + const startedAt = performance.now(); + assert.throws(() => { + reconcileFetchedChannelWindow( + client, + channelId, + canceledEvents, + [], + canceled.signal, + ); + traceChannelWindowFetch(channelId, canceledEvents.length, 1, startedAt); + }); + + // Accepted-second: reconciles cleanly, then claims the slot. + const acceptedEvents = wirePage([ + event("fresh-2", 120), + event("fresh-1", 110), + ]); + reconcileFetchedChannelWindow( + client, + channelId, + acceptedEvents, + [], + new AbortController().signal, + ); + traceChannelWindowFetch( + channelId, + acceptedEvents.length, + 2, + performance.now(), + ); + + settleChannelSwitchTrace(channelId); + for (let i = 0; i < 10 && frames.length > 0; i += 1) { + for (const cb of frames.splice(0, frames.length)) cb(); + } + const measure = performance.getEntriesByName(CHANNEL_SWITCH_MEASURE).at(-1); + assert.equal( + measure?.detail?.windowFetch?.eventCount, + acceptedEvents.length, + "the accepted fetch owns the attribution slot", + ); + resetChannelSwitchTrace(); + } finally { + 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; + } +}); diff --git a/desktop/src/features/messages/ui/MessageTimeline.tsx b/desktop/src/features/messages/ui/MessageTimeline.tsx index fa8bb4e9f6..8222dcdd22 100644 --- a/desktop/src/features/messages/ui/MessageTimeline.tsx +++ b/desktop/src/features/messages/ui/MessageTimeline.tsx @@ -693,7 +693,15 @@ const MessageTimelineBase = React.forwardRef< return ( -
+ {/* The render-pending marker must live on this always-mounted wrapper: + during the skeleton→loaded transition the message-list branches (and + their own markers) are not mounted yet, and the switch tracer would + read "not pending" and record a settle before the heavy deferred + list ever committed or painted. */} +
{showUnreadPill ? (
{useTimelineVirtualizer && timelineList ? ( -
- {timelineList} -
+
{timelineList}
) : (
{timelineList}
diff --git a/desktop/src/shared/lib/channelSwitchPerf.test.mjs b/desktop/src/shared/lib/channelSwitchPerf.test.mjs new file mode 100644 index 0000000000..586ae70a32 --- /dev/null +++ b/desktop/src/shared/lib/channelSwitchPerf.test.mjs @@ -0,0 +1,216 @@ +import assert from "node:assert/strict"; +import test from "node:test"; + +import { + shouldAttributeFetch, + buildSwitchPerfLogRecord, + resolveSettleAction, + summarizeChannelSwitchTrace, +} from "./channelSwitchPerf.ts"; + +function trace(overrides = {}) { + return { + channelId: "abcdef1234567890", + startedAt: 1_000, + routeCommitAt: null, + windowFetch: null, + membersFetch: null, + ...overrides, + }; +} + +test("summary reports total and cache-served fetches", () => { + const summary = summarizeChannelSwitchTrace(trace(), 1_412.4); + assert.equal( + summary, + "[switch-perf] channel=abcdef12 total=412ms commit=? window=cache members=cache", + ); +}); + +test("summary includes route commit offset and fetch timings", () => { + const summary = summarizeChannelSwitchTrace( + trace({ + routeCommitAt: 1_038, + windowFetch: { durationMs: 180.6, eventCount: 250 }, + membersFetch: { durationMs: 320.2, memberCount: 10_000 }, + }), + 1_912, + ); + assert.equal( + summary, + "[switch-perf] channel=abcdef12 total=912ms commit=+38ms " + + "window=250 events in 181ms members=10000 members in 320ms", + ); +}); + +test("log record carries rounded stage timings and fetch attributions", () => { + const record = buildSwitchPerfLogRecord( + trace({ + routeCommitAt: 1_038.4, + windowFetch: { durationMs: 180.6, eventCount: 250 }, + membersFetch: { durationMs: 320.2, memberCount: 10_000 }, + }), + 1_912.3, + ); + assert.equal(record.channelId, "abcdef1234567890"); + assert.equal(record.totalMs, 912); + assert.equal(record.commitOffsetMs, 38); + assert.deepEqual(record.windowFetch, { durationMs: 181, eventCount: 250 }); + assert.deepEqual(record.membersFetch, { + durationMs: 320, + memberCount: 10_000, + }); + assert.equal(typeof record.ts, "string"); +}); + +test("log record marks cache-served fetches and missing commit as null", () => { + const record = buildSwitchPerfLogRecord(trace(), 1_412); + assert.equal(record.commitOffsetMs, null); + assert.equal(record.windowFetch, null); + assert.equal(record.membersFetch, null); +}); + +test("settle resolves only the trace for the settled channel", () => { + const active = trace(); + assert.deepEqual(resolveSettleAction(active, "abcdef1234567890", 2_000), { + settledTrace: active, + clearActive: true, + }); + assert.deepEqual(resolveSettleAction(null, "abcdef1234567890", 2_000), { + settledTrace: null, + clearActive: false, + }); +}); + +test("a mismatched settle never clobbers a newer switch's trace", () => { + // Channel A settles after the user already clicked channel B: B's trace + // must survive so B still gets measured. + const nextSwitch = trace({ channelId: "bbbb0000bbbb0000" }); + assert.deepEqual(resolveSettleAction(nextSwitch, "abcdef1234567890", 2_000), { + settledTrace: null, + clearActive: false, + }); +}); + +test("settle drops a trace that has timed out", () => { + const stale = trace({ startedAt: 1_000 }); + assert.deepEqual(resolveSettleAction(stale, "abcdef1234567890", 31_001), { + settledTrace: null, + clearActive: true, + }); + assert.deepEqual( + resolveSettleAction(stale, "abcdef1234567890", 11_000).settledTrace, + stale, + ); +}); + +test("fetches attribute only when started after the switch began", () => { + const active = trace({ channelId: "abcdef1234567890", startedAt: 1_000 }); + // Started before the switch (stale A→B→A leg): not attributable. + assert.equal(shouldAttributeFetch(active, "abcdef1234567890", 999), false); + // Started at/after the switch: attributable. + assert.equal(shouldAttributeFetch(active, "abcdef1234567890", 1_000), true); + assert.equal(shouldAttributeFetch(active, "abcdef1234567890", 1_500), true); + // Other channel or no trace: never. + assert.equal(shouldAttributeFetch(active, "bbbb0000bbbb0000", 1_500), false); + assert.equal(shouldAttributeFetch(null, "abcdef1234567890", 1_500), false); +}); + +// --- Settle lifecycle: rapid switches and community resets ---------------- + +async function withSettleHarness(run) { + const frames = []; + const originalWindow = globalThis.window; + const originalDocument = globalThis.document; + globalThis.window = { + requestAnimationFrame: (cb) => frames.push(cb) && frames.length, + cancelAnimationFrame: () => {}, + }; + globalThis.document = { querySelector: () => null }; + const { + abandonChannelSwitchTrace, + beginChannelSwitchTrace, + settleChannelSwitchTrace, + resetChannelSwitchTrace, + CHANNEL_SWITCH_MEASURE, + } = await import("./channelSwitchPerf.ts"); + performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); + const flush = () => { + // Drain chained rAFs until quiescent. + for (let i = 0; i < 20 && frames.length > 0; i += 1) { + for (const cb of frames.splice(0, frames.length)) cb(); + } + }; + const measures = () => + performance + .getEntriesByName(CHANNEL_SWITCH_MEASURE) + .map((entry) => entry.detail?.channelId); + try { + await run({ + abandon: abandonChannelSwitchTrace, + begin: beginChannelSwitchTrace, + settle: settleChannelSwitchTrace, + reset: resetChannelSwitchTrace, + flush, + measures, + }); + } finally { + 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 switch begun during A's deferred wait drops A's record (no clock theft)", async () => { + await withSettleHarness(async ({ begin, settle, flush, measures }) => { + begin("aaaa1111aaaa1111"); + settle("aaaa1111aaaa1111"); // A's deferred-paint wait is now queued + begin("bbbb2222bbbb2222"); // rapid follow-up switch replaces the trace + flush(); + // A must NOT be recorded: its settledAt would be sampled from B's + // timeline, charging B's delay to A. + assert.deepEqual(measures(), []); + settle("bbbb2222bbbb2222"); + flush(); + assert.deepEqual(measures(), ["bbbb2222bbbb2222"]); + }); +}); + +test("a community reset during the deferred wait drops the record", async () => { + await withSettleHarness(async ({ begin, settle, reset, flush, measures }) => { + begin("aaaa1111aaaa1111"); + settle("aaaa1111aaaa1111"); + reset(); + flush(); + assert.deepEqual(measures(), []); + }); +}); + +test("an undisturbed settle records exactly one measure", async () => { + await withSettleHarness(async ({ begin, settle, flush, measures }) => { + begin("aaaa1111aaaa1111"); + settle("aaaa1111aaaa1111"); + flush(); + assert.deepEqual(measures(), ["aaaa1111aaaa1111"]); + }); +}); + +test("leaving the channel surface abandons the trace; history-back records nothing", async () => { + await withSettleHarness( + async ({ abandon, begin, settle, flush, measures }) => { + begin("aaaa1111aaaa1111"); + // Route exit (Projects/Home): the channel screen unmounts before the + // trace settled and abandons it. + abandon("aaaa1111aaaa1111"); + // History-back re-enters the channel without goChannel; its settle must + // find no trace — otherwise the time spent away would be recorded as + // switch latency. + settle("aaaa1111aaaa1111"); + flush(); + assert.deepEqual(measures(), []); + }, + ); +}); diff --git a/desktop/src/shared/lib/channelSwitchPerf.ts b/desktop/src/shared/lib/channelSwitchPerf.ts new file mode 100644 index 0000000000..015537179a --- /dev/null +++ b/desktop/src/shared/lib/channelSwitchPerf.ts @@ -0,0 +1,297 @@ +/** + * Channel-switch tracing: measures click → settled-paint for channel + * navigations, with the two relay fetches that can sit on that path + * (message window, member roster) attributed to the switch. + * + * One trace is active at a time; `beginChannelSwitchTrace` (called from + * `goChannel`) opens it and `settleChannelSwitchTrace` (called when the + * timeline settles for that channel) closes it after the next paint. Fetch + * traces and settles for non-active channels are ignored, so background + * refetches never pollute a switch measurement. + * + * 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. + * + * Attribution window: fetches are credited to a switch only when they finish + * 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. + */ + +export type ChannelSwitchFetchTrace = { + durationMs: number; + eventCount?: number; + memberCount?: number; +}; + +import { invoke, isTauri } from "@tauri-apps/api/core"; + +export type ChannelSwitchTrace = { + channelId: string; + startedAt: number; + routeCommitAt: number | null; + windowFetch: { durationMs: number; eventCount: number } | null; + membersFetch: { durationMs: number; memberCount: number } | null; +}; + +/** A switch that hasn't settled after this long is abandoned, not measured. */ +const SWITCH_TRACE_TIMEOUT_MS = 30_000; + +export const CHANNEL_SWITCH_START_MARK = "buzz:channel-switch:start"; +export const CHANNEL_SWITCH_SETTLED_MARK = "buzz:channel-switch:settled"; +export const CHANNEL_SWITCH_MEASURE = "buzz:channel-switch:click-to-settled"; + +let activeTrace: ChannelSwitchTrace | null = null; + +/** Formats one settled trace as the `[switch-perf]` console line. */ +export function summarizeChannelSwitchTrace( + trace: ChannelSwitchTrace, + settledAt: number, +): string { + const total = Math.round(settledAt - trace.startedAt); + const commit = + trace.routeCommitAt === null + ? "?" + : `+${Math.round(trace.routeCommitAt - trace.startedAt)}ms`; + const window = + trace.windowFetch === null + ? "cache" + : `${trace.windowFetch.eventCount} events in ${Math.round(trace.windowFetch.durationMs)}ms`; + const members = + trace.membersFetch === null + ? "cache" + : `${trace.membersFetch.memberCount} members in ${Math.round(trace.membersFetch.durationMs)}ms`; + return ( + `[switch-perf] channel=${trace.channelId.slice(0, 8)} total=${total}ms ` + + `commit=${commit} window=${window} members=${members}` + ); +} + +/** + * The JSONL record persisted per settled switch. The backend folds in the + * build's git revision and the optional BUZZ_PERF_LOG_LABEL run label, so + * before/after sessions are attributable offline. Pure for unit testing. + */ +export function buildSwitchPerfLogRecord( + trace: ChannelSwitchTrace, + settledAt: number, +): { + ts: string; + channelId: string; + totalMs: number; + commitOffsetMs: number | null; + windowFetch: { durationMs: number; eventCount: number } | null; + membersFetch: { durationMs: number; memberCount: number } | null; +} { + return { + ts: new Date().toISOString(), + channelId: trace.channelId, + totalMs: Math.round(settledAt - trace.startedAt), + commitOffsetMs: + trace.routeCommitAt === null + ? null + : Math.round(trace.routeCommitAt - trace.startedAt), + windowFetch: trace.windowFetch + ? { + durationMs: Math.round(trace.windowFetch.durationMs), + eventCount: trace.windowFetch.eventCount, + } + : null, + membersFetch: trace.membersFetch + ? { + durationMs: Math.round(trace.membersFetch.durationMs), + memberCount: trace.membersFetch.memberCount, + } + : null, + }; +} + +let hasAnnouncedLogPath = false; + +/** Fire-and-forget JSONL append; diagnostics must never surface failures. */ +function appendSwitchPerfLogRecord(record: Record): void { + if (!isTauri()) return; + void invoke("append_switch_perf_log", { + recordJson: JSON.stringify(record), + }) + .then((path) => { + if (!hasAnnouncedLogPath) { + hasAnnouncedLogPath = true; + console.info(`[switch-perf] logging to ${path}`); + } + }) + .catch(() => {}); +} + +/** + * Decides what a settle call does with the active trace. A settle for a + * different channel must leave the trace alone — a previous channel can + * finish loading after the next switch already began, and clobbering the + * newer trace would silently drop exactly the slow/rapid switches this + * instrumentation exists to capture. Only the settled channel's own trace is + * consumed (measured, or dropped when timed out). Pure so the attribution + * rules are unit-testable. + */ +export function resolveSettleAction( + trace: ChannelSwitchTrace | null, + channelId: string, + now: number, +): { settledTrace: ChannelSwitchTrace | null; clearActive: boolean } { + if (!trace || trace.channelId !== channelId) { + return { settledTrace: null, clearActive: false }; + } + if (now - trace.startedAt > SWITCH_TRACE_TIMEOUT_MS) { + return { settledTrace: null, clearActive: true }; + } + return { settledTrace: trace, clearActive: true }; +} + +/** + * Drops the active trace for surfaces whose readiness this instrument cannot + * observe (e.g. forum channels, whose loading is owned by ForumView's own + * queries). Better no measurement than a systematically underreported one. + */ +export function abandonChannelSwitchTrace(channelId: string): void { + if (activeTrace?.channelId === channelId) { + activeTrace = null; + } +} + +export function beginChannelSwitchTrace(channelId: string): void { + if (typeof performance === "undefined") return; + activeTrace = { + channelId, + startedAt: performance.now(), + routeCommitAt: null, + windowFetch: null, + membersFetch: null, + }; + performance.mark(CHANNEL_SWITCH_START_MARK, { detail: { channelId } }); +} + +export function markChannelSwitchRouteCommit(channelId: string): void { + if (typeof performance === "undefined") return; + if (!activeTrace || activeTrace.channelId !== channelId) return; + if (activeTrace.routeCommitAt !== null) return; + activeTrace.routeCommitAt = performance.now(); +} + +/** + * A fetch attributes to the active trace only when it targets the traced + * channel AND started after the switch began. A fetch that started before + * the switch (e.g. the first leg of a rapid A→B→A completing during the + * second A trace) is not this switch's cost; letting it claim the `??=` + * slot would also block the real fetch. Pure for unit testing. + */ +export function shouldAttributeFetch( + trace: ChannelSwitchTrace | null, + channelId: string, + fetchStartedAt: number, +): trace is ChannelSwitchTrace { + if (!trace || trace.channelId !== channelId) return false; + return fetchStartedAt >= trace.startedAt; +} + +export function traceChannelWindowFetch( + channelId: string, + eventCount: number, + durationMs: number, + fetchStartedAt: number, +): void { + if (!shouldAttributeFetch(activeTrace, channelId, fetchStartedAt)) return; + activeTrace.windowFetch ??= { durationMs, eventCount }; +} + +export function traceChannelMembersFetch( + channelId: string, + memberCount: number, + durationMs: number, + fetchStartedAt: number, +): void { + if (!shouldAttributeFetch(activeTrace, channelId, fetchStartedAt)) return; + activeTrace.membersFetch ??= { durationMs, memberCount }; +} + +/** + * Drops any active trace. Community switches remount the app shell but this + * module-level singleton survives; channel ids are community-scoped, so a + * stale trace could adopt the next community's fetches. Wired into + * resetCommunityState() like every community-scoped singleton. + */ +export function resetChannelSwitchTrace(): void { + activeTrace = null; +} + +/** Bound on waiting for the deferred timeline commit before recording. */ +const SETTLE_RENDER_WAIT_MS = 5_000; + +/** + * Closes the active trace once the settled frame has painted. The timeline + * renders rows through a deferred snapshot that exposes + * `data-render-pending` until the low-priority commit catches up — waiting + * for it (bounded) keeps `totalMs` honest on render-heavy switches; a final + * rAF pair then lands the mark after the browser paints. + */ +export function settleChannelSwitchTrace(channelId: string): void { + if (typeof performance === "undefined") return; + const { settledTrace, clearActive } = resolveSettleAction( + activeTrace, + channelId, + performance.now(), + ); + if (!settledTrace) { + if (clearActive) activeTrace = null; + return; + } + const trace = settledTrace; + if (typeof window === "undefined") { + activeTrace = null; + return; + } + // 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. + const waitDeadline = performance.now() + SETTLE_RENDER_WAIT_MS; + const record = () => { + const settledAt = performance.now(); + if (activeTrace === trace) activeTrace = null; + performance.mark(CHANNEL_SWITCH_SETTLED_MARK, { + detail: { channelId }, + }); + performance.measure(CHANNEL_SWITCH_MEASURE, { + detail: { + channelId, + routeCommitAt: trace.routeCommitAt, + windowFetch: trace.windowFetch, + membersFetch: trace.membersFetch, + }, + start: trace.startedAt, + end: settledAt, + }); + console.info(summarizeChannelSwitchTrace(trace, settledAt)); + appendSwitchPerfLogRecord(buildSwitchPerfLogRecord(trace, settledAt)); + }; + const awaitDeferredCommit = () => { + if (activeTrace !== trace) { + // A newer switch replaced this trace, or a community reset dropped it. + // Either way the paint this callback would sample is not this switch's + // 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. + return; + } + if ( + performance.now() < waitDeadline && + document.querySelector('[data-render-pending="true"]') !== null + ) { + window.requestAnimationFrame(awaitDeferredCommit); + return; + } + window.requestAnimationFrame(() => { + if (activeTrace !== trace) return; + record(); + }); + }; + window.requestAnimationFrame(awaitDeferredCommit); +} diff --git a/desktop/src/testing/e2eBridge.ts b/desktop/src/testing/e2eBridge.ts index 94f6c1fcc4..30f3b96746 100644 --- a/desktop/src/testing/e2eBridge.ts +++ b/desktop/src/testing/e2eBridge.ts @@ -12040,6 +12040,9 @@ export function maybeInstallE2eTauriMocks() { }, activeConfig, ); + case "append_switch_perf_log": + // Perf-trace JSONL sink — a real file makes no sense in mock runs. + return "/mock/switch-perf.jsonl"; case "get_os_idle_seconds": // e2e runs headless with no OS idle API; the presence hook falls back // to in-app activity tracking. diff --git a/desktop/tests/e2e/switch-settle-after-paint.spec.ts b/desktop/tests/e2e/switch-settle-after-paint.spec.ts new file mode 100644 index 0000000000..ce8e223df6 --- /dev/null +++ b/desktop/tests/e2e/switch-settle-after-paint.spec.ts @@ -0,0 +1,58 @@ +import { expect, test } from "@playwright/test"; + +import { installMockBridge } from "../helpers/bridge"; + +/** + * The switch trace must settle AFTER the deferred timeline has committed and + * painted. During the skeleton→loaded transition the message-list branches + * (which used to own the `data-render-pending` marker) are not mounted, so a + * tracer polling only that marker would read "not pending" and record a + * settle while the heavy deferred list was still uncommitted — underreporting + * exactly the switches the tracer exists to measure. The marker now lives on + * the timeline's always-mounted wrapper; this spec pins the contract on a + * real empty→loaded cold switch into a deep channel. + */ + +const SWITCH_MEASURE = "buzz:channel-switch:click-to-settled"; + +test("cold-switch settle measure lands only after rows are painted", async ({ + page, +}) => { + await installMockBridge(page, { deepHistoryMessageCount: 600 }); + await page.goto("/"); + await expect(page.getByTestId("app-sidebar")).toBeVisible(); + + // Cold first entry: skeleton → deferred list commit → settled paint. + await page.getByTestId("channel-deep-history").click(); + + // Poll for the settle measure inside the page and — in the same synchronous + // evaluation turn — snapshot what the DOM shows at that moment. Reading the + // DOM from the test process after the fact would race further renders. + const atSettle = await page.evaluate(async (measureName) => { + const deadline = Date.now() + 15_000; + while (Date.now() < deadline) { + if (performance.getEntriesByName(measureName).length > 0) { + return { + renderPending: + document.querySelector('[data-render-pending="true"]') !== null, + rowCount: document.querySelectorAll( + '[data-message-id^="mock-deep-history-"]', + ).length, + settled: true, + }; + } + await new Promise((resolve) => setTimeout(resolve, 16)); + } + return { renderPending: true, rowCount: 0, settled: false }; + }, SWITCH_MEASURE); + + expect(atSettle.settled, "switch trace must settle").toBe(true); + expect( + atSettle.rowCount, + "settle must not be recorded before the deferred list painted", + ).toBeGreaterThan(0); + expect( + atSettle.renderPending, + "settle must not be recorded while a deferred commit is still pending", + ).toBe(false); +});