From 370c6687cf4b356ac2e9af4d4aa998fd43ee810a Mon Sep 17 00:00:00 2001 From: Max Lampert Date: Thu, 20 Aug 2026 13:47:13 -0700 Subject: [PATCH] perf(desktop): trace channel switches from click to settled paint MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add a single-active-trace instrument for channel navigation: goChannel opens the trace, ChannelScreen marks route commit and settles it after the timeline loading latch clears (double rAF so the frame painted). The two relay fetches that can sit on the switch path — the message window and the member roster — are attributed to the trace when they run during it; cache-served switches log "cache". Each switch emits one [switch-perf] console line plus User Timing marks/measures (buzz:channel-switch:*) so before/after comparisons work identically in a dev build, the Performance panel, and Playwright perf specs. Signed-off-by: Max Lampert --- desktop/playwright.config.ts | 1 + desktop/src-tauri/build.rs | 28 ++ desktop/src-tauri/src/commands/mod.rs | 2 + desktop/src-tauri/src/commands/perf_log.rs | 268 ++++++++++++++++ desktop/src-tauri/src/lib.rs | 1 + .../src/app/navigation/useAppNavigation.ts | 13 +- desktop/src/features/channels/hooks.ts | 82 +---- desktop/src/features/channels/sidebarPerf.ts | 74 +++++ .../features/channels/ui/ChannelScreen.tsx | 6 + .../channels/useChannelSwitchTraceMarks.ts | 54 ++++ .../features/communities/useCommunityInit.ts | 5 + desktop/src/features/messages/hooks.ts | 16 +- .../lib/projectChannelWindow.test.mjs | 82 +++++ .../features/messages/ui/MessageTimeline.tsx | 18 +- .../src/shared/lib/channelSwitchPerf.test.mjs | 216 +++++++++++++ desktop/src/shared/lib/channelSwitchPerf.ts | 297 ++++++++++++++++++ desktop/src/testing/e2eBridge.ts | 3 + .../e2e/switch-settle-after-paint.spec.ts | 58 ++++ 18 files changed, 1146 insertions(+), 78 deletions(-) create mode 100644 desktop/src-tauri/src/commands/perf_log.rs create mode 100644 desktop/src/features/channels/sidebarPerf.ts create mode 100644 desktop/src/features/channels/useChannelSwitchTraceMarks.ts create mode 100644 desktop/src/shared/lib/channelSwitchPerf.test.mjs create mode 100644 desktop/src/shared/lib/channelSwitchPerf.ts create mode 100644 desktop/tests/e2e/switch-settle-after-paint.spec.ts 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); +});