From c299a22ea761ef434c7b578b0a63d5e8aa76d7e9 Mon Sep 17 00:00:00 2001 From: Max Lampert Date: Wed, 26 Aug 2026 19:58:15 -0700 Subject: [PATCH] refactor(desktop): cut the switch tracer to a simple, honest metric The instrument was accumulating defects faster than it was answering questions. Nearly every review finding lived in a seam that existed only because the tracer inferred more than it could observe: a starvation heartbeat, a per-seam guard matrix, DOM-attribute sniffing with a commit generation, click anchors threaded by hand through nine async call sites, and an on-disk JSONL sink with rotation and byte caps. Each fix added a seam, and the next review found the guard that seam was missing. The perf work these numbers support matters more than the numbers, so the instrument is now scoped to what it can measure without inference: - click (or navigation) -> route commit -> settled paint, as a console line plus User Timing marks/measures. That is what the Performance panel and the perf harness read. - the message-window fetch when it starts inside that interval. - one drop rule per unmeasurable condition (hidden window, timeout, superseded, left the surface), each printing why. Removed: the Rust perf-log sink and its git-revision baking, the click-anchor threading and every call site that existed only to carry it, the starvation heartbeat, the roster-fetch attribution and its sequence machinery, and the commit-generation burst gate. Scope bounds are now stated in the module doc rather than inferred: callers that await before navigating are measured from the navigation, a bounded frame wait replaces the 5s render deadline, and a sample past that bound is flagged rather than dropped. Net: 2231 lines removed, 462 added. Signed-off-by: Max Lampert --- desktop/src-tauri/build.rs | 28 - desktop/src-tauri/src/commands/mod.rs | 2 - desktop/src-tauri/src/commands/perf_log.rs | 416 -------- desktop/src-tauri/src/lib.rs | 1 - desktop/src/app/AppShell.tsx | 8 +- .../commitGuardedNavigation.test.mjs | 86 -- .../app/navigation/commitGuardedNavigation.ts | 23 +- .../src/app/navigation/useAppNavigation.ts | 27 +- .../src/features/agents/ui/AgentsScreen.tsx | 5 +- desktop/src/features/channels/hooks.ts | 92 +- desktop/src/features/channels/sidebarPerf.ts | 74 -- .../channels/ui/useChannelProfilePanel.ts | 5 +- .../useChannelSwitchTraceMarks.test.mjs | 20 - .../channels/useChannelSwitchTraceMarks.ts | 20 - desktop/src/features/home/ui/HomeView.tsx | 5 +- .../features/messages/ui/MessageTimeline.tsx | 27 +- .../features/messages/ui/NewMessageScreen.tsx | 3 - .../ui/useProfileInteractionActions.ts | 12 +- .../projects/ui/useProjectProfilePanel.ts | 5 +- .../src/features/pulse/lib/useNoteActions.ts | 7 +- desktop/src/features/pulse/ui/PulseScreen.tsx | 5 +- .../src/shared/lib/channelSwitchPerf.test.mjs | 942 +++++------------- desktop/src/shared/lib/channelSwitchPerf.ts | 866 +++------------- .../e2e/switch-settle-after-paint.spec.ts | 86 +- 24 files changed, 498 insertions(+), 2267 deletions(-) delete mode 100644 desktop/src-tauri/src/commands/perf_log.rs delete mode 100644 desktop/src/features/channels/sidebarPerf.ts diff --git a/desktop/src-tauri/build.rs b/desktop/src-tauri/build.rs index 63dfa91dc6..2cdd785c73 100644 --- a/desktop/src-tauri/build.rs +++ b/desktop/src-tauri/build.rs @@ -8,34 +8,6 @@ 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 0389c20ece..7cb2d8e3b8 100644 --- a/desktop/src-tauri/src/commands/mod.rs +++ b/desktop/src-tauri/src/commands/mod.rs @@ -44,7 +44,6 @@ mod notifications; mod observer_archive; mod os_idle; pub mod pairing; -mod perf_log; mod personas; mod prevent_sleep; mod profile; @@ -106,7 +105,6 @@ 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 deleted file mode 100644 index 51249be618..0000000000 --- a/desktop/src-tauri/src/commands/perf_log.rs +++ /dev/null @@ -1,416 +0,0 @@ -//! 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. Enforced on the input -/// record and again on the final serialized line, so folded-in metadata can -/// never defeat it. -const MAX_RECORD_BYTES: usize = 4 * 1024; - -/// Upper bound on the operator-supplied `BUZZ_PERF_LOG_LABEL` run label. -/// Truncating (rather than erroring) keeps a fat-fingered label from -/// silently dropping every trace for the whole run — the frontend swallows -/// sink errors by design. -const MAX_LABEL_BYTES: usize = 128; - -/// Truncates to the last char boundary at or below `max_bytes`. -fn truncate_at_char_boundary(text: &str, max_bytes: usize) -> &str { - if text.len() <= max_bytes { - return text; - } - let mut end = max_bytes; - while !text.is_char_boundary(end) { - end -= 1; - } - &text[..end] -} - -/// 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( - truncate_at_char_boundary(label, MAX_LABEL_BYTES).to_string(), - ), - ); - } - let line = serde_json::to_string(&value).map_err(|e| e.to_string())?; - // The cap must hold for what actually reaches the disk: gitSha and label - // are folded in after the record-size check above, and writeln! appends - // a newline terminator — reserve one byte for it. - if line.len() + 1 > MAX_RECORD_BYTES { - return Err("perf log line too large".to_string()); - } - Ok(line) -} - -/// 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. Same - // platform rule as managed_agents::storage::start_install_log_session. - // - // Rotation itself is best-effort: an AV/EDR or editor holding a - // transient lock (again, chiefly Windows) would otherwise fail - // EVERY append until the lock clears — the frontend deliberately - // swallows sink errors, so records would vanish silently. - // Degrade to an unrotated append; the size cap re-applies once - // rotation succeeds on a later write. - let rotation = (|| -> std::io::Result<()> { - if rotated.exists() { - std::fs::remove_file(&rotated)?; - } - std::fs::rename(path, &rotated) - })(); - if let Err(e) = rotation { - eprintln!("buzz-desktop: perf-log rotation failed, appending unrotated: {e}"); - } - } - } - let mut file = std::fs::OpenOptions::new() - .create(true) - .append(true) - .open(path) - .map_err(|e| e.to_string())?; - // One write_all, not writeln!: writeln! issues two write syscalls (line, - // then newline), and PERF_LOG_LOCK is process-local while the path is - // not — a second Buzz process sharing the log dir could interleave - // between them. A single O_APPEND write keeps lines atomic. - file.write_all(format!("{line}\n").as_bytes()) - .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 shape_truncates_an_unbounded_label_and_keeps_the_line_capped() { - // BUZZ_PERF_LOG_LABEL is operator-supplied; a runaway value must not - // defeat the record cap by being folded in after the size check. - let label = "l".repeat(1024 * 1024); - let line = - shape_perf_log_line(r#"{"totalMs":13}"#, Some("abc123"), Some(&label)).expect("shape"); - assert!(line.len() <= MAX_RECORD_BYTES, "line stays under the cap"); - let value: serde_json::Value = serde_json::from_str(&line).expect("parse"); - assert_eq!( - value["label"].as_str().expect("label").len(), - MAX_LABEL_BYTES - ); - assert_eq!(value["totalMs"], 13); - } - - #[test] - fn label_truncation_cuts_at_a_char_boundary() { - // '€' is 3 bytes; MAX_LABEL_BYTES (128) is not a multiple of 3, so a - // byte-index cut would split a char and panic (or emit invalid UTF-8). - let label = "€".repeat(MAX_LABEL_BYTES); - let line = shape_perf_log_line(r#"{"totalMs":1}"#, None, Some(&label)).expect("shape"); - let value: serde_json::Value = serde_json::from_str(&line).expect("parse"); - let stored = value["label"].as_str().expect("label"); - assert_eq!(stored.len(), MAX_LABEL_BYTES - (MAX_LABEL_BYTES % 3)); - assert!(stored.chars().all(|c| c == '€')); - } - - #[test] - fn shape_rejects_a_line_that_outgrows_the_cap_after_metadata() { - // The record alone passes the input check; the folded-in git sha - // pushes the serialized line over the cap. - let pad = "x".repeat(MAX_RECORD_BYTES - 20); - let record = format!(r#"{{"pad":"{pad}"}}"#); - assert!(record.len() <= MAX_RECORD_BYTES); - assert!(shape_perf_log_line(&record, Some(&"s".repeat(64)), None).is_err()); - } - - #[test] - fn the_cap_bounds_bytes_on_disk_including_the_newline() { - // Shaped line = {"pad":"…","gitSha":null} → pad length + 24 bytes. - // The largest accepted line is MAX_RECORD_BYTES - 1: writeln! appends - // a newline, and the cap bounds what reaches the disk. - let fits = format!(r#"{{"pad":"{}"}}"#, "x".repeat(MAX_RECORD_BYTES - 25)); - let line = shape_perf_log_line(&fits, None, None).expect("one byte reserved for newline"); - assert_eq!(line.len(), MAX_RECORD_BYTES - 1); - - let dir = std::env::temp_dir().join(format!( - "perf-log-newline-{}-{:?}", - 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); - append_line_rotating(&path, &line, MAX_LOG_BYTES).expect("append"); - assert_eq!( - std::fs::metadata(&path).expect("metadata").len(), - MAX_RECORD_BYTES as u64, - "on-disk record must not exceed the cap" - ); - std::fs::remove_dir_all(&dir).ok(); - - // One pad byte more serializes to exactly MAX_RECORD_BYTES, which - // would write MAX_RECORD_BYTES + 1 bytes — rejected. - let over = format!(r#"{{"pad":"{}"}}"#, "x".repeat(MAX_RECORD_BYTES - 24)); - assert!(shape_perf_log_line(&over, 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 a_failed_rotation_degrades_to_an_unrotated_append() { - let dir = std::env::temp_dir().join(format!( - "perf-log-degrade-{}-{:?}", - 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"); - std::fs::write(&path, "oversized-live\n").expect("seed live"); - // A non-empty DIRECTORY at the rotated path defeats remove_file and - // rename on every platform — including for root, where permission - // tricks no-op (containers often run tests as uid 0). It stands in - // for a transient AV/EDR hold: the append must degrade to the - // unrotated file, not drop records until the lock clears. - std::fs::create_dir_all(rotated.join("hold")).expect("seed blocker"); - - append_line_rotating(&path, "must-survive", 8) - .expect("append must survive a failed rotation"); - - assert_eq!( - std::fs::read_to_string(&path).expect("read live"), - "oversized-live\nmust-survive\n" - ); - assert!(rotated.join("hold").exists(), "blocker untouched"); - 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 18 bytes on disk (17 chars + newline) = 576 - // bytes against a 384-byte cap: rotation triggers before the 23rd - // append (22 lines = 396 bytes ≥ 384) and the ≤10 lines that follow - // (≤180 bytes) cannot re-trigger it, so the boundary is crossed - // exactly once and 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(); - // Unconditional: if rotation never fired under contention, the size - // cap is inoperative and this test must fail, not silently pass with - // all 32 lines in the live file. - let rotated = std::fs::read_to_string(dir.join("switch-perf.jsonl.1")) - .expect("rotation must have occurred under contention"); - 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 ac13a22c84..613040b809 100644 --- a/desktop/src-tauri/src/lib.rs +++ b/desktop/src-tauri/src/lib.rs @@ -591,7 +591,6 @@ 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/AppShell.tsx b/desktop/src/app/AppShell.tsx index 777fe882f0..468435e15e 100644 --- a/desktop/src/app/AppShell.tsx +++ b/desktop/src/app/AppShell.tsx @@ -13,7 +13,6 @@ import { TerminalContextOverrideProvider, } from "@/app/TerminalContextOverrideContext"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { useBackForwardControls } from "@/app/navigation/useBackForwardControls"; import { useCommunityNavigationTransitions } from "@/app/useCommunityNavigationTransitions"; import { useLiveHomeFeedActions } from "@/app/useLiveHomeFeedActions"; @@ -866,16 +865,11 @@ export function AppShell() { onMarkChannelUnread={markChannelUnread} onBrowseChannels={handleOpenBrowseChannels} onOpenDm={async ({ pubkeys }) => { - // Anchor before awaiting open_dm; see - // captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); const directMessage = await openDmMutation.mutateAsync({ pubkeys, }); - await goChannel(directMessage.id, { - traceStartedAt, - }); + await goChannel(directMessage.id); }} onSelectAgents={() => void goAgents()} onSelectChannel={handleSidebarChannelSelect} diff --git a/desktop/src/app/navigation/commitGuardedNavigation.test.mjs b/desktop/src/app/navigation/commitGuardedNavigation.test.mjs index 5895b9debc..0b836ec20b 100644 --- a/desktop/src/app/navigation/commitGuardedNavigation.test.mjs +++ b/desktop/src/app/navigation/commitGuardedNavigation.test.mjs @@ -268,89 +268,3 @@ test("a same-destination navigation carrying router state still commits", async assert.equal(committed, true); assert.deepEqual(order, ["guard", "navigate"]); }); - -test("a rejected navigate cancels the trace it opened", async () => { - await withTraceHarness(async ({ flush, measures }) => { - // Router/loader rejection: no destination committed, so the trace must - // not survive for a later untraced re-entry to settle with the failed - // attempt plus everything in between. - await assert.rejects( - commitGuardedNavigation({ - currentHref: "/channels/aaaa", - nextHref: "/channels/bbbb", - guardedTarget: route("/channels/bbbb"), - traceChannelId: "bbbb", - navigate: async () => { - throw new Error("loader failed"); - }, - }), - /loader failed/, - ); - settleChannelSwitchTrace("bbbb"); - flush(); - assert.deepEqual(measures(), []); - }); -}); - -test("a rejected navigate never cancels a newer same-channel trace", async () => { - await withTraceHarness(async ({ flush, measures }) => { - // Cancel by identity, not by channel: the retry's trace is a different - // object and must keep its measurement when the first attempt rejects. - let releaseFirst; - const firstGate = new Promise((resolve) => { - releaseFirst = resolve; - }); - const failing = assert.rejects( - commitGuardedNavigation({ - currentHref: "/channels/aaaa", - nextHref: "/channels/bbbb", - guardedTarget: route("/channels/bbbb"), - traceChannelId: "bbbb", - navigate: async () => { - await firstGate; - throw new Error("loader failed"); - }, - }), - /loader failed/, - ); - // Retry lands while the first attempt is still in flight. - await commitGuardedNavigation({ - currentHref: "/channels/aaaa", - nextHref: "/channels/bbbb", - guardedTarget: route("/channels/bbbb"), - force: true, - traceChannelId: "bbbb", - navigate: async () => {}, - }); - releaseFirst(); - await failing; - settleChannelSwitchTrace("bbbb"); - flush(); - assert.deepEqual(measures(), ["bbbb"]); - }); -}); - -test("a DM caller's click anchor is carried into the trace", async () => { - await withTraceHarness(async () => { - const anchors = []; - await commitGuardedNavigation( - { - currentHref: "/", - nextHref: "/channels/bbbb", - guardedTarget: route("/channels/bbbb"), - traceChannelId: "bbbb", - traceStartedAt: 1234, - navigate: async () => {}, - }, - { - allow: () => true, - beginTrace: (channelId, anchoredAt) => { - anchors.push([channelId, anchoredAt]); - return null; - }, - }, - ); - // Without this the open_dm round-trip would sit outside the measurement. - assert.deepEqual(anchors, [["bbbb", 1234]]); - }); -}); diff --git a/desktop/src/app/navigation/commitGuardedNavigation.ts b/desktop/src/app/navigation/commitGuardedNavigation.ts index 2565ed1efa..449442f5c9 100644 --- a/desktop/src/app/navigation/commitGuardedNavigation.ts +++ b/desktop/src/app/navigation/commitGuardedNavigation.ts @@ -4,7 +4,6 @@ import { } from "@/app/navigation/navigationGuard"; import { beginChannelSwitchTrace, - cancelChannelSwitchTrace, dropActiveChannelSwitchTrace, } from "@/shared/lib/channelSwitchPerf"; @@ -19,12 +18,8 @@ import { * navigation (deliberately untraced) would settle with the refused click's * inflated wall time. When `leavesChannelSurface` is set, any active trace is * dropped instead: the trace may be live with no channel screen mounted - * (route still resolving), so this is the only reliable exit hook. A - * `navigate()` rejection cancels the trace this call opened — by identity, so - * a newer same-channel attempt is never erased — because no destination - * committed and an untraced re-entry would otherwise settle the failed - * attempt. Returns whether the navigation was performed. `deps` exists for - * unit tests. + * (route still resolving), so this is the only reliable exit hook. Returns + * whether the navigation was performed. `deps` exists for unit tests. */ export async function commitGuardedNavigation( input: { @@ -35,20 +30,16 @@ export async function commitGuardedNavigation( hasStateUpdate?: boolean; leavesChannelSurface?: boolean; traceChannelId?: string; - /** Click-time anchor for callers that await before `goChannel`. */ - traceStartedAt?: number; navigate: () => Promise; }, deps: { allow?: typeof allowNavigation; beginTrace?: typeof beginChannelSwitchTrace; - cancelTrace?: typeof cancelChannelSwitchTrace; dropActiveTrace?: typeof dropActiveChannelSwitchTrace; } = {}, ): Promise { const allow = deps.allow ?? allowNavigation; const beginTrace = deps.beginTrace ?? beginChannelSwitchTrace; - const cancelTrace = deps.cancelTrace ?? cancelChannelSwitchTrace; const dropActiveTrace = deps.dropActiveTrace ?? dropActiveChannelSwitchTrace; if ( input.currentHref === input.nextHref && @@ -63,15 +54,9 @@ export async function commitGuardedNavigation( if (input.leavesChannelSurface) { dropActiveTrace(); } - let handle = null; if (input.traceChannelId !== undefined) { - handle = beginTrace(input.traceChannelId, input.traceStartedAt) ?? null; - } - try { - await input.navigate(); - } catch (error) { - cancelTrace(handle); - throw error; + beginTrace(input.traceChannelId); } + await input.navigate(); return true; } diff --git a/desktop/src/app/navigation/useAppNavigation.ts b/desktop/src/app/navigation/useAppNavigation.ts index 2f08b25925..c963bc25e6 100644 --- a/desktop/src/app/navigation/useAppNavigation.ts +++ b/desktop/src/app/navigation/useAppNavigation.ts @@ -42,7 +42,6 @@ export function useAppNavigation() { behavior: NavigationBehavior = {}, guardedTarget?: GuardedNavigation, traceChannelId?: string, - traceStartedAt?: number, ) => { const nextLocation = router.buildLocation(next as never); return commitGuardedNavigation({ @@ -67,7 +66,6 @@ export function useAppNavigation() { } as never), nextHref: nextLocation.href, traceChannelId, - traceStartedAt, }); }, [location.href, navigate, router], @@ -283,13 +281,6 @@ export function useAppNavigation() { preserveSearchHighlight?: boolean; searchHighlight?: SearchHighlightNavigation; replace?: boolean; - /** - * Click-time anchor from `captureSwitchTraceAnchor()`, for callers - * that must await before they know the channel id (DM actions await - * `open_dm`). Without it the trace would start after that relay - * round-trip and exclude felt click latency. - */ - traceStartedAt?: number; /** Open this thread panel directly without waiting for a timeline row. */ thread?: string; threadRootId?: string | null; @@ -334,20 +325,16 @@ export function useAppNavigation() { threadRootId: options.threadRootId ?? null, } : undefined, - // goChannel is the click-time anchor for the switch trace; it opens - // inside commitGuardedNavigation only after the navigation guard - // accepts. Coverage: sidebar, search, notification, and DM-open - // navigations all funnel through here; DM callers pass traceStartedAt - // so the open_dm round-trip stays inside the measurement. History - // back/forward is deliberately untraced. Navigations that stay on the - // already-active channel (exact re-click only rewrites router state; - // jump-to-message/autoSend/force change only search params) never - // re-run the channel's settle effects, so a trace could only time out - // — also untraced. + // goChannel is the anchor for the switch trace; it opens inside + // commitGuardedNavigation only after the navigation guard accepts. + // Callers that await before navigating (DM actions await open_dm) + // are measured from the navigation, not from their click — see the + // scope note in channelSwitchPerf.ts. History back/forward is + // untraced, and navigations that stay on the already-active channel + // never re-run the settle effects, so a trace could only time out. location.pathname.endsWith(`/channels/${channelId}`) ? undefined : channelId, - options?.traceStartedAt, ); }, [commitNavigation, location.pathname], diff --git a/desktop/src/features/agents/ui/AgentsScreen.tsx b/desktop/src/features/agents/ui/AgentsScreen.tsx index 5c37d18e5c..361199c50d 100644 --- a/desktop/src/features/agents/ui/AgentsScreen.tsx +++ b/desktop/src/features/agents/ui/AgentsScreen.tsx @@ -1,7 +1,6 @@ import * as React from "react"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { usePersonasQuery } from "@/features/agents/hooks"; import { useOpenDmMutation } from "@/features/channels/hooks"; import { @@ -111,10 +110,8 @@ export function AgentsScreen() { const handleOpenDm = React.useCallback( async (pubkeys: string[]) => { - // Anchor before awaiting open_dm; see captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); const dm = await openDmMutation.mutateAsync({ pubkeys }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); }, [goChannel, openDmMutation], ); diff --git a/desktop/src/features/channels/hooks.ts b/desktop/src/features/channels/hooks.ts index beef0614a6..9069b052da 100644 --- a/desktop/src/features/channels/hooks.ts +++ b/desktop/src/features/channels/hooks.ts @@ -42,10 +42,6 @@ import type { } from "@/shared/api/tauriChannels"; import { mergeConcurrentChannelRecency } from "@/features/channels/lib/channelRecencyMerge"; import { useIdentityQuery } from "@/shared/api/hooks"; -import { - openChannelMembersFetch, - traceChannelMembersFetch, -} from "@/shared/lib/channelSwitchPerf"; import { useFocusedRefetchInterval } from "@/shared/lib/useDocumentVisible"; import { useCommunities } from "@/features/communities/useCommunities"; import { @@ -53,10 +49,6 @@ import { type ChannelSnapshot, writeChannelSnapshot, } from "@/features/channels/channelSnapshot"; -import { - markSnapshotDiagnostic, - measureFullSidebarPaint, -} from "@/features/channels/sidebarPerf"; import { CHANNEL_MEMBERS_STALE_TIME_MS, channelMembersQueryKey, @@ -105,6 +97,73 @@ 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; @@ -568,22 +627,7 @@ export function useChannelMembersQuery( throw new Error("No channel selected."); } - // Supersession token, NOT the query's AbortSignal: reading the signal - // getter flips React Query to cancel-and-revert when the last observer - // unsubscribes mid-fetch, which would discard warm rosters on - // interrupted switches. The token keeps stale fetches (replaced by a - // live join/leave invalidation) out of the trace's one-shot slot. - const fetchAttempt = openChannelMembersFetch(channelId); - const fetchStartedAt = performance.now(); - const members = await getChannelMembers(channelId); - traceChannelMembersFetch( - channelId, - members.length, - performance.now() - fetchStartedAt, - fetchStartedAt, - fetchAttempt, - ); - return members; + return getChannelMembers(channelId); }, staleTime: CHANNEL_MEMBERS_STALE_TIME_MS, }); diff --git a/desktop/src/features/channels/sidebarPerf.ts b/desktop/src/features/channels/sidebarPerf.ts deleted file mode 100644 index e2904fcd09..0000000000 --- a/desktop/src/features/channels/sidebarPerf.ts +++ /dev/null @@ -1,74 +0,0 @@ -/** - * 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/useChannelProfilePanel.ts b/desktop/src/features/channels/ui/useChannelProfilePanel.ts index 5631926fe6..1a35666478 100644 --- a/desktop/src/features/channels/ui/useChannelProfilePanel.ts +++ b/desktop/src/features/channels/ui/useChannelProfilePanel.ts @@ -1,7 +1,6 @@ import * as React from "react"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { useOpenDmMutation } from "@/features/channels/hooks"; import type { ProfilePanelOpenOptions } from "@/shared/context/ProfilePanelContext"; @@ -61,10 +60,8 @@ export function useChannelProfilePanel({ const openDmMutateAsync = openDmMutation.mutateAsync; const handleOpenDm = React.useCallback( async (pubkeys: string[]) => { - // Anchor before awaiting open_dm; see captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); const dm = await openDmMutateAsync({ pubkeys }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); }, [goChannel, openDmMutateAsync], ); diff --git a/desktop/src/features/channels/useChannelSwitchTraceMarks.test.mjs b/desktop/src/features/channels/useChannelSwitchTraceMarks.test.mjs index c5f3e95b2f..c329bd2b92 100644 --- a/desktop/src/features/channels/useChannelSwitchTraceMarks.test.mjs +++ b/desktop/src/features/channels/useChannelSwitchTraceMarks.test.mjs @@ -101,26 +101,6 @@ it("a trace survives StrictMode's effect replay and still settles", async () => dom.window.close(); }); -it("a real route exit still abandons: a history-back settle records nothing", async () => { - const { dom, flushFrames } = setupDom(); - performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); - beginChannelSwitchTrace("chan-exit"); - const root = createRoot(document.getElementById("root")); - await renderHarness(root, { - channelId: "chan-exit", - isTimelineLoading: true, - }); - // Leaving the channel surface unmounts the hook; with no re-setup to - // cancel it, the scheduled abandon must fire. - await act(async () => root.unmount()); - await new Promise((resolve) => setImmediate(resolve)); - // History-back re-enters without goChannel; its settle must find no trace. - settleChannelSwitchTrace("chan-exit"); - flushFrames(); - assert.deepEqual(measures(), []); - dom.window.close(); -}); - it("an A→B switch's deferred abandon of A never kills B's trace", async () => { const { dom, flushFrames } = setupDom(); performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); diff --git a/desktop/src/features/channels/useChannelSwitchTraceMarks.ts b/desktop/src/features/channels/useChannelSwitchTraceMarks.ts index dece8ab0aa..bef5d3d614 100644 --- a/desktop/src/features/channels/useChannelSwitchTraceMarks.ts +++ b/desktop/src/features/channels/useChannelSwitchTraceMarks.ts @@ -2,9 +2,7 @@ import * as React from "react"; import { abandonChannelSwitchTrace, - cancelRouteExitAbandon, markChannelSwitchRouteCommit, - scheduleRouteExitAbandon, settleChannelSwitchTrace, } from "@/shared/lib/channelSwitchPerf"; import type { ChannelType } from "@/shared/api/types"; @@ -32,24 +30,6 @@ export function useChannelSwitchTraceMarks({ React.useLayoutEffect(() => { 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. The abandon is scheduled (one microtask) rather - // than immediate so StrictMode's dev-only effect replay — whose re-setup - // runs synchronously right after this cleanup — cancels it instead of - // killing the just-opened trace. - React.useEffect(() => { - if (!activeChannelId) return; - const channelId = activeChannelId; - cancelRouteExitAbandon(channelId); - return () => { - scheduleRouteExitAbandon(channelId); - }; - }, [activeChannelId]); React.useEffect(() => { if (!activeChannelId) return; if (activeChannelType === "forum") { diff --git a/desktop/src/features/home/ui/HomeView.tsx b/desktop/src/features/home/ui/HomeView.tsx index 6055ea5b65..893b3c309c 100644 --- a/desktop/src/features/home/ui/HomeView.tsx +++ b/desktop/src/features/home/ui/HomeView.tsx @@ -3,7 +3,6 @@ import { RefreshCcw } from "lucide-react"; import { useAppShell } from "@/app/AppShellContext"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { useKnownAgentPubkeys } from "@/features/agents/useKnownAgentPubkeys"; import { useChannelsQuery, useOpenDmMutation } from "@/features/channels/hooks"; import { RightAuxiliaryPane } from "@/features/channels/ui/RightAuxiliaryPane"; @@ -222,10 +221,8 @@ export function HomeView({ const [isSendingReply, setIsSendingReply] = React.useState(false); const handleOpenDm = React.useCallback( async (pubkeys: string[]) => { - // Anchor before awaiting open_dm; see captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); const dm = await openDm({ pubkeys }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); }, [goChannel, openDm], ); diff --git a/desktop/src/features/messages/ui/MessageTimeline.tsx b/desktop/src/features/messages/ui/MessageTimeline.tsx index c8e9031b2a..8222dcdd22 100644 --- a/desktop/src/features/messages/ui/MessageTimeline.tsx +++ b/desktop/src/features/messages/ui/MessageTimeline.tsx @@ -144,22 +144,12 @@ type TimelineSnapshot = { * finally land (the pass-1 tear, ledgered 2026-07-11). */ historyExhausted: boolean; - /** - * Monotonic id of this snapshot. Rendered as `data-timeline-commit` from - * the DEFERRED snapshot, so the switch tracer can tell "the commit I was - * waiting for has painted" from "new live traffic re-latched the pending - * marker after my rows painted" — the two are indistinguishable from - * `data-render-pending` alone, and the second one used to inflate the - * recorded switch by the whole burst. - */ - generation: number; }; const EMPTY_TIMELINE_SNAPSHOT: TimelineSnapshot = { channelId: null, messages: EMPTY_MESSAGES, historyExhausted: false, - generation: 0, }; const MessageTimelineBase = React.forwardRef< @@ -256,18 +246,10 @@ const MessageTimelineBase = React.forwardRef< // Channel id travels with the deferred message snapshot. Without that guard, a // route change can paint the previous channel's deferred rows for a frame even // though the sidebar/header already moved to the new channel. - const snapshotGenerationRef = React.useRef(0); - const liveSnapshot = React.useMemo(() => { - // Monotonic only — StrictMode's double-invoke may skip a number, which - // the tracer's `>` comparison tolerates. - snapshotGenerationRef.current += 1; - return { - channelId: channelId ?? null, - messages, - historyExhausted, - generation: snapshotGenerationRef.current, - }; - }, [channelId, historyExhausted, messages]); + const liveSnapshot = React.useMemo( + () => ({ channelId: channelId ?? null, messages, historyExhausted }), + [channelId, historyExhausted, messages], + ); const deferredSnapshot = React.useDeferredValue( liveSnapshot, EMPTY_TIMELINE_SNAPSHOT, @@ -719,7 +701,6 @@ const MessageTimelineBase = React.forwardRef<
{showUnreadPill ? (
{ const dm = await openDm({ pubkeys: [targetPubkey] }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); if (isMountedRef.current) { onClose(); } @@ -170,10 +166,9 @@ export function useProfileInteractionActions({ return; } - const traceStartedAt = captureSwitchTraceAnchor(); void runAction("huddle", async (targetPubkey) => { const dm = await openDm({ pubkeys: [targetPubkey] }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); await startHuddle(dm.id, isBot ? [targetPubkey] : []); await queryClient.invalidateQueries({ queryKey: channelsQueryKey }); if (isMountedRef.current) { @@ -197,7 +192,6 @@ export function useProfileInteractionActions({ return; } - const traceStartedAt = captureSwitchTraceAnchor(); void runAction("wave", async (targetPubkey) => { const identity = identityQuery.data; if (!identity) { @@ -233,7 +227,7 @@ export function useProfileInteractionActions({ ); try { - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); if (isMountedRef.current) { onClose(); } diff --git a/desktop/src/features/projects/ui/useProjectProfilePanel.ts b/desktop/src/features/projects/ui/useProjectProfilePanel.ts index 16fd27609c..7c984103ed 100644 --- a/desktop/src/features/projects/ui/useProjectProfilePanel.ts +++ b/desktop/src/features/projects/ui/useProjectProfilePanel.ts @@ -1,7 +1,6 @@ import * as React from "react"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { useOpenDmMutation } from "@/features/channels/hooks"; import type { ProfilePanelTab, @@ -52,10 +51,8 @@ export function useProjectProfilePanel() { ), handleOpenDm: React.useCallback( async (pubkeys: string[]) => { - // Anchor before awaiting open_dm; see captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); const dm = await openDmMutation.mutateAsync({ pubkeys }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); }, [goChannel, openDmMutation], ), diff --git a/desktop/src/features/pulse/lib/useNoteActions.ts b/desktop/src/features/pulse/lib/useNoteActions.ts index aaac391190..48f27a18ff 100644 --- a/desktop/src/features/pulse/lib/useNoteActions.ts +++ b/desktop/src/features/pulse/lib/useNoteActions.ts @@ -1,6 +1,5 @@ import * as React from "react"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { useQueryClient } from "@tanstack/react-query"; import { toast } from "sonner"; @@ -156,14 +155,12 @@ export function usePulseNoteActions({ const startDm = React.useCallback( async (pubkey: string) => { // goChannel, not raw navigate: this is a first-class channel entry and - // must produce a switch measurement like every other one. Anchor before - // awaiting open_dm; see captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); + // must go through the same navigation guard as every other one. try { const directMessage = await openDmMutation.mutateAsync({ pubkeys: [pubkey], }); - await goChannel(directMessage.id, { traceStartedAt }); + await goChannel(directMessage.id); } catch (error) { toast.error( error instanceof Error ? error.message : "Failed to open DM", diff --git a/desktop/src/features/pulse/ui/PulseScreen.tsx b/desktop/src/features/pulse/ui/PulseScreen.tsx index 297b2f5cf9..882601bcde 100644 --- a/desktop/src/features/pulse/ui/PulseScreen.tsx +++ b/desktop/src/features/pulse/ui/PulseScreen.tsx @@ -1,7 +1,6 @@ import * as React from "react"; import { useAppNavigation } from "@/app/navigation/useAppNavigation"; -import { captureSwitchTraceAnchor } from "@/shared/lib/channelSwitchPerf"; import { useOpenDmMutation } from "@/features/channels/hooks"; import { type ProfilePanelTab, @@ -54,10 +53,8 @@ export function PulseScreen() { const { goChannel } = useAppNavigation(); const handleOpenDm = React.useCallback( async (pubkeys: string[]) => { - // Anchor before awaiting open_dm; see captureSwitchTraceAnchor. - const traceStartedAt = captureSwitchTraceAnchor(); const dm = await openDmMutation.mutateAsync({ pubkeys }); - await goChannel(dm.id, { traceStartedAt }); + await goChannel(dm.id); }, [goChannel, openDmMutation], ); diff --git a/desktop/src/shared/lib/channelSwitchPerf.test.mjs b/desktop/src/shared/lib/channelSwitchPerf.test.mjs index 03bfc7a82a..fa8ba254ed 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.test.mjs +++ b/desktop/src/shared/lib/channelSwitchPerf.test.mjs @@ -2,205 +2,90 @@ import assert from "node:assert/strict"; import test from "node:test"; import { - shouldAttributeFetch, - buildSwitchPerfLogRecord, - resolveSettleAction, CHANNEL_SWITCH_MEASURE, - beginChannelSwitchTrace, - resetChannelSwitchTrace, - resolveFinalFrame, - resolveSettleWait, + CHANNEL_SWITCH_START_MARK, abandonChannelSwitchTrace, - resolveRenderReadiness, - scheduleRouteExitAbandon, - resolveTraceAnchor, + beginChannelSwitchTrace, + dropActiveChannelSwitchTrace, + markChannelSwitchRouteCommit, + resetChannelSwitchTrace, + resolveSettleAction, settleChannelSwitchTrace, + shouldAttributeFetch, summarizeChannelSwitchTrace, + traceChannelWindowFetch, } from "./channelSwitchPerf.ts"; function trace(overrides = {}) { return { channelId: "abcdef1234567890", startedAt: 1_000, - // Liveness clock defaults to the anchor; DM entries back-date startedAt - // below openedAt, which is exactly why the two are separate fields. - openedAt: overrides.startedAt ?? 1_000, - maxFrameGapMs: 0, - settleEnteredAt: null, routeCommitAt: null, windowFetch: null, - membersFetch: null, + settleEnteredAt: null, ...overrides, }; } -test("summary reports total and cache-served fetches", () => { - const summary = summarizeChannelSwitchTrace(trace(), 1_412.4); +// --- Pure helpers --------------------------------------------------------- + +test("summary reports total, commit offset and cache-served fetches", () => { assert.equal( - summary, - "[switch-perf] channel=abcdef12 total=412ms commit=? window=cache members=cache", + summarizeChannelSwitchTrace(trace({ routeCommitAt: 1_200 }), 1_412.4), + "[switch-perf] channel=abcdef12 total=412ms commit=+200ms window=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, - ); +test("summary reports an attributed fetch and the truncation flag", () => { assert.equal( - summary, - "[switch-perf] channel=abcdef12 total=912ms commit=+38ms " + - "window=250 events in 181ms members=10000 members in 320ms", + summarizeChannelSwitchTrace( + trace({ windowFetch: { durationMs: 307.2, eventCount: 89 } }), + 1_739, + true, + ), + "[switch-perf] channel=abcdef12 total=739ms commit=? " + + "window=89 events in 307ms settle=truncated", ); }); -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", () => { +test("a settle for another channel leaves the active trace alone", () => { + // A previous channel can finish loading after the next switch began; + // clobbering the newer trace would drop exactly the rapid switches worth + // capturing. const active = trace(); - assert.deepEqual(resolveSettleAction(active, "abcdef1234567890", 2_000), { - settledTrace: active, - clearActive: true, - }); - assert.deepEqual(resolveSettleAction(null, "abcdef1234567890", 2_000), { + assert.deepEqual(resolveSettleAction(active, "bbbb0000bbbb0000", 1_100), { settledTrace: null, - clearActive: false, + timedOut: false, + }); + assert.deepEqual(resolveSettleAction(null, "abcdef1234567890", 1_100), { + settledTrace: null, + timedOut: 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", () => { +test("a settle past the timeout reports the trace as timed out", () => { const stale = trace({ startedAt: 1_000 }); assert.deepEqual(resolveSettleAction(stale, "abcdef1234567890", 31_001), { settledTrace: null, - clearActive: true, + timedOut: true, }); - assert.deepEqual( + assert.equal( resolveSettleAction(stale, "abcdef1234567890", 11_000).settledTrace, stale, ); }); -test("the settle wait records truncated — never as an honest settle — at deadline", () => { - // Still pending, before the deadline: keep waiting. - assert.equal(resolveSettleWait(4_999, 5_000, true, 0), "wait"); - // Render caught up: record cleanly. - assert.deepEqual(resolveSettleWait(1_000, 5_000, false, 0), { - settleWaitTruncated: false, - }); - // Deadline expired while still pending: the record must say so — a >5s - // switch reported as an ordinary settle would hide exactly the tail this - // tracer exists to expose. - assert.deepEqual(resolveSettleWait(5_000, 5_000, true, 0), { - settleWaitTruncated: true, - }); -}); - -test("a frame-starved trace is dropped, not recorded as a clean settle", () => { - // rAF suspends in hidden windows, so a queued settle can fire minutes - // after the click with renderPending long since false — the absence must - // not be charged to the switch. Nothing legitimate can be older than the - // 30s settle-entry timeout plus the 5s render wait. - assert.equal(resolveSettleWait(35_001, 40_000, false, 0), "drop"); - assert.equal(resolveSettleWait(35_001, 40_000, true, 0), "drop"); - // At the bound (a 29.9s settle plus a truncated 5s wait) records survive. - assert.deepEqual(resolveSettleWait(35_000, 34_900, true, 0), { - settleWaitTruncated: true, - }); -}); - -test("a not-pending frame landing past the wait deadline is starvation, not a settle", () => { - // Settle entered at t=1s (deadline 6s), render caught up, then frames - // stalled (system suspend, App Nap — no visibilitychange): the next frame - // lands at t=20s with nothing pending. The gap is starvation; recording - // it would fabricate a clean 20s switch well under the 35s age guard. - assert.equal(resolveSettleWait(20_000, 6_000, false, 0), "drop"); - // Still-pending arrivals past the deadline remain truncated records: the - // render genuinely wasn't done, which is the tail the tracer must keep. - assert.deepEqual(resolveSettleWait(6_001, 6_000, true, 0), { - settleWaitTruncated: true, - }); -}); - -test("a starved frame gap drops even while the render-pending marker is latched", () => { - // During a suspension React can't flush the deferred commit, so the - // pending marker stays latched — its truth is NOT evidence the render was - // slow. A single inter-frame gap beyond any plausible main-thread stall - // means the process was suspended; recording a truncated 22s "switch" - // would fabricate the very regression the tracer hunts. - assert.equal(resolveSettleWait(22_300, 5_300, true, 0, 22_000), "drop"); - // Heavy-but-real frames (multi-hundred-ms long tasks) still record. - assert.deepEqual(resolveSettleWait(5_400, 5_300, true, 0, 900), { - settleWaitTruncated: true, - }); - // The first frame has no predecessor: no gap to judge. - assert.deepEqual(resolveSettleWait(1_000, 5_300, false, 0, null), { - settleWaitTruncated: false, - }); -}); - -test("a truncated settle is flagged in the summary and the log record", () => { - const summary = summarizeChannelSwitchTrace(trace(), 1_412, true); - assert.ok(summary.endsWith(" settle=truncated"), summary); - const record = buildSwitchPerfLogRecord(trace(), 1_412, true); - assert.equal(record.settleWaitTruncated, true); - // Clean settles keep the field out of the line entirely. - assert.ok( - !("settleWaitTruncated" in buildSwitchPerfLogRecord(trace(), 1_412)), - ); -}); - -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. +test("fetches attribute only inside the measured interval", () => { + const active = trace({ startedAt: 1_000 }); + // Started before the switch (a stale A→B→A leg): not this switch's cost, + // and it would occupy the one-shot slot the real fetch needs. 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); - // Started after the timeline settled: background revalidation the user - // never waited on. The trace is still active (it waits for the deferred - // paint), so without the upper bound this would be reported as switch cost. + // Started after the timeline settled: background revalidation the user never + // waited on. The trace is still active while it waits for the paint. const settling = trace({ startedAt: 1_000, settleEnteredAt: 2_000 }); assert.equal(shouldAttributeFetch(settling, "abcdef1234567890", 1_999), true); assert.equal( @@ -209,417 +94,69 @@ test("fetches attribute only when started after the switch began", () => { ); }); -test("a superseded members fetch never claims the trace's one-shot slot", async () => { - const { openChannelMembersFetch, traceChannelMembersFetch } = await import( - "./channelSwitchPerf.ts" - ); - await withSettleHarness(async ({ begin, settle, flush }) => { - begin("aaaa1111aaaa1111"); - const startedAt = performance.now(); - // Fetch #1 starts, then a live join/leave invalidation replaces it with - // fetch #2. #1 resolves first (the Tauri call can't be cancelled) but - // must not attribute: its roster is not the one rendered. The query's - // AbortSignal is deliberately not used for this — consuming it flips - // React Query to cancel-and-revert on last-observer unsubscribe, which - // discards warm rosters on interrupted switches. - const first = openChannelMembersFetch("aaaa1111aaaa1111"); - const second = openChannelMembersFetch("aaaa1111aaaa1111"); - traceChannelMembersFetch("aaaa1111aaaa1111", 9_999, 900, startedAt, first); - traceChannelMembersFetch( - "aaaa1111aaaa1111", - 10_002, - 120, - startedAt, - second, - ); - settle("aaaa1111aaaa1111"); - flush(); - const measure = performance - .getEntriesByName("buzz:channel-switch:click-to-settled") - .at(-1); - assert.equal(measure?.detail?.membersFetch?.memberCount, 10_002); - assert.equal(measure?.detail?.membersFetch?.durationMs, 120); - }); -}); +// --- Lifecycle ------------------------------------------------------------ -test("a suspension before the first settle frame drops, not records truncated", async () => { - await withSettleHarness(async ({ begin, settle, flush, measures }) => { - const virtualClock = { now: 0 }; - performance.now = () => virtualClock.now; - try { - // The deferred marker stays latched during a suspension, so its truth - // is not evidence of slow rendering — the settle-entry → first-frame - // window must be starvation-guarded like every later frame. - // Element-like: carries the pending marker but no committed timeline - // generation, so readiness stays gated on the marker alone. - globalThis.document.querySelector = () => ({ getAttribute: () => null }); - begin("aaaa1111aaaa1111"); - settle("aaaa1111aaaa1111"); - virtualClock.now = 20_000; - flush(); - assert.deepEqual(measures(), []); - } finally { - delete performance.now; - } - }); -}); - -// --- Settle lifecycle: rapid switches and community resets ---------------- - -async function withSettleHarness(run, documentOverrides = {}) { - const frames = []; - const originalWindow = globalThis.window; - const originalDocument = globalThis.document; - globalThis.window = { - requestAnimationFrame: (cb) => frames.push(cb) && frames.length, - cancelAnimationFrame: () => {}, - }; - globalThis.document = { - addEventListener: () => {}, - querySelector: () => null, - removeEventListener: () => {}, - visibilityState: "visible", - ...documentOverrides, - }; - const { - abandonChannelSwitchTrace, - beginChannelSwitchTrace, - cancelRouteExitAbandon, - scheduleRouteExitAbandon, - 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, - cancelAbandon: cancelRouteExitAbandon, - scheduleAbandon: scheduleRouteExitAbandon, - 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("beginning a switch clears the previous switch's settled mark and measure", async () => { - await withSettleHarness(async ({ begin, settle, flush, measures }) => { - const { CHANNEL_SWITCH_SETTLED_MARK } = await import( - "./channelSwitchPerf.ts" - ); - begin("aaaa1111aaaa1111"); - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), ["aaaa1111aaaa1111"]); - // A consumer polling the buffer mid-switch (the Playwright specs, the - // Performance panel) must never read the PREVIOUS switch's entries as - // the current one's. - begin("bbbb2222bbbb2222"); - assert.deepEqual(measures(), []); - assert.equal( - performance.getEntriesByName(CHANNEL_SWITCH_SETTLED_MARK).length, - 0, - ); - }); -}); - -test("a window hidden between click and settle entry drops the trace", async () => { - const visibilityListeners = []; - await withSettleHarness( - async ({ begin, settle, flush, measures }) => { - begin("aaaa1111aaaa1111"); - assert.ok(visibilityListeners.length >= 1, "watcher armed at begin"); - // The window hides while the fetch is in flight (cmd-H / minimize), - // then the user returns and the settle runs with the window visible - // again: the absence sits inside totalMs, so the trace must drop. - globalThis.document.visibilityState = "hidden"; - for (const listener of visibilityListeners) listener(); - globalThis.document.visibilityState = "visible"; - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), []); - }, - { - addEventListener: (type, listener) => { - if (type === "visibilitychange") visibilityListeners.push(listener); - }, - }, - ); -}); - -test("abandoned switches never accumulate start marks", async () => { - await withSettleHarness(async ({ abandon, begin }) => { - const { CHANNEL_SWITCH_START_MARK } = await import( - "./channelSwitchPerf.ts" - ); - performance.clearMarks?.(CHANNEL_SWITCH_START_MARK); - // Traces that die without recording (forum visits, route exits, drops) - // never reach record()'s buffer clearing — begin() must bound the - // buffer itself or weeks-long sessions accumulate a mark per abandon. - for (const channelId of ["aaaa", "bbbb", "cccc", "dddd"]) { - begin(channelId); - abandon(channelId); - } - assert.equal( - performance.getEntriesByName(CHANNEL_SWITCH_START_MARK).length, - 1, - ); - performance.clearMarks?.(CHANNEL_SWITCH_START_MARK); - }); -}); - -test("a settle in a hidden window drops the trace instead of recording", async () => { - await withSettleHarness( - async ({ begin, settle, flush, measures }) => { - begin("aaaa1111aaaa1111"); - // rAF is suspended while hidden; the queued chain would only fire when - // the user returns, charging the whole absence to the switch. - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), []); - // The trace was released, not wedged: a later stale settle is a no-op. - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), []); - }, - { visibilityState: "hidden" }, - ); -}); - -test("a window hidden during the settle wait drops the record", async () => { - const visibilityListeners = []; - await withSettleHarness( - async ({ begin, settle, flush, measures }) => { - begin("aaaa1111aaaa1111"); - settle("aaaa1111aaaa1111"); - assert.equal(visibilityListeners.length, 1, "wait registers a listener"); - // The user cmd-tabs away mid-wait; frames resume only on return. - visibilityListeners[0](); - flush(); - assert.deepEqual(measures(), []); - }, - { - addEventListener: (type, listener) => { - if (type === "visibilitychange") visibilityListeners.push(listener); - }, - }, - ); -}); - -test("a scheduled route-exit abandon canceled in the same task keeps the trace", async () => { - await withSettleHarness( - async ({ - begin, - cancelAbandon, - scheduleAbandon, - settle, - flush, - measures, - }) => { - begin("aaaa1111aaaa1111"); - // StrictMode's dev-only effect replay: cleanup schedules the abandon, - // the synchronous re-setup cancels it before the microtask runs. - scheduleAbandon("aaaa1111aaaa1111"); - cancelAbandon("aaaa1111aaaa1111"); - await Promise.resolve(); - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), ["aaaa1111aaaa1111"]); - }, - ); -}); - -test("the trace anchors at the input event, not handler dispatch", async () => { - await withSettleHarness(async ({ begin, settle, flush }) => { - // Real-clock gap: earlier tests fired visibilitychange listeners, and a - // back-dated anchor overlapping those timestamps is (correctly) dropped - // by the hidden-window guard. Let them age out first. - await new Promise((resolve) => setTimeout(resolve, 600)); - // A click can sit queued behind a long task before its handler runs; - // that input delay is felt switch latency and must be inside totalMs. - // window.event is set only during synchronous dispatch, so this anchor - // can never leak in from async continuations. - globalThis.window.event = { timeStamp: performance.now() - 550 }; - begin("aaaa1111aaaa1111"); - delete globalThis.window.event; - const startMark = performance - .getEntriesByName("buzz:channel-switch:start") - .at(-1); - settle("aaaa1111aaaa1111"); - flush(); - const measure = performance - .getEntriesByName("buzz:channel-switch:click-to-settled") - .at(-1); - assert.ok(measure, "measure recorded"); - assert.ok( - measure.duration >= 550, - `input delay must be inside the measure (got ${measure.duration})`, - ); - // The mark and the measure must share the anchor, or the Performance - // panel shows two different switch durations for the same switch. - assert.equal(startMark?.startTime, measure.startTime); - }); -}); - -test("beginning a switch revokes a pending route-exit abandon for that channel", async () => { - await withSettleHarness( - async ({ begin, scheduleAbandon, settle, flush, measures }) => { - // Same-task unmount-then-renavigate to the same channel: the cleanup - // schedules the abandon, then goChannel synchronously opens a fresh - // trace before the microtask drains. The stale abandon must not kill - // the new trace. - scheduleAbandon("aaaa1111aaaa1111"); - begin("aaaa1111aaaa1111"); - await Promise.resolve(); - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), ["aaaa1111aaaa1111"]); - }, - ); -}); - -test("an uncanceled route-exit abandon drops the trace before any frame fires", async () => { - await withSettleHarness( - async ({ begin, scheduleAbandon, settle, flush, measures }) => { - begin("aaaa1111aaaa1111"); - scheduleAbandon("aaaa1111aaaa1111"); - await Promise.resolve(); - settle("aaaa1111aaaa1111"); - flush(); - assert.deepEqual(measures(), []); - }, - ); -}); - -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(), []); - }, - ); -}); - -test("suspension between readiness and the paint frame drops the record", () => { - // The reviewer's repro: readiness at t=10ms, final frame at t=20_000ms. - // Recording here would emit total=20000ms as an ordinary clean switch — - // App Nap fires no visibilitychange, so the hidden-window guard cannot see - // it and the frame-gap guard in awaitDeferredCommit has already run. - assert.equal(resolveFinalFrame(20_000, 10, 0), "drop"); - // A normal paint frame one refresh interval after readiness still records. - assert.equal(resolveFinalFrame(27, 10, 0), "record"); - // Boundary: exactly the frame-gap cap is still a record; one past it drops. - assert.equal(resolveFinalFrame(3_010, 10, 0), "record"); - assert.equal(resolveFinalFrame(3_011, 10, 0), "drop"); -}); - -test("the final frame also honors the overall trace age cap", () => { - // Readiness landed just under the age cap and the paint frame is prompt, - // so the frame gap is innocent — only the age check can catch this. - assert.equal(resolveFinalFrame(35_001, 35_000, 0), "drop"); - assert.equal(resolveFinalFrame(35_000, 34_999, 0), "record"); -}); - -// Drives the real settle lifecycle with a controllable clock and rAF queue so -// a stall can be injected at one exact seam. Offsets are rebased above the -// real clock: earlier tests in this file fire visibilitychange, and a trace -// back-dated below those timestamps is (correctly) dropped at settle entry — -// which would make every assertion here vacuous. -function withClockedFrames(run) { +/** + * Drives the real lifecycle with a manual frame queue, a virtual clock and a + * controllable pending marker. The clock is rebased above the real one so a + * visibilitychange fired by an earlier test cannot silently drop every trace + * at settle entry and make these assertions vacuous. + */ +function withHarness(run) { const frames = []; + const drops = []; const originalWindow = globalThis.window; const originalDocument = globalThis.document; const originalNow = performance.now; + const originalInfo = console.info; const base = originalNow.call(performance) + 1_000; let clock = base; + let pending = false; performance.now = () => clock; + console.info = (line) => { + if (typeof line === "string" && line.includes("dropped (")) { + drops.push(line.slice(line.indexOf("dropped (") + 9, -1)); + } + }; globalThis.window = { requestAnimationFrame: (cb) => frames.push(cb) && frames.length, cancelAnimationFrame: () => {}, }; globalThis.document = { addEventListener: () => {}, - // No pending marker: readiness is reached on the first settle frame. - querySelector: () => null, + querySelector: () => (pending ? {} : null), removeEventListener: () => {}, visibilityState: "visible", }; performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); - const at = (offset) => { - clock = base + offset; + const api = { + drops, + at: (offset) => { + clock = base + offset; + }, + setPending: (value) => { + pending = value; + }, + hide: () => { + globalThis.document.visibilityState = "hidden"; + }, + flush: (rounds = 40) => { + for (let i = 0; i < rounds && frames.length > 0; i += 1) { + for (const cb of frames.splice(0, frames.length)) cb(); + } + }, + measures: () => + performance + .getEntriesByName(CHANNEL_SWITCH_MEASURE) + .map((entry) => entry.detail?.channelId), + lastMeasure: () => + performance.getEntriesByName(CHANNEL_SWITCH_MEASURE).at(-1), }; - const step = (offset) => { - at(offset); - for (const cb of frames.splice(0, frames.length)) cb(); - }; - const measures = () => - performance.getEntriesByName(CHANNEL_SWITCH_MEASURE).length; try { - run({ at, step, measures }); + run(api); } finally { performance.now = originalNow; + console.info = originalInfo; resetChannelSwitchTrace(); performance.clearMeasures?.(CHANNEL_SWITCH_MEASURE); if (originalWindow === undefined) delete globalThis.window; @@ -629,190 +166,159 @@ function withClockedFrames(run) { } } -test("a stall between readiness and the paint frame records nothing", () => { - withClockedFrames(({ at, step, measures }) => { +test("an undisturbed switch records exactly one measure", () => { + withHarness(({ at, flush, measures, lastMeasure }) => { at(0); beginChannelSwitchTrace("aaaa"); - at(10); + at(20); + markChannelSwitchRouteCommit("aaaa"); + at(120); settleChannelSwitchTrace("aaaa"); - // Readiness frame: no pending marker, inside the wait deadline. - step(10); - // Process suspended here (App Nap): no visibilitychange fires, so only - // the final-frame guard can catch it. - step(20_000); - assert.equal(measures(), 0, "a 20s suspension must not record a switch"); + flush(); + assert.deepEqual(measures(), ["aaaa"]); + assert.notEqual(lastMeasure().detail.routeCommitAt, null); + assert.equal(lastMeasure().detail.settleWaitTruncated, undefined); }); }); -test("a prompt paint frame after readiness still records", () => { - withClockedFrames(({ at, step, measures }) => { +test("the settle waits for a pending render, then truncates rather than hangs", () => { + withHarness(({ at, flush, setPending, measures, lastMeasure }) => { at(0); beginChannelSwitchTrace("aaaa"); - at(10); + setPending(true); + at(50); settleChannelSwitchTrace("aaaa"); - step(10); - step(26); - assert.equal(measures(), 1, "the guard must not drop healthy switches"); + // The marker never clears: the wait is bounded in frames, and the sample + // is reported flagged rather than discarded — a slow switch is data. + flush(); + assert.deepEqual(measures(), ["aaaa"]); + assert.equal(lastMeasure().detail.settleWaitTruncated, true); }); }); -test("a stale caller anchor is discarded rather than charged to the switch", () => { - // DM flow: anchor captured at the click, open_dm awaited. If the user - // navigates away during that await, the anchor is no longer this switch's - // start and would charge unrelated activity to it. - assert.deepEqual(resolveTraceAnchor(1_000, 500, 30_000), { - startedAt: 30_000, - anchorDiscarded: true, - }); - // Inside the bound: the open_dm round-trip stays in the measurement. - assert.deepEqual(resolveTraceAnchor(25_000, 500, 30_000), { - startedAt: 25_000, - anchorDiscarded: false, - }); -}); - -test("anchors are never negative, non-finite, or in the future", () => { - // performance.mark({startTime}) throws on a negative timestamp, and begin() - // runs inside the click handler — a diagnostic must never break navigation. - assert.equal(resolveTraceAnchor(-5, 100, 100).startedAt, 0); - assert.equal(resolveTraceAnchor(Number.NaN, 100, 100).anchorDiscarded, true); - assert.equal(resolveTraceAnchor(Number.NaN, 100, 100).startedAt, 100); - // A skewed event clock reporting the future is clamped to now. - assert.equal(resolveTraceAnchor(200, 100, 100).startedAt, 100); - // No anchor supplied, and performance was unavailable at capture time. - assert.equal(resolveTraceAnchor(undefined, Number.NaN, 100).startedAt, 100); -}); - -test("a truncated settle survives a slow paint frame; a clean one does not", () => { - // renderWasPending is direct evidence the long frame is a heavy commit, not - // a suspension — and that measurement is already flagged. Dropping it would - // discard exactly the pathological switch the instrument exists to expose. - assert.equal(resolveFinalFrame(3_600, 10, 0, true), "record"); - assert.equal(resolveFinalFrame(3_600, 10, 0, false), "drop"); - // The age cap still applies to both. - assert.equal(resolveFinalFrame(35_001, 35_000, 0, true), "drop"); -}); - -test("post-paint churn does not keep a settled switch waiting", () => { - // Nothing pending: ready, regardless of generations. - assert.equal(resolveRenderReadiness(false, 4, 4), true); - // Pending and the timeline has not committed since settle entry: the - // switch's own rows are still unpainted, so keep waiting. - assert.equal(resolveRenderReadiness(true, 4, 4), false); - // Pending, but the timeline committed past the generation painted at settle - // entry: the rows are on screen and this marker belongs to live traffic - // that arrived afterwards. Recording the burst would inflate the switch. - assert.equal(resolveRenderReadiness(true, 4, 5), true); - // No timeline mounted (Suspense fallback still up): the pending marker is - // the fallback's own, and there is nothing painted yet to be ready. - assert.equal(resolveRenderReadiness(true, null, null), false); - assert.equal(resolveRenderReadiness(true, 4, null), false); -}); - -// --- Drop accounting: no measurement disappears without a record ----------- - -function withDropCapture(run) { - const drops = []; - const originalInfo = console.info; - console.info = (line) => { - if (typeof line === "string" && line.includes("dropped reason=")) { - drops.push(line.slice(line.indexOf("dropped reason=") + 15)); - } - }; - try { - run(drops); - } finally { - console.info = originalInfo; - resetChannelSwitchTrace(); - } -} - -test("an impatient second click accounts for the trace it supersedes", () => { - withClockedFrames(({ at }) => { - withDropCapture((drops) => { - at(0); - beginChannelSwitchTrace("aaaa"); - at(400); - // The user gave up on A and clicked B. A's trace is gone — and A being - // slow is exactly why they clicked again, so a silent discard censors - // the switches worth measuring. - beginChannelSwitchTrace("bbbb"); - assert.deepEqual(drops, ["superseded"]); - }); - }); -}); - -test("a community reset accounts for the trace it clears", () => { - withClockedFrames(({ at }) => { - withDropCapture((drops) => { - at(0); - beginChannelSwitchTrace("aaaa"); - resetChannelSwitchTrace(); - assert.deepEqual(drops, ["community-reset"]); - }); - }); -}); - -test("an unobservable surface accounts for its abandon", () => { - withClockedFrames(({ at }) => { - withDropCapture((drops) => { - at(0); - beginChannelSwitchTrace("aaaa"); - abandonChannelSwitchTrace("aaaa"); - assert.deepEqual(drops, ["unobservable-surface"]); - }); - }); -}); - -test("a timed-out settle accounts for the drop", () => { - withClockedFrames(({ at, measures }) => { - withDropCapture((drops) => { - at(0); - beginChannelSwitchTrace("aaaa"); - at(31_000); - settleChannelSwitchTrace("aaaa"); - assert.deepEqual(drops, ["timeout"]); - assert.equal(measures(), 0); - }); - }); -}); - -test("route-exit abandon respects hash-history routes", async () => { - // The app uses createHashHistory, so the route lives in location.hash. - // Reading location.pathname made this guard answer false for every real - // channel route, degrading it to an unconditional abandon. - const drops = []; - const originalInfo = console.info; - const originalWindow = globalThis.window; - const originalNow = performance.now; - const base = originalNow.call(performance) + 1_000; - performance.now = () => base; - console.info = (line) => { - if (typeof line === "string" && line.includes("dropped reason=")) { - drops.push(line.slice(line.indexOf("dropped reason=") + 15)); - } - }; - globalThis.window = { - requestAnimationFrame: () => 1, - cancelAnimationFrame: () => {}, - location: { pathname: "/index.html", hash: "#/channels/aaaa" }, - }; - try { +test("a switch that paints mid-wait records without the truncation flag", () => { + withHarness(({ at, flush, setPending, lastMeasure }) => { + at(0); beginChannelSwitchTrace("aaaa"); - scheduleRouteExitAbandon("aaaa"); - await Promise.resolve(); - assert.deepEqual(drops, [], "the route still points at this channel"); - - // A real exit still abandons. - globalThis.window.location.hash = "#/projects"; - scheduleRouteExitAbandon("aaaa"); - await Promise.resolve(); - assert.deepEqual(drops, ["route-exit"]); - } finally { - console.info = originalInfo; - performance.now = originalNow; - resetChannelSwitchTrace(); - if (originalWindow === undefined) delete globalThis.window; - else globalThis.window = originalWindow; - } + setPending(true); + at(50); + settleChannelSwitchTrace("aaaa"); + flush(2); + setPending(false); + flush(); + assert.equal(lastMeasure().detail.settleWaitTruncated, undefined); + }); +}); + +test("a superseding switch discards the first trace, with a reason", () => { + withHarness(({ at, flush, drops, measures }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + at(400); + // The user gave up on A and clicked B. A being slow is exactly why they + // clicked again, so a silent discard censors the switches worth seeing. + beginChannelSwitchTrace("bbbb"); + settleChannelSwitchTrace("aaaa"); + flush(); + assert.deepEqual(drops, ["superseded"]); + assert.deepEqual(measures(), []); + }); +}); + +test("a hidden window drops the trace instead of recording the absence", () => { + withHarness(({ at, flush, hide, drops, measures }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + hide(); + at(9_000); + settleChannelSwitchTrace("aaaa"); + flush(); + assert.deepEqual(drops, ["hidden window"]); + assert.deepEqual(measures(), []); + }); +}); + +test("a timed-out switch is dropped, with a reason", () => { + withHarness(({ at, flush, drops, measures }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + at(31_000); + settleChannelSwitchTrace("aaaa"); + flush(); + assert.deepEqual(drops, ["timed out"]); + assert.deepEqual(measures(), []); + }); +}); + +test("leaving the channel surface and forum surfaces drop with a reason", () => { + withHarness(({ at, drops }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + dropActiveChannelSwitchTrace(); + at(10); + beginChannelSwitchTrace("bbbb"); + abandonChannelSwitchTrace("bbbb"); + assert.deepEqual(drops, ["left channel surface", "unobservable surface"]); + }); +}); + +test("a second settle neither restarts the wait nor moves the fetch bound", () => { + withHarness(({ at, flush, measures }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + at(50); + settleChannelSwitchTrace("aaaa"); + at(60); + settleChannelSwitchTrace("aaaa"); + flush(); + assert.deepEqual(measures(), ["aaaa"]); + }); +}); + +test("an attributed window fetch reaches the measure", () => { + withHarness(({ at, flush, lastMeasure }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + traceChannelWindowFetch("aaaa", 89, 307, performance.now()); + at(120); + settleChannelSwitchTrace("aaaa"); + flush(); + assert.deepEqual(lastMeasure().detail.windowFetch, { + durationMs: 307, + eventCount: 89, + }); + }); +}); + +test("beginning a switch clears the previous switch's entries", () => { + withHarness(({ at, flush, measures }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + at(100); + settleChannelSwitchTrace("aaaa"); + flush(); + assert.deepEqual(measures(), ["aaaa"]); + // A consumer polling the buffer mid-switch must never read the previous + // switch's measure as the current one's. + at(200); + beginChannelSwitchTrace("bbbb"); + assert.deepEqual(measures(), []); + }); +}); + +test("the start mark shares the measure's anchor", () => { + withHarness(({ at, flush }) => { + at(0); + beginChannelSwitchTrace("aaaa"); + const startMark = performance + .getEntriesByName(CHANNEL_SWITCH_START_MARK) + .at(-1); + at(100); + settleChannelSwitchTrace("aaaa"); + flush(); + const measure = performance.getEntriesByName(CHANNEL_SWITCH_MEASURE).at(-1); + // Without a shared anchor the Performance panel shows the measure + // starting before its own start mark. + assert.equal(startMark.startTime, measure.startTime); + }); }); diff --git a/desktop/src/shared/lib/channelSwitchPerf.ts b/desktop/src/shared/lib/channelSwitchPerf.ts index 67dbfd1aa7..5243e31a1a 100644 --- a/desktop/src/shared/lib/channelSwitchPerf.ts +++ b/desktop/src/shared/lib/channelSwitchPerf.ts @@ -1,81 +1,64 @@ /** - * 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. + * Channel-switch timing: click → route commit → settled paint, plus the + * message-window fetch when it lands inside that interval. * - * 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. + * Deliberately small. One trace is active at a time; `beginChannelSwitchTrace` + * (from `goChannel`, via `commitGuardedNavigation`) opens it and + * `settleChannelSwitchTrace` closes it one paint after the channel's timeline + * leaves its loading latch. Output is a `[switch-perf]` console line plus User + * Timing marks and measures (`buzz:channel-switch:*`) — the Performance panel + * and the Playwright perf harness read the same numbers. Nothing is persisted. * - * Traced entry paths: every navigation that reaches `goChannel` — sidebar, - * search, notification activation, and the DM actions, which capture - * `captureSwitchTraceAnchor()` at the click so their `open_dm` round-trip is - * inside the interval rather than before it. Deliberately untraced: history - * back/forward (no click to anchor on) and navigations that stay on the - * already-active channel (nothing re-runs the settle, so a trace could only - * time out). - * - * Output per switch: a `[switch-perf]` console line plus User Timing - * marks/measures (`buzz:channel-switch:*`) so Playwright perf specs and the - * Performance panel can read the same numbers. - * - * 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. - * - * The settled timestamp lands one rAF after the paint, so `totalMs` includes - * up to one display refresh interval (~17ms at 60Hz, ~8ms at 120Hz) — - * compare before/after runs on the same display. + * The honesty bounds below are chosen rather than inferred. Every extra + * inference this instrument tried to make became a way to report a number that + * never happened, so the scope is narrow on purpose: + * - Only navigations that reach `goChannel` are traced. History back/forward + * and re-selecting the active channel are not. + * - The interval starts at the navigation, anchored to the triggering input + * event when one is dispatching. Callers that await before navigating (DM + * actions await `open_dm`) exclude that await by design. + * - A trace overlapping a hidden window is dropped, never measured: rAF + * suspends and network throttles while hidden, so elapsed time there is not + * the user's switch. + * - The settle waits a bounded number of frames for a pending render. Past + * that bound the measure is still emitted, flagged `settleWaitTruncated` — + * a slow switch is data, not an error. + * - Every abandoned trace prints why. Drops correlate with slow switches, so a + * silent drop would make "no switches" and "switches discarded" look alike. */ -import { invoke, isTauri } from "@tauri-apps/api/core"; - export type ChannelSwitchTrace = { channelId: string; - /** Reported anchor: the click. May predate `openedAt` for DM entries. */ startedAt: number; - /** - * When begin() ran. Liveness (timeout, starvation age) is measured from - * here, never from `startedAt`: a back-dated anchor would otherwise spend - * the trace's whole staleness budget on the relay round-trip that preceded - * the navigation, and an honest slow DM entry would go unmeasured. - */ - openedAt: number; - /** Largest inter-frame gap seen while this trace was live. */ - maxFrameGapMs: number; - /** The caller's anchor was too stale to trust; see MAX_ANCHOR_AGE_MS. */ - anchorDiscarded: boolean; - /** - * When the timeline reported settled. The trace stays active past this - * point to wait for the deferred paint, so it bounds fetch attribution: - * work the user never waited on must not claim the switch's one-shot slot. - */ - settleEnteredAt: number | null; routeCommitAt: number | null; windowFetch: { durationMs: number; eventCount: number } | null; - membersFetch: { durationMs: number; memberCount: number } | null; + /** Set when the timeline reports settled; bounds fetch attribution. */ + settleEnteredAt: number | null; }; /** A switch that hasn't settled after this long is abandoned, not measured. */ const SWITCH_TRACE_TIMEOUT_MS = 30_000; /** - * Oldest caller-supplied anchor still treated as this navigation's click. - * A DM action captures its anchor before awaiting `open_dm`; if the user - * navigates elsewhere while that await is outstanding, the anchor is no - * longer the start of the switch that eventually commits. Beyond this the - * anchor is discarded (and the record says so) rather than charging unrelated - * activity to the switch. + * Frames the settle waits for a pending render before recording anyway. + * Bounded in frames rather than milliseconds so a stalled main thread cannot + * stretch the wait into the measurement. */ -const MAX_ANCHOR_AGE_MS = 10_000; +const MAX_SETTLE_FRAMES = 30; 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"; +/** + * Repo-wide marker for "a deferred commit is in flight", set by the message + * timeline and by the lazy channel pane's fallback. Other components use it + * too, so the settle wait is bounded in frames rather than trusting it to + * clear: a foreign owner can extend a switch by at most MAX_SETTLE_FRAMES, + * and that sample is flagged `settleWaitTruncated`. + */ +const RENDER_PENDING_SELECTOR = '[data-render-pending="true"]'; + let activeTrace: ChannelSwitchTrace | null = null; /** Formats one settled trace as the `[switch-perf]` console line. */ @@ -93,241 +76,24 @@ export function summarizeChannelSwitchTrace( 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}` + + `commit=${commit} window=${window}` + (settleWaitTruncated ? " settle=truncated" : "") ); } -/** - * 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, - settleWaitTruncated = false, -): { - ts: string; - channelId: string; - totalMs: number; - commitOffsetMs: number | null; - windowFetch: { durationMs: number; eventCount: number } | null; - membersFetch: { durationMs: number; memberCount: number } | null; - settleWaitTruncated?: true; - anchorDiscarded?: true; -} { - return { - ...(settleWaitTruncated ? { settleWaitTruncated: true as const } : {}), - ...(trace.anchorDiscarded ? { anchorDiscarded: true as const } : {}), - 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; -let hasWarnedSinkFailure = false; - -/** - * Fire-and-forget JSONL append; diagnostics must never throw into the app. - * A permanently dead sink must not be SILENT though — the console keeps - * printing per-switch lines that read as "tracing works", so warn once when - * persistence fails or an operator's before/after run yields an empty file - * with no way to tell why. - */ -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((error) => { - if (!hasWarnedSinkFailure) { - hasWarnedSinkFailure = true; - console.warn( - "[switch-perf] failed to persist record; offline log may be incomplete:", - error, - ); - } - }); -} - -export type SwitchDropReason = - | "timeout" - | "hidden-window" - | "frame-starvation" - | "settle-wait-exceeded" - | "route-exit" - | "unobservable-surface" - | "left-channel-surface" - | "navigation-failed" - | "superseded" - | "community-reset"; - -/** - * Every abandoned trace is accounted for. Drop conditions correlate with slow - * switches (starvation, timeout, hidden window), so silent drops would censor - * exactly the tail an operator is measuring and make "no samples" and "N - * samples discarded" indistinguishable in the offline log. - */ -function recordSwitchDrop( - trace: ChannelSwitchTrace, - reason: SwitchDropReason, -): void { +function dropTrace(trace: ChannelSwitchTrace, reason: string): void { console.info( - `[switch-perf] channel=${trace.channelId.slice(0, 8)} dropped reason=${reason}`, + `[switch-perf] channel=${trace.channelId.slice(0, 8)} dropped (${reason})`, ); - appendSwitchPerfLogRecord({ - ts: new Date().toISOString(), - channelId: trace.channelId, - dropped: reason, - }); + if (activeTrace === trace) activeTrace = null; } /** - * 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.openedAt > 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, - reason: SwitchDropReason = "unobservable-surface", -): void { - if (activeTrace?.channelId === channelId) { - recordSwitchDrop(activeTrace, reason); - activeTrace = null; - } -} - -/** - * dropActiveChannelSwitchTrace abandons whatever trace is active, regardless - * of channel. Called when navigation leaves the channel surface (any - * committed non-channel destination, any history traversal): a trace can be - * live with no channel screen mounted at all — the route still resolving — - * so no route-exit cleanup exists to abandon it, and a later untraced - * re-entry within the timeout would settle it with the time spent away. - */ -export function dropActiveChannelSwitchTrace( - reason: SwitchDropReason = "left-channel-surface", -): void { - if (activeTrace) recordSwitchDrop(activeTrace, reason); - activeTrace = null; -} - -// Route-exit abandons currently deferred; see scheduleRouteExitAbandon. -const pendingRouteExitAbandons = new Set(); - -/** - * scheduleRouteExitAbandon abandons the channel's trace one microtask from - * now unless cancelRouteExitAbandon runs first. Call it from the route-exit - * effect cleanup: deferring lets React StrictMode's dev-only effect replay - * — cleanup + re-setup, synchronously within one commit — cancel the - * abandon, where abandoning synchronously would kill every just-opened - * trace in dev builds and break the Performance-panel workflow. A real - * route exit has no re-setup, so the scheduled abandon still fires — and - * microtasks run before any frame callback, so a queued settle cannot - * record in the gap. - */ -export function scheduleRouteExitAbandon(channelId: string): void { - pendingRouteExitAbandons.add(channelId); - queueMicrotask(() => { - if (!pendingRouteExitAbandons.delete(channelId)) return; - // The unmount may be a remount in disguise: a Suspense boundary between - // the two commits (project-home channels swap ChannelScreen for a lazy - // ChannelScreenView) means the re-setup that would have cancelled this - // has not run yet, and killing the trace here loses a switch the user - // did make. The route is the authority — if it still points at this - // channel, nothing exited. - if (routeStillOnChannel(channelId)) return; - abandonChannelSwitchTrace(channelId, "route-exit"); - }); -} - -/** - * Whether the current URL is still this channel's own route. Read from - * location rather than React state: the check runs from a microtask, after - * the unmount commit, where no component tree is authoritative. - */ -function routeStillOnChannel(channelId: string): boolean { - if (typeof window === "undefined" || !window.location) return false; - // The app uses createHashHistory (app/router.tsx), so the route lives in - // location.hash and location.pathname is the document path. Reading - // pathname here made this guard inert — it answered false for every real - // channel route, degrading the caller to an unconditional abandon. - const hash = window.location.hash; - const route = hash.startsWith("#") ? hash.slice(1) : window.location.pathname; - const path = route.split("?")[0]; - return ( - path === `/channels/${channelId}` || - path.startsWith(`/channels/${channelId}/`) - ); -} - -/** - * cancelRouteExitAbandon revokes a pending scheduleRouteExitAbandon for the - * channel. Call it from the route-enter effect setup, before any work. - */ -export function cancelRouteExitAbandon(channelId: string): void { - pendingRouteExitAbandons.delete(channelId); -} - -/** - * Timestamp of the most recent visibilitychange. rAF suspends and network - * work throttles while the window is hidden, so any visibility transition - * inside a trace window means an off-screen interval overlaps the - * measurement — such traces are dropped rather than charged with the - * absence. One listener per document (tests swap documents). + * Timestamp of the most recent visibilitychange. Any transition inside a trace + * window means an off-screen interval overlaps the measurement. One listener + * per document (tests swap documents). */ let lastVisibilityChangeAt = Number.NEGATIVE_INFINITY; const watchedDocuments = new WeakSet(); @@ -341,180 +107,51 @@ function ensureVisibilityWatcher(): void { }); } -function traceOverlapsHiddenWindow(trace: ChannelSwitchTrace): boolean { +function overlapsHiddenWindow(trace: ChannelSwitchTrace): boolean { return ( document.visibilityState === "hidden" || lastVisibilityChangeAt >= trace.startedAt ); } -/** - * Timestamp to anchor a switch trace on, read during synchronous event - * dispatch. Callers that must await before they know the target channel (DM - * actions await `open_dm` for its id) capture this at the click and hand it to - * `goChannel`, so the relay round-trip stays inside the measured interval - * instead of silently preceding it. - */ -export function captureSwitchTraceAnchor(): number { - // NaN, not 0: 0 is a valid timestamp meaning "time origin", and it would - // silently report the whole session uptime as switch latency. - if (typeof performance === "undefined") return Number.NaN; - const now = performance.now(); - const dispatchingEvent = - typeof window === "undefined" ? undefined : window.event; - return dispatchingEvent && typeof dispatchingEvent.timeStamp === "number" - ? Math.min(dispatchingEvent.timeStamp, now) - : now; -} - -/** - * Samples inter-frame gaps for as long as `trace` is the active one. The - * settle path guards its own frames, but the click -> settle-entry interval - * had no starvation guard at all: process suspension there (App Nap, a - * suspended VM) fires no `visibilitychange`, and the switch recorded the whole - * absence as clean. The loop exits as soon as the trace is replaced, dropped, - * or recorded, so at most one rAF per frame is live per switch. - */ -function startStarvationHeartbeat(trace: ChannelSwitchTrace): void { - if (typeof window === "undefined" || !window.requestAnimationFrame) return; - // Bind the scheduler once. Reading the ambient `window` on every tick would - // follow a swapped-out global (tests replace it; a torn-down document in - // production would be equivalent) and throw from inside a frame callback, - // where nothing can catch it. - const schedule = window.requestAnimationFrame.bind(window); - let lastAt = trace.openedAt; - const tick = () => { - if (activeTrace !== trace) return; - const now = performance.now(); - // Past its own liveness budget the trace can no longer be measured, so - // sampling it is pure cost. Without this the loop outlives any trace that - // is never settled, dropped, or replaced — one frame callback per frame, - // forever. - if ( - now - trace.openedAt > - SWITCH_TRACE_TIMEOUT_MS + SETTLE_RENDER_WAIT_MS - ) { - return; - } - trace.maxFrameGapMs = Math.max(trace.maxFrameGapMs, now - lastAt); - lastAt = now; - try { - schedule(tick); - } catch { - // Frame loop is gone; the gap it would have measured is unknowable. - // Leave maxFrameGapMs at what was observed rather than guessing. - } - }; - try { - schedule(tick); - } catch { - /* no frame loop available; settle-path guards still apply */ - } -} - -/** - * Resolves the reported start for a trace. A caller-supplied anchor is used - * only when it is finite, not in the future, and recent enough to still be - * this navigation's click; otherwise `now` is used and the caller is told the - * anchor was discarded so the record can say so. Pure for unit testing. - */ -export function resolveTraceAnchor( - anchoredAt: number | undefined, - fallback: number, - now: number, -): { startedAt: number; anchorDiscarded: boolean } { - if (anchoredAt === undefined) { - return { - startedAt: Number.isFinite(fallback) - ? Math.max(0, Math.min(fallback, now)) - : now, - anchorDiscarded: false, - }; - } - if (!Number.isFinite(anchoredAt) || now - anchoredAt > MAX_ANCHOR_AGE_MS) { - return { startedAt: now, anchorDiscarded: true }; - } - return { - startedAt: Math.max(0, Math.min(anchoredAt, now)), - anchorDiscarded: false, - }; -} - -/** Opaque identity for one opened trace; see `cancelChannelSwitchTrace`. */ -export type ChannelSwitchTraceHandle = { readonly trace: ChannelSwitchTrace }; - -/** - * Cancels `handle`'s trace, and only that one. A later begin for the same - * channel installs a different trace object, so a failed navigation can never - * erase a newer attempt's measurement. - */ -export function cancelChannelSwitchTrace( - handle: ChannelSwitchTraceHandle | null, -): void { - if (handle && activeTrace === handle.trace) { - recordSwitchDrop(activeTrace, "navigation-failed"); - activeTrace = null; - } -} - -export function beginChannelSwitchTrace( - channelId: string, - anchoredAt?: number, -): ChannelSwitchTraceHandle | null { - if (typeof performance === "undefined") return null; - ensureVisibilityWatcher(); - // A same-task unmount-then-renavigate to this channel leaves the exit - // cleanup's scheduled abandon pending; it must not kill the fresh trace - // when its microtask drains. - cancelRouteExitAbandon(channelId); - // Anchor at the triggering input event when one is dispatching: a click - // can sit queued behind a long task before its handler runs, and that - // input delay is felt switch latency. window.event is set only during - // synchronous dispatch, so a stale timestamp can never leak in from async - // continuations; min() guards against skewed event clocks and against a - // caller-supplied anchor that a monotonic-clock skew put in the future. - const now = performance.now(); - const { startedAt, anchorDiscarded } = resolveTraceAnchor( - anchoredAt, - captureSwitchTraceAnchor(), - now, - ); - if (activeTrace) recordSwitchDrop(activeTrace, "superseded"); - activeTrace = { - channelId, - startedAt, - openedAt: now, - maxFrameGapMs: 0, - anchorDiscarded, - settleEnteredAt: null, - routeCommitAt: null, - windowFetch: null, - membersFetch: null, - }; - const handle: ChannelSwitchTraceHandle = { trace: activeTrace }; - if (anchorDiscarded) { - console.info( - `[switch-perf] channel=${channelId.slice(0, 8)} anchor discarded (stale); measuring from navigation`, - ); - } - startStarvationHeartbeat(activeTrace); - // Clear the whole previous switch here, not only in record(): traces that - // die without recording (forum visits, route exits, drops) never reach - // record()'s buffer clearing — weeks-long sessions would accumulate a - // stray start mark per abandon — and a consumer polling the buffer - // mid-switch (Playwright specs, Performance panel) must never read the - // previous switch's settled mark or measure as the current one's. +function clearSwitchEntries(): void { performance.clearMarks(CHANNEL_SWITCH_START_MARK); performance.clearMarks(CHANNEL_SWITCH_SETTLED_MARK); performance.clearMeasures(CHANNEL_SWITCH_MEASURE); - // startTime keeps the mark on the same anchor as the measure — without it - // the Performance panel would show the measure starting before its own - // start mark by the input delay. +} + +export function beginChannelSwitchTrace(channelId: string): void { + if (typeof performance === "undefined") return; + ensureVisibilityWatcher(); + if (activeTrace) dropTrace(activeTrace, "superseded"); + // Anchor at the triggering input event when one is dispatching: a click can + // sit queued behind a long task before its handler runs, and that input + // delay is felt switch latency. window.event is set only during synchronous + // dispatch, so a stale timestamp cannot leak in from an async continuation. + // min() guards a skewed event clock; max() keeps the mark non-negative, + // which performance.mark requires. + const now = performance.now(); + const dispatching = typeof window === "undefined" ? undefined : window.event; + const startedAt = + dispatching && typeof dispatching.timeStamp === "number" + ? Math.max(0, Math.min(dispatching.timeStamp, now)) + : now; + activeTrace = { + channelId, + startedAt, + routeCommitAt: null, + windowFetch: null, + settleEnteredAt: null, + }; + // Clear the previous switch here, not only on record: traces that die + // without recording never reach record()'s clearing, and a consumer polling + // the buffer mid-switch must never read the previous switch's entries. + clearSwitchEntries(); + // startTime keeps the mark on the same anchor as the measure. performance.mark(CHANNEL_SWITCH_START_MARK, { detail: { channelId }, startTime: startedAt, }); - return handle; } export function markChannelSwitchRouteCommit(channelId: string): void { @@ -526,14 +163,11 @@ export function markChannelSwitchRouteCommit(channelId: string): void { /** * A fetch attributes to the active trace only when it targets the traced - * channel and started inside the measured interval. Both bounds matter. A - * fetch that started before the switch (the first leg of a rapid A→B→A - * completing during the second A trace) is not this switch's cost, and - * letting it claim the `??=` slot would also block the real fetch. A fetch - * that started after the timeline settled is a background revalidation the - * user never waited on; the trace stays active through the deferred-paint - * wait, so without this upper bound it would be reported as switch cost. - * Pure for unit testing. + * channel and started inside the measured interval. A fetch that started + * before the switch (the first leg of a rapid A→B→A completing during the + * second A trace) is not this switch's cost, and letting it claim the slot + * would block the real fetch. A fetch that started after the timeline settled + * is background revalidation the user never waited on. Pure for unit testing. */ export function shouldAttributeFetch( trace: ChannelSwitchTrace | null, @@ -558,241 +192,104 @@ export function traceChannelWindowFetch( } /** - * Per-channel roster-fetch sequence numbers. A live join/leave invalidation - * cancels-and-replaces an in-flight roster refetch, but the underlying - * Tauri call cannot be cancelled — the superseded fetch still resolves and - * must not claim the trace's one-shot slot with a stale count. The query's - * AbortSignal is deliberately NOT used for this: merely reading - * `context.signal` flips React Query to cancel-and-revert when the last - * observer unsubscribes mid-fetch, discarding warm rosters on interrupted - * switches (a product-behavior change this instrumentation must not make). + * Drops the active trace for surfaces whose readiness this instrument cannot + * observe (forum channels, whose loading ForumView owns). Better no + * measurement than a systematically underreported one. */ -const channelMembersFetchSequences = new Map(); - -/** Registers a roster fetch attempt; pass the token to traceChannelMembersFetch. */ -export function openChannelMembersFetch(channelId: string): number { - const next = (channelMembersFetchSequences.get(channelId) ?? 0) + 1; - channelMembersFetchSequences.set(channelId, next); - return next; -} - -export function traceChannelMembersFetch( - channelId: string, - memberCount: number, - durationMs: number, - fetchStartedAt: number, - fetchAttempt?: number, -): void { - if ( - fetchAttempt !== undefined && - channelMembersFetchSequences.get(channelId) !== fetchAttempt - ) { - return; +export function abandonChannelSwitchTrace(channelId: string): void { + if (activeTrace?.channelId === channelId) { + dropTrace(activeTrace, "unobservable surface"); } - 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. + * Abandons whatever trace is active, regardless of channel. Called when + * navigation leaves the channel surface (any committed non-channel + * destination, any history traversal): a trace can be live with no channel + * screen mounted at all — the route still resolving — so this is the only + * reliable exit hook, and a later untraced re-entry would otherwise settle it + * with the time spent away. */ +export function dropActiveChannelSwitchTrace(): void { + if (activeTrace) dropTrace(activeTrace, "left channel surface"); +} + +/** Community switch (and test reset): nothing survives into the next one. */ export function resetChannelSwitchTrace(): void { - if (activeTrace) recordSwitchDrop(activeTrace, "community-reset"); + if (activeTrace) dropTrace(activeTrace, "community reset"); activeTrace = null; lastVisibilityChangeAt = Number.NEGATIVE_INFINITY; - // A community switch must not leave the previous community's marks where a - // consumer polling the buffer would read them as the next community's. - if (typeof performance !== "undefined") { - performance.clearMarks(CHANNEL_SWITCH_START_MARK); - performance.clearMarks(CHANNEL_SWITCH_SETTLED_MARK); - performance.clearMeasures(CHANNEL_SWITCH_MEASURE); - } - pendingRouteExitAbandons.clear(); - channelMembersFetchSequences.clear(); + if (typeof performance !== "undefined") clearSwitchEntries(); } -/** Bound on waiting for the deferred timeline commit before recording. */ -const SETTLE_RENDER_WAIT_MS = 5_000; - /** - * Largest inter-frame gap attributable to real main-thread work (heavy - * long tasks run a few hundred ms; 4x-throttled harness frames stay well - * under this). Anything larger is rAF starvation — suspension without a - * visibilitychange — and the sample drops. + * 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 began, and clobbering the newer trace would + * drop exactly the rapid switches worth capturing. Pure for unit testing. */ -const MAX_SETTLE_FRAME_GAP_MS = 3_000; - -/** - * Per-frame decision for the bounded settle wait: keep waiting only while - * the deferred render is still pending AND the deadline hasn't passed. When - * the wait ends with the render still pending, the record must say so — the - * >deadline tail is exactly what this tracer exists to expose, so the - * measurement is kept but flagged rather than posing as an honest settled - * paint. Frame starvation is dropped, not recorded: a healthy chain with - * nothing pending records within a frame or two of settle entry, so a - * not-pending frame landing past the wait deadline means the gap was rAF - * suspension (system suspend, App Nap — cases that fire no - * visibilitychange), not render time. A trace older than the settle-entry - * timeout plus the render wait is dropped on the same grounds regardless of - * pending state, as is a single inter-frame gap beyond any plausible - * main-thread stall — a suspension latches the pending marker, so its truth - * is not evidence the render was slow. The rare honest render that catches - * up within one frame of the deadline is sacrificed by these rules — better - * no measurement than a fabricated one. Pure for unit testing. - */ -export function resolveSettleWait( +export function resolveSettleAction( + trace: ChannelSwitchTrace | null, + channelId: string, now: number, - waitDeadline: number, - renderPending: boolean, - openedAt: number, - frameGapMs: number | null = null, -): "wait" | "drop" | { settleWaitTruncated: boolean } { - if (now - openedAt > SWITCH_TRACE_TIMEOUT_MS + SETTLE_RENDER_WAIT_MS) { - return "drop"; +): { settledTrace: ChannelSwitchTrace | null; timedOut: boolean } { + if (!trace || trace.channelId !== channelId) { + return { settledTrace: null, timedOut: false }; } - if (frameGapMs !== null && frameGapMs > MAX_SETTLE_FRAME_GAP_MS) { - return "drop"; + if (now - trace.startedAt > SWITCH_TRACE_TIMEOUT_MS) { + return { settledTrace: null, timedOut: true }; } - if (!renderPending && now > waitDeadline) return "drop"; - if (renderPending && now < waitDeadline) return "wait"; - return { settleWaitTruncated: renderPending }; -} - -/** - * Decides whether the post-readiness paint frame may still be recorded. - * `awaitDeferredCommit` guards every frame it drives, but the readiness → - * paint frame is a starvation seam of its own: process suspension (App Nap, - * a suspended VM) can land there with no `visibilitychange`, and the resumed - * frame would record the whole absence as an ordinary clean switch. Pure for - * unit testing. - */ -/** - * Reads the timeline's painted commit generation, or null when no timeline is - * mounted (Suspense fallback, forum surface). - */ -function readTimelineCommit(): number | null { - // Defensive: this runs on the settle path, and a diagnostic must never - // throw into the app. - const raw = document - .querySelector("[data-timeline-commit]") - ?.getAttribute?.("data-timeline-commit"); - if (raw == null) return null; - const parsed = Number(raw); - return Number.isFinite(parsed) ? parsed : null; -} - -/** - * Decides whether the switch's own deferred commit has painted. A pending - * marker alone cannot distinguish "my rows have not committed yet" from "live - * traffic arriving after my rows painted re-latched the marker" — and a burst - * right after a switch (the subscription's catch-up) is exactly when the - * second happens, which recorded the whole burst as switch latency, unflagged. - * A commit generation past the one painted at settle entry proves the - * timeline has committed since, so the switch's rows are on screen. - * Pure for unit testing. - */ -export function resolveRenderReadiness( - renderPending: boolean, - commitAtEntry: number | null, - commitNow: number | null, -): boolean { - if (!renderPending) return true; - if (commitAtEntry === null || commitNow === null) return false; - return commitNow > commitAtEntry; -} - -export function resolveFinalFrame( - now: number, - readyAt: number, - openedAt: number, - renderWasPending = false, -): "record" | "drop" { - // A render still pending at readiness is direct evidence that a heavy - // commit — not a suspension — owns this frame, and that measurement is - // already flagged `settleWaitTruncated`. Dropping it here would discard - // exactly the pathological switch the instrument exists to expose. - if (!renderWasPending && now - readyAt > MAX_SETTLE_FRAME_GAP_MS) { - return "drop"; - } - if (now - openedAt > SWITCH_TRACE_TIMEOUT_MS + SETTLE_RENDER_WAIT_MS) { - return "drop"; - } - return "record"; + return { settledTrace: trace, timedOut: false }; } /** * 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, and the - * lazy channel pane's Suspense fallback carries the same marker while its - * chunk is still loading — waiting for both (bounded) keeps `totalMs` - * honest on render-heavy and cold-chunk switches; a final rAF pair then - * lands the mark after the browser paints. + * exposes `data-render-pending` until its deferred commit catches up, + * and the lazy channel pane's fallback carries the same marker while its chunk + * loads; waiting for both (bounded) keeps `totalMs` honest on render-heavy and + * cold-chunk switches. A final frame then lands the mark after the paint. */ export function settleChannelSwitchTrace(channelId: string): void { if (typeof performance === "undefined") return; - const { settledTrace, clearActive } = resolveSettleAction( + const { settledTrace, timedOut } = resolveSettleAction( activeTrace, channelId, performance.now(), ); if (!settledTrace) { - if (clearActive && activeTrace) { - recordSwitchDrop(activeTrace, "timeout"); - activeTrace = null; - } + if (timedOut && activeTrace) dropTrace(activeTrace, "timed out"); return; } const trace = settledTrace; - // The click -> settle-entry interval is guarded by the heartbeat, not by - // the settle loop's own frame gaps: a suspension there fires no - // visibilitychange and would otherwise land as a clean record. - if (trace.maxFrameGapMs > MAX_SETTLE_FRAME_GAP_MS) { - recordSwitchDrop(trace, "frame-starvation"); - activeTrace = null; + // These globals gate the whole settle path: the wait loop reads + // document.visibilityState, querySelector and rAF unguarded past this point. + if ( + typeof window === "undefined" || + typeof document === "undefined" || + !window.requestAnimationFrame + ) { + dropTrace(trace, "no DOM"); return; } - // Both globals gate the whole settle path: the wait loop reads - // document.visibilityState and querySelector unguarded past this point. - if (typeof window === "undefined" || typeof document === "undefined") { - activeTrace = null; - return; - } - // rAF suspends and network work throttles in hidden windows: a hidden - // interval anywhere between the click and the recorded settle would be - // charged to the switch as a clean record. Drop when the window is hidden - // now or any visibility transition happened since the click — better no - // measurement than a fabricated one. ensureVisibilityWatcher(); - if (traceOverlapsHiddenWindow(trace)) { - recordSwitchDrop(trace, "hidden-window"); - activeTrace = null; + if (overlapsHiddenWindow(trace)) { + dropTrace(trace, "hidden window"); 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. - // Stamping settle entry closes attribution to fetches that START after - // this point — those are background work, not switch cost. + // Idempotent: a second settle for this channel must not restart the wait or + // move the fetch-attribution bound. if (trace.settleEnteredAt !== null) return; - // Bind once: a swapped-out global would otherwise throw from inside a frame - // callback, where nothing can catch it (same hazard as the heartbeat). - const schedule = window.requestAnimationFrame.bind(window); trace.settleEnteredAt = performance.now(); - const commitAtEntry = readTimelineCommit(); - const waitDeadline = performance.now() + SETTLE_RENDER_WAIT_MS; + // Bind once — reading the ambient global on every frame would follow a + // swapped-out window and throw from inside a callback nothing can catch. + const schedule = window.requestAnimationFrame.bind(window); + const record = (settleWaitTruncated: boolean) => { const settledAt = performance.now(); if (activeTrace === trace) activeTrace = null; - // Keep only the latest switch in the User Timing buffer: desktop - // sessions run for weeks and the buffer is never GC'd. DevTools - // recordings capture entries at emit time, so clearing loses nothing. - performance.clearMarks(CHANNEL_SWITCH_START_MARK); - performance.clearMarks(CHANNEL_SWITCH_SETTLED_MARK); - performance.clearMeasures(CHANNEL_SWITCH_MEASURE); + // Keep only the latest switch in the User Timing buffer: desktop sessions + // run for weeks and the buffer is never GC'd. + clearSwitchEntries(); performance.mark(CHANNEL_SWITCH_SETTLED_MARK, { detail: { channelId }, startTime: settledAt, @@ -802,7 +299,6 @@ export function settleChannelSwitchTrace(channelId: string): void { channelId, routeCommitAt: trace.routeCommitAt, windowFetch: trace.windowFetch, - membersFetch: trace.membersFetch, ...(settleWaitTruncated ? { settleWaitTruncated: true } : {}), }, start: trace.startedAt, @@ -811,80 +307,32 @@ export function settleChannelSwitchTrace(channelId: string): void { console.info( summarizeChannelSwitchTrace(trace, settledAt, settleWaitTruncated), ); - appendSwitchPerfLogRecord( - buildSwitchPerfLogRecord(trace, settledAt, settleWaitTruncated), - ); }; - const dropTrace = (reason: SwitchDropReason) => { - if (activeTrace === trace) { - recordSwitchDrop(trace, reason); - activeTrace = null; - } - }; - // Seeded now, not on the first frame: the settle-entry → first-frame - // window must be starvation-guarded too, or a suspension there records a - // truncated measure inflated by the whole stall. - let lastFrameAt: number | null = performance.now(); - 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. + + let framesWaited = 0; + const awaitPaint = () => { + // A newer switch replaced this trace, or a reset dropped it. Either way + // the paint this callback would sample is not this switch's own. + if (activeTrace !== trace) return; + if (overlapsHiddenWindow(trace)) { + dropTrace(trace, "hidden window"); return; } - if (traceOverlapsHiddenWindow(trace)) { - dropTrace("hidden-window"); + const pending = document.querySelector(RENDER_PENDING_SELECTOR) !== null; + if (pending && framesWaited < MAX_SETTLE_FRAMES) { + framesWaited += 1; + schedule(awaitPaint); return; } - const now = performance.now(); - const frameGapMs = lastFrameAt === null ? null : now - lastFrameAt; - lastFrameAt = now; - const renderPending = !resolveRenderReadiness( - document.querySelector('[data-render-pending="true"]') !== null, - commitAtEntry, - readTimelineCommit(), - ); - const decision = resolveSettleWait( - now, - waitDeadline, - renderPending, - trace.openedAt, - frameGapMs, - ); - if (decision === "wait") { - schedule(awaitDeferredCommit); - return; - } - if (decision === "drop") { - dropTrace( - frameGapMs !== null && frameGapMs > MAX_SETTLE_FRAME_GAP_MS - ? "frame-starvation" - : "settle-wait-exceeded", - ); - return; - } - const readyAt = now; + // One more frame so the mark lands after the browser paints. schedule(() => { if (activeTrace !== trace) return; - if (traceOverlapsHiddenWindow(trace)) { - dropTrace("hidden-window"); + if (overlapsHiddenWindow(trace)) { + dropTrace(trace, "hidden window"); return; } - if ( - resolveFinalFrame( - performance.now(), - readyAt, - trace.openedAt, - renderPending, - ) === "drop" - ) { - dropTrace("frame-starvation"); - return; - } - record(decision.settleWaitTruncated); + record(pending); }); }; - schedule(awaitDeferredCommit); + schedule(awaitPaint); } diff --git a/desktop/tests/e2e/switch-settle-after-paint.spec.ts b/desktop/tests/e2e/switch-settle-after-paint.spec.ts index 8c90251097..fb264593e8 100644 --- a/desktop/tests/e2e/switch-settle-after-paint.spec.ts +++ b/desktop/tests/e2e/switch-settle-after-paint.spec.ts @@ -112,77 +112,37 @@ test("settle waits for a delayed lazy channel-pane chunk", async ({ page }) => { }) .toBe(true); - // Give the tracer ample frames to (incorrectly) settle behind the held - // chunk. The tracer's 5s render-wait deadline runs from settle entry - // (query readiness — immediate in mock mode), after which it honestly - // emits a TRUNCATED measure even while suspended; the contract under test - // is that no CLEAN measure appears. Guard the timing assumption - // explicitly so a slow CI box fails with the real reason. - await page.waitForTimeout(1_500); - const early = await page.evaluate((name) => { - const start = performance.getEntriesByName("buzz:channel-switch:start")[0]; - return { - cleanMeasures: performance + // While the pane chunk is held there are no rows on screen, so any measure + // emitted here must carry the truncation flag. A CLEAN measure would be the + // regression: a settled paint reported for a screen showing a fallback. + await page.waitForTimeout(1_000); + const cleanWhileSuspended = await page.evaluate( + (name) => + performance .getEntriesByName(name) .filter( (entry) => !(entry as PerformanceMeasure).detail?.settleWaitTruncated, ).length, - elapsedSinceClick: start ? performance.now() - start.startTime : null, - }; - }, SWITCH_MEASURE); - // Order matters: a clean measure recorded behind the held chunk — the - // regression under test — clears the start mark, nulling elapsedSinceClick. - // Asserting the budget first would then fail with a "rerun, not a tracer - // bug" message that states the opposite of the truth. + SWITCH_MEASURE, + ); expect( - early.cleanMeasures, + cleanWhileSuspended, "no clean settle may be recorded while the pane chunk is suspended", ).toBe(0); - // Boolean form: a truncated record already landing clears the start mark - // and nulls elapsedSinceClick — that too is budget exhaustion, and must - // fail with this message rather than a raw matcher error. - expect( - early.elapsedSinceClick !== null && early.elapsedSinceClick < 4_500, - "harness overhead consumed the tracer's settle deadline — timing, not a tracer bug", - ).toBe(true); releaseChunk(); - // Same in-page polling as above: snapshot the DOM in the evaluation turn - // where the first CLEAN measure exists. A truncated measure here means the - // released chunk's mount outran the remaining render-wait budget — a - // harness timing exhaustion, and it must fail with that reason. - const atSettle = await page.evaluate(async (measureName) => { - const deadline = Date.now() + 15_000; - while (Date.now() < deadline) { - const entries = performance.getEntriesByName(measureName); - const clean = entries.filter( - (entry) => !(entry as PerformanceMeasure).detail?.settleWaitTruncated, - ); - if (clean.length > 0) { - return { - rowCount: document.querySelectorAll( - '[data-message-id^="mock-deep-history-"]', - ).length, - settled: true, - truncatedOnly: false, - }; - } - if (entries.length > 0) { - return { rowCount: 0, settled: false, truncatedOnly: true }; - } - await new Promise((resolve) => setTimeout(resolve, 16)); - } - return { rowCount: 0, settled: false, truncatedOnly: false }; - }, SWITCH_MEASURE); - - expect( - atSettle.truncatedOnly, - "tracer truncated before the released chunk painted — harness timing exhausted, not a tracer bug; rerun", - ).toBe(false); - expect(atSettle.settled, "switch trace must settle after release").toBe(true); - expect( - atSettle.rowCount, - "the settle must land only after the released pane painted rows", - ).toBeGreaterThan(0); + // After release the pane mounts and paints rows. The tracer's own record + // may already have landed (truncated, by design) — what matters is that the + // channel actually painted, which is what a clean settle would have claimed. + await expect + .poll( + () => + page + .locator('[data-message-id^="mock-deep-history-"]') + .count() + .then((count) => count > 0), + { message: "the released pane must paint rows", timeout: 15_000 }, + ) + .toBe(true); });