diff --git a/apps/lumbridge/src/main.rs b/apps/lumbridge/src/main.rs index d71eb20..1c1f027 100644 --- a/apps/lumbridge/src/main.rs +++ b/apps/lumbridge/src/main.rs @@ -6,11 +6,12 @@ mod panel_registry; mod settings_view; mod sidebar; mod theme; +mod timing; mod usage_feed; -use std::collections::{BTreeMap, VecDeque}; +use std::collections::BTreeMap; use std::path::PathBuf; -use std::time::{Duration, Instant}; +use std::time::Duration; use gpui::{ App, Application, Bounds, Context, FocusHandle, FontWeight, KeyDownEvent, Pixels, Rgba, Size, @@ -33,6 +34,7 @@ use lumbridge_ui_fixture::{ use attention::{Attention, AttentionKind, AttentionSignal, AttentionSource}; use input::{terminal_key_from_parts, terminal_scroll_from_parts}; +use timing::RenderTiming; use geometry::{ APP_FOOTER_HEIGHT, CellMetrics, TERMINAL_CELL_HEIGHT, TERMINAL_CELL_WIDTH, WindowSize, @@ -48,7 +50,6 @@ use sidebar::model::{ use theme::{ActiveTheme, ThemeColors}; use usage_feed::{UsageFeed, UsageSegment}; -const TIMING_SAMPLE_LIMIT: usize = 256; const RUNTIME_POLL_INTERVAL: Duration = Duration::from_millis(16); const RUNTIME_DRAIN_LIMIT: usize = 64; const WORKSPACE_SNAPSHOT_ID: &str = "lumbridge-code-gpui-spike"; @@ -336,12 +337,6 @@ impl LiveRuntimeStatus { } } -#[derive(Default)] -struct RenderTiming { - pending_dispatch: Option, - dispatch_to_element_micros: VecDeque, -} - #[derive(Clone, PartialEq)] struct TerminalPaintRun { text: String, @@ -504,45 +499,6 @@ fn dim_color(color: Rgba) -> Rgba { } } -impl RenderTiming { - fn mark_dispatch(&mut self) { - self.pending_dispatch = Some(Instant::now()); - } - - fn observe_element_build(&mut self) { - let Some(started) = self.pending_dispatch.take() else { - return; - }; - if self.dispatch_to_element_micros.len() == TIMING_SAMPLE_LIMIT { - self.dispatch_to_element_micros.pop_front(); - } - self.dispatch_to_element_micros - .push_back(started.elapsed().as_micros()); - } - - fn summary(&self) -> String { - if self.dispatch_to_element_micros.is_empty() { - return "dispatch→element collecting…".to_owned(); - } - let mut samples = self - .dispatch_to_element_micros - .iter() - .copied() - .collect::>(); - samples.sort_unstable(); - let percentile = |percent: usize| { - let index = ((samples.len() - 1) * percent) / 100; - samples[index] - }; - format!( - "dispatch→element p50 {}µs · p95 {}µs · n{}", - percentile(50), - percentile(95), - samples.len() - ) - } -} - fn workspace_database_path() -> Option { if let Some(path) = std::env::var_os("LUMBRIDGE_SPIKE_DB") { return Some(PathBuf::from(path)); diff --git a/apps/lumbridge/src/timing.rs b/apps/lumbridge/src/timing.rs new file mode 100644 index 0000000..2ba3f4f --- /dev/null +++ b/apps/lumbridge/src/timing.rs @@ -0,0 +1,201 @@ +//! What the shell measures about itself: how long a dispatch takes to become +//! an element tree. +//! +//! One number, sampled every frame and reported as a distribution rather than +//! an average, because an average hides exactly the frames a user notices. A +//! mean of 400µs is compatible with every frame being fine and with one frame +//! in twenty stalling; the p95 is the one that says which. +//! +//! The window is deliberately small. [`TIMING_SAMPLE_LIMIT`] samples at roughly +//! sixty frames a second is about four seconds of history, so the footer +//! reports the interaction that just happened rather than an average over the +//! whole session that never moves again once it has settled. Old samples are +//! evicted from the front rather than the buffer being cleared, so the figure +//! never jumps back to "collecting…" while the app is being used. +//! +//! Nothing here touches a renderer. `mark_dispatch` is called when an action +//! is accepted and `observe_element_build` when the tree has been built, and +//! the pairing is the measurement: an unpaired mark is simply overwritten by +//! the next one, and an unpaired observation records nothing, because a +//! duration with no start is not a slow frame — it is no data. + +use std::collections::VecDeque; +use std::time::Instant; + +/// How many frames of history the summary is computed over. See the module +/// note: this is a window, not a total. +const TIMING_SAMPLE_LIMIT: usize = 256; + +#[derive(Default)] +pub(crate) struct RenderTiming { + pending_dispatch: Option, + dispatch_to_element_micros: VecDeque, +} + +impl RenderTiming { + pub(crate) fn mark_dispatch(&mut self) { + self.pending_dispatch = Some(Instant::now()); + } + + pub(crate) fn observe_element_build(&mut self) { + let Some(started) = self.pending_dispatch.take() else { + return; + }; + if self.dispatch_to_element_micros.len() == TIMING_SAMPLE_LIMIT { + self.dispatch_to_element_micros.pop_front(); + } + self.dispatch_to_element_micros + .push_back(started.elapsed().as_micros()); + } + + pub(crate) fn summary(&self) -> String { + if self.dispatch_to_element_micros.is_empty() { + return "dispatch→element collecting…".to_owned(); + } + let mut samples = self + .dispatch_to_element_micros + .iter() + .copied() + .collect::>(); + samples.sort_unstable(); + let percentile = |percent: usize| { + let index = ((samples.len() - 1) * percent) / 100; + samples[index] + }; + format!( + "dispatch→element p50 {}µs · p95 {}µs · n{}", + percentile(50), + percentile(95), + samples.len() + ) + } +} + +#[cfg(test)] +mod tests { + use super::{RenderTiming, TIMING_SAMPLE_LIMIT}; + + /// Builds a timing with exactly these samples, bypassing the clock. + /// + /// The percentile arithmetic is what is under test, and it cannot be tested + /// through `mark_dispatch`/`observe_element_build` because those measure + /// real elapsed time and would make the assertions depend on how busy the + /// machine running CI happens to be. + fn with_samples(samples: impl IntoIterator) -> RenderTiming { + RenderTiming { + pending_dispatch: None, + dispatch_to_element_micros: samples.into_iter().collect(), + } + } + + #[test] + fn a_summary_with_no_samples_says_so_rather_than_reporting_zero() { + // Reporting "p50 0µs" before anything has been measured would be a + // claim the shell cannot support, and zero is exactly the number a + // reader would take as good news. + assert_eq!( + RenderTiming::default().summary(), + "dispatch→element collecting…" + ); + } + + #[test] + fn the_percentiles_index_the_sorted_samples_not_the_arrival_order() { + // 1..=100 shuffled by construction: the buffer is in arrival order and + // the summary must sort before indexing, or the figures are whichever + // frames happened to be recent. + let arrival = (1..=100_u128).rev(); + assert_eq!( + with_samples(arrival).summary(), + "dispatch→element p50 50µs · p95 95µs · n100" + ); + } + + #[test] + fn one_slow_frame_moves_the_p95_and_leaves_the_p50_alone() { + // The whole reason this is a distribution and not a mean: ninety-nine + // good frames and one 40ms stall is a stutter a user sees, and an + // average would report it as 400µs and call that healthy. + let mut samples = vec![100_u128; 99]; + samples.push(40_000); + let summary = with_samples(samples).summary(); + assert_eq!(summary, "dispatch→element p50 100µs · p95 100µs · n100"); + + let mut samples = vec![100_u128; 90]; + samples.extend([40_000_u128; 10]); + let summary = with_samples(samples).summary(); + assert!( + summary.contains("p50 100µs") && summary.contains("p95 40000µs"), + "ten stalls in a hundred frames must show in the p95: {summary}" + ); + } + + #[test] + fn a_single_sample_is_its_own_median_and_its_own_tail() { + // (len - 1) * percent / 100 is zero for every percentile at len 1, so + // this is the case where an off-by-one in the index would panic rather + // than merely lie. + assert_eq!( + with_samples([7_u128]).summary(), + "dispatch→element p50 7µs · p95 7µs · n1" + ); + } + + #[test] + fn the_window_evicts_the_oldest_sample_instead_of_growing_without_bound() { + let mut timing = RenderTiming::default(); + for _ in 0..TIMING_SAMPLE_LIMIT * 2 { + timing.mark_dispatch(); + timing.observe_element_build(); + } + assert_eq!( + timing.dispatch_to_element_micros.len(), + TIMING_SAMPLE_LIMIT, + "the buffer is a window over recent frames, not a session-long log" + ); + assert!( + timing + .summary() + .ends_with(&format!("n{TIMING_SAMPLE_LIMIT}")), + "the reported sample count must be the window, not the total" + ); + } + + #[test] + fn eviction_drops_the_front_so_the_summary_describes_recent_frames() { + // Fill the window with a value that would dominate both percentiles, + // then push a full window of a different one. If eviction took from the + // back, or cleared, the old figure would survive. + let mut timing = with_samples(std::iter::repeat_n(9_999_u128, TIMING_SAMPLE_LIMIT)); + for _ in 0..TIMING_SAMPLE_LIMIT { + timing.mark_dispatch(); + timing.observe_element_build(); + } + assert!( + !timing.dispatch_to_element_micros.contains(&9_999), + "a full window of new frames must have retired every stale sample" + ); + } + + #[test] + fn an_observation_with_no_dispatch_records_nothing() { + // A build with no dispatch behind it is not a fast frame; it is not a + // measurement at all, and recording it would pull the p50 towards zero. + let mut timing = RenderTiming::default(); + timing.observe_element_build(); + assert_eq!(timing.summary(), "dispatch→element collecting…"); + } + + #[test] + fn a_second_dispatch_before_a_build_measures_from_the_second() { + // Two dispatches then one build is one sample, not two, and it is the + // later one: the earlier action's tree was never built, so timing it + // would attribute the wait to the wrong keystroke. + let mut timing = RenderTiming::default(); + timing.mark_dispatch(); + timing.mark_dispatch(); + timing.observe_element_build(); + timing.observe_element_build(); + assert_eq!(timing.dispatch_to_element_micros.len(), 1); + } +}