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); });