Give the frame-time measurement its own file, and its first tests
RenderTiming is the shell measuring itself, and until now nothing measured it. The percentile index, the 256-sample bound and the eviction that keeps it bounded had no test at all, which is a strange place for a codebase to have a blind spot: this is the number the footer shows a user when they ask whether the app is slow. The eight tests state the decisions the code already made, so that changing one is a choice rather than an accident. Percentiles are computed over sorted samples, not arrival order. Ninety-nine good frames and one 40ms stall keep a p50 of 100µs and the stall shows in the p95, which is the entire reason this is a distribution and not the mean it would be so much easier to compute. A full window of new frames retires every stale sample, and eviction is from the front, so the figure describes the last four seconds rather than the session. An unpaired build records nothing, because a duration with no start is not a fast frame -- it is no data, and averaging a zero into the p50 would report the shell as faster than it is. Two dispatches before one build is one sample and it is the later one, since the earlier action's tree was never built. The percentile tests build the buffer directly rather than going through the clock. Driving them through mark_dispatch would make every assertion depend on how loaded the machine running CI happens to be, which is how a timing test becomes the flaky one everybody reruns. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01SPYebLiN2w4TqnHUYGdECq
This commit is contained in:
co-authored by
Claude Opus 5
parent
6daee84ca6
commit
44c2391199
@@ -6,11 +6,12 @@ mod panel_registry;
|
|||||||
mod settings_view;
|
mod settings_view;
|
||||||
mod sidebar;
|
mod sidebar;
|
||||||
mod theme;
|
mod theme;
|
||||||
|
mod timing;
|
||||||
mod usage_feed;
|
mod usage_feed;
|
||||||
|
|
||||||
use std::collections::{BTreeMap, VecDeque};
|
use std::collections::BTreeMap;
|
||||||
use std::path::PathBuf;
|
use std::path::PathBuf;
|
||||||
use std::time::{Duration, Instant};
|
use std::time::Duration;
|
||||||
|
|
||||||
use gpui::{
|
use gpui::{
|
||||||
App, Application, Bounds, Context, FocusHandle, FontWeight, KeyDownEvent, Pixels, Rgba, Size,
|
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 attention::{Attention, AttentionKind, AttentionSignal, AttentionSource};
|
||||||
use input::{terminal_key_from_parts, terminal_scroll_from_parts};
|
use input::{terminal_key_from_parts, terminal_scroll_from_parts};
|
||||||
|
use timing::RenderTiming;
|
||||||
|
|
||||||
use geometry::{
|
use geometry::{
|
||||||
APP_FOOTER_HEIGHT, CellMetrics, TERMINAL_CELL_HEIGHT, TERMINAL_CELL_WIDTH, WindowSize,
|
APP_FOOTER_HEIGHT, CellMetrics, TERMINAL_CELL_HEIGHT, TERMINAL_CELL_WIDTH, WindowSize,
|
||||||
@@ -48,7 +50,6 @@ use sidebar::model::{
|
|||||||
use theme::{ActiveTheme, ThemeColors};
|
use theme::{ActiveTheme, ThemeColors};
|
||||||
use usage_feed::{UsageFeed, UsageSegment};
|
use usage_feed::{UsageFeed, UsageSegment};
|
||||||
|
|
||||||
const TIMING_SAMPLE_LIMIT: usize = 256;
|
|
||||||
const RUNTIME_POLL_INTERVAL: Duration = Duration::from_millis(16);
|
const RUNTIME_POLL_INTERVAL: Duration = Duration::from_millis(16);
|
||||||
const RUNTIME_DRAIN_LIMIT: usize = 64;
|
const RUNTIME_DRAIN_LIMIT: usize = 64;
|
||||||
const WORKSPACE_SNAPSHOT_ID: &str = "lumbridge-code-gpui-spike";
|
const WORKSPACE_SNAPSHOT_ID: &str = "lumbridge-code-gpui-spike";
|
||||||
@@ -336,12 +337,6 @@ impl LiveRuntimeStatus {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
#[derive(Default)]
|
|
||||||
struct RenderTiming {
|
|
||||||
pending_dispatch: Option<Instant>,
|
|
||||||
dispatch_to_element_micros: VecDeque<u128>,
|
|
||||||
}
|
|
||||||
|
|
||||||
#[derive(Clone, PartialEq)]
|
#[derive(Clone, PartialEq)]
|
||||||
struct TerminalPaintRun {
|
struct TerminalPaintRun {
|
||||||
text: String,
|
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::<Vec<_>>();
|
|
||||||
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<PathBuf> {
|
fn workspace_database_path() -> Option<PathBuf> {
|
||||||
if let Some(path) = std::env::var_os("LUMBRIDGE_SPIKE_DB") {
|
if let Some(path) = std::env::var_os("LUMBRIDGE_SPIKE_DB") {
|
||||||
return Some(PathBuf::from(path));
|
return Some(PathBuf::from(path));
|
||||||
|
|||||||
@@ -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<Instant>,
|
||||||
|
dispatch_to_element_micros: VecDeque<u128>,
|
||||||
|
}
|
||||||
|
|
||||||
|
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::<Vec<_>>();
|
||||||
|
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<Item = u128>) -> 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);
|
||||||
|
}
|
||||||
|
}
|
||||||
Reference in New Issue
Block a user