From 7316cf77459a1dbc62979beffedeeeaa8e91389a Mon Sep 17 00:00:00 2001 From: Anthony Eid <56899983+Anthony-Eid@users.noreply.github.com> Date: Fri, 21 Aug 2026 19:46:11 +0000 Subject: [PATCH] gpui: Report foreground executor work in bench reports (#63035) `BenchReport`'s frame histograms only ever recorded a window's draw and present timings, so a slow foreground task that never dirtied or drew a window was invisible to `gpui::bench` consumers even though GPUI's foreground journal already timed it. Delta hit this concretely: a foreground task stalled for 76-130ms with no window draw in progress, and the only way to see it in a benchmark was to manually queue a marker task and time it by hand, outside the normal report. GPUI already has the data needed to close this gap. The foreground journal (`crate::profiler::journal`, merged separately in #62779) times every foreground task poll, action handler, and input dispatch on the main thread, independent of whether a window ever gets involved. This PR wires that journal into `BenchAppContext`/`BenchReport` so the existing benchmark harness reports it directly, instead of asking benchmark authors to build their own timing side channel. `TraceScope`, the type that already scopes frame-timing collection to a measurement, now also owns a `ForegroundJournalCollector` created at the same point it starts. Since a collector only observes journal entries recorded after its own creation, per-iteration setup work (which runs before the trace scope starts) is excluded from the measurement by construction, the same way it already was for draw/present timings. Drained task poll, action, and input events are recorded into a new `foreground_work` duration histogram on `BenchReport` (draws and presents are skipped there since the existing frame-timing histograms already cover them), exposed through `BenchReport::foreground_work()` as `count`/`total`/`max`/percentiles plus frame-budget overruns at the report's configured FPS, and printed alongside the existing histograms. Because this rides on the same per-task-poll instrumentation that already powers GPUI's hang detection, it works for `bench_task`, `bench_batched_task`, and `bench_renderer` without requiring a window at all, and it aggregates every foreground event recorded during a measurement (not just the first). The `#[cfg(test)]`-only `install_test_foreground_journal` helper is widened from `pub(super)` to `pub(crate)` so `bench_context`'s own tests can install an isolated per-thread journal instead of sharing (and being interfered by) whatever the shared production journal on that thread happens to hold. ## Testing - `cargo test -p gpui --features bench --lib bench_context` - two new focused unit tests drive the foreground journal directly: one proves a 60ms synchronous task poll with no window is reported as foreground work with no frame events recorded; the other proves an 80ms task poll before the trace scope starts is excluded from the measured summary. A third test exercises the real public API end to end, running `BenchAppContext::bench_task` through an actual `criterion::Bencher` (via `criterion::Criterion::bench_function`) and asserting the ~20ms task shows up in `BenchReport::foreground_work()`. - `cargo nextest run -p gpui --features bench --lib profiler` - the existing foreground journal, hang detection, and frame-timing test suites still pass unchanged. - `cargo check -p benchmarks --benches` - the existing `#[gpui::bench]` consumers (`bench_iter`, `bench_renderer`) still compile against the updated `TraceScope`/`BenchReport` internals. - `cargo fmt --package gpui -- --check` and `./script/clippy -p gpui --features bench` are clean. Release Notes: - N/A --- crates/gpui/src/app/bench_context.rs | 323 +++++++++++++++++++++++++-- crates/gpui/src/profiler/journal.rs | 11 +- 2 files changed, 319 insertions(+), 15 deletions(-) diff --git a/crates/gpui/src/app/bench_context.rs b/crates/gpui/src/app/bench_context.rs index 7a74bcee1f..7fc5831f72 100644 --- a/crates/gpui/src/app/bench_context.rs +++ b/crates/gpui/src/app/bench_context.rs @@ -15,7 +15,10 @@ use crate::{ PlatformTextSystem, Render, Reservation, Task, TestPlatform, ThreadedDispatcher, VisualContext, Window, WindowBounds, WindowHandle, WindowOptions, app::GpuiBorrow, - profiler::{self, FrameEvent, FrameTimingCollector}, + profiler::{ + self, FrameEvent, FrameTimingCollector, + journal::{ForegroundEvent, ForegroundJournalCollector, ForegroundJournalEntry}, + }, }; /// Returns a benchmark platform backed by this thread's shared dispatcher. @@ -63,6 +66,32 @@ const DEFAULT_FPS: u64 = 120; const NANOS_PER_SECOND: u128 = 1_000_000_000; +/// Aggregate statistics for total foreground executor work observed during a +/// measured interval, returned by [`BenchReport::foreground_work`]. +#[derive(Clone, Copy, Debug)] +pub struct ForegroundWorkSummary { + /// Number of foreground work items recorded: task polls, action + /// handlers, input dispatches, and folded sub-floor poll flushes. + pub count: u64, + /// Sum of every recorded item's duration. + pub total: Duration, + /// The longest single recorded item. + pub max: Duration, + /// 50th percentile duration. + pub p50: Duration, + /// 90th percentile duration. + pub p90: Duration, + /// 95th percentile duration. + pub p95: Duration, + /// 99th percentile duration. + pub p99: Duration, + /// How many whole frame budgets (at the report's configured FPS) were + /// exceeded in total, summed across every recorded item. + pub frame_budget_overruns_total: u64, + /// How many whole frame budgets the longest recorded item exceeded. + pub frame_budget_overruns_max: u64, +} + /// A small report produced by GPUI benchmarks. #[derive(Clone)] pub struct BenchReport { @@ -128,6 +157,24 @@ impl BenchReport { } } + /// Records total foreground executor work observed during a measured + /// interval: task polls, action handlers, and input dispatches, whether + /// or not they produced a window draw. Draws and presents are excluded + /// here since [`Self::record_frame_timings`] already accounts for them. + fn record_foreground_events<'i>(&self, events: impl IntoIterator) { + let mut snapshot = self.frame_snapshot.borrow_mut(); + for event in events { + let duration = match event { + ForegroundEvent::Draw(_) | ForegroundEvent::Present(_) => continue, + // A flush's span (used by `ForegroundEvent::duration`) is not + // the time spent polling; its summary total is. + ForegroundEvent::SmallPolls(flush) => flush.summary.total, + _ => event.duration(), + }; + snapshot.foreground_work.record(duration); + } + } + fn total_budget_overruns(&self, histogram: &Histogram) -> u64 { histogram .iter_recorded() @@ -152,6 +199,36 @@ impl BenchReport { over_budget_nanos.div_ceil(self.frame_budget_nanos) as u64 } + /// Returns aggregate statistics for total foreground executor work + /// observed during the measured interval: every task poll, action + /// handler, and input dispatch on the foreground thread, whether or not + /// it produced a window draw. This is captured through GPUI's foreground + /// journal, so it requires no window and surfaces a slow or stalled task + /// even when nothing was drawn while it ran. + /// + /// Returns `None` when no foreground work was recorded, e.g. a + /// [`BenchAppContext::bench_iter`] measurement that does no async work. + pub fn foreground_work(&self) -> Option { + let frame_snapshot = self.frame_snapshot.borrow(); + let foreground_work = &frame_snapshot.foreground_work; + if foreground_work.histogram.is_empty() { + return None; + } + + let max = Duration::from_nanos(foreground_work.histogram.max()); + Some(ForegroundWorkSummary { + count: foreground_work.histogram.len(), + total: Duration::from_nanos(foreground_work.total_nanos), + max, + p50: Duration::from_nanos(foreground_work.histogram.value_at_quantile(0.50)), + p90: Duration::from_nanos(foreground_work.histogram.value_at_quantile(0.90)), + p95: Duration::from_nanos(foreground_work.histogram.value_at_quantile(0.95)), + p99: Duration::from_nanos(foreground_work.histogram.value_at_quantile(0.99)), + frame_budget_overruns_total: self.total_budget_overruns(&foreground_work.histogram), + frame_budget_overruns_max: self.budget_overruns(max), + }) + } + /// Prints this report to stderr. pub fn print(&self, benchmark_name: Option<&'static str>) { let frame_snapshot = self.frame_snapshot.borrow(); @@ -172,6 +249,7 @@ impl BenchReport { frame_snapshot.invalidations_per_frame.max() ); } + self.print_foreground_work(&frame_snapshot.foreground_work); } fn print_histogram(&self, name: &str, histogram: &Histogram) { @@ -179,8 +257,26 @@ impl BenchReport { return; } - let max_foreground_time = Duration::from_nanos(histogram.max()); eprintln!(" {name}:"); + self.print_histogram_body(histogram); + } + + fn print_foreground_work(&self, foreground_work: &DurationHistogram) { + if foreground_work.histogram.is_empty() { + return; + } + + eprintln!(" foreground executor work (task polls, actions, input dispatch):"); + eprintln!(" note: excludes window draw/present, reported separately above"); + eprintln!( + " total: {}", + format_duration(Duration::from_nanos(foreground_work.total_nanos)) + ); + self.print_histogram_body(&foreground_work.histogram); + } + + fn print_histogram_body(&self, histogram: &Histogram) { + let max_foreground_time = Duration::from_nanos(histogram.max()); eprintln!(" samples: {}", histogram.len()); eprintln!( " mean: {}", @@ -219,6 +315,7 @@ struct WindowFrameSnapshot { draw: Histogram, present_interval: Histogram, invalidations_per_frame: Histogram, + foreground_work: DurationHistogram, } impl WindowFrameSnapshot { @@ -228,11 +325,39 @@ impl WindowFrameSnapshot { draw: Histogram::new(3).expect("3 significant digits is valid"), present_interval: Histogram::new(3).expect("3 significant digits is valid"), invalidations_per_frame: Histogram::new(3).expect("3 significant digits is valid"), + foreground_work: DurationHistogram::new(), } } fn is_empty(&self) -> bool { - self.dirty_to_draw.is_empty() && self.draw.is_empty() && self.present_interval.is_empty() + self.dirty_to_draw.is_empty() + && self.draw.is_empty() + && self.present_interval.is_empty() + && self.foreground_work.histogram.is_empty() + } +} + +/// A duration histogram paired with an exact running total, since the +/// histogram's bucketed values (3 significant digits) approximate a sum less +/// precisely than tracking it directly. +struct DurationHistogram { + histogram: Histogram, + total_nanos: u64, +} + +impl DurationHistogram { + fn new() -> Self { + Self { + histogram: Histogram::new(3).expect("3 significant digits is valid"), + total_nanos: 0, + } + } + + fn record(&mut self, duration: Duration) { + let nanos = duration.as_nanos() as u64; + // Infallible: the histogram auto-resizes. + self.histogram.record(nanos).ok(); + self.total_nanos += nanos; } } @@ -240,27 +365,56 @@ fn format_duration(duration: Duration) -> String { format!("{:.3}ms", duration.as_secs_f64() * 1000.) } -/// Enables profiler tracing for a measurement and collects its frame events. +/// Enables profiler tracing for a measurement and collects its frame events +/// and foreground journal entries. /// /// The previous tracing state is restored on drop, so a panicking measurement /// doesn't leave tracing enabled for unrelated code such as a later benchmark /// in the same process. +/// +/// The foreground journal collector is created at the same point, so +/// foreground work recorded before the scope starts (e.g. per-iteration +/// setup) is excluded from what [`Self::finish`] returns: a collector only +/// observes entries recorded after its creation. struct TraceScope { collector: FrameTimingCollector, + journal_collector: ForegroundJournalCollector, _trace_guard: profiler::TraceGuard, } impl TraceScope { - fn start() -> Self { + fn start(journal_collector: ForegroundJournalCollector) -> Self { let trace_guard = profiler::trace_scope(); Self { collector: FrameTimingCollector::new(), + journal_collector, _trace_guard: trace_guard, } } - fn finish(mut self) -> Vec { - self.collector.collect_unseen() + fn finish(mut self) -> TracedEvents { + TracedEvents { + frame_events: self.collector.collect_unseen(), + journal_entries: self.journal_collector.collect_unseen().entries, + } + } +} + +/// Events observed during one [`TraceScope`]. +struct TracedEvents { + frame_events: Vec, + journal_entries: Vec, +} + +impl TracedEvents { + /// Foreground journal entries that describe completed work (task polls, + /// action handlers, input dispatches, draws, presents, and folded + /// sub-floor polls), excluding interval boundaries and metadata. + fn foreground_events(&self) -> impl Iterator { + self.journal_entries.iter().filter_map(|entry| match entry { + ForegroundJournalEntry::Event(event) => Some(event), + _ => None, + }) } } @@ -281,8 +435,10 @@ impl Drop for MeasuredTaskOutput { .trace_scope .take() .expect("measured task output should retain its trace scope"); + let events = trace_scope.finish(); + self.report.record_frame_timings(events.frame_events.iter()); self.report - .record_frame_timings(trace_scope.finish().iter()); + .record_foreground_events(events.foreground_events()); } } @@ -458,6 +614,12 @@ impl<'a, 'measurement> BenchAppContext<'a, 'measurement> { .run_until(ready) } + /// Creates a collector observing foreground journal entries recorded + /// from this point on, for use by a new [`TraceScope`]. + fn foreground_journal_collector(&self) -> ForegroundJournalCollector { + self.read(|app| app.foreground_journal().collector()) + } + /// Measures a generic benchmark workload using Criterion's iteration loop. /// /// The closure is invoked once per Criterion iteration with this @@ -467,10 +629,13 @@ impl<'a, 'measurement> BenchAppContext<'a, 'measurement> { /// benchmark's frame report through the GPUI frame profiler. pub fn bench_iter(&mut self, mut benchmark: impl FnMut(&mut Self)) { let bencher = self.take_bencher("bench_iter"); - let collector = TraceScope::start(); + let collector = TraceScope::start(self.foreground_journal_collector()); let mut benchmark = || benchmark(self); bencher.iter(&mut benchmark); - self.report.record_frame_timings(collector.finish().iter()); + let events = collector.finish(); + self.report.record_frame_timings(events.frame_events.iter()); + self.report + .record_foreground_events(events.foreground_events()); self.replace_bencher(bencher); } @@ -532,7 +697,9 @@ impl<'a, 'measurement> BenchAppContext<'a, 'measurement> { setup_context.settle(); MeasuredTaskInput { input: setup(&mut setup_context), - trace_scope: Some(TraceScope::start()), + trace_scope: Some(TraceScope::start( + setup_context.foreground_journal_collector(), + )), } }, |measured_input| { @@ -574,7 +741,7 @@ impl<'a, 'measurement> BenchAppContext<'a, 'measurement> { .expect("cannot benchmark renderer for entity without a current window"); let dispatcher = self.background_executor.dispatcher().clone(); - let collector = TraceScope::start(); + let collector = TraceScope::start(self.foreground_journal_collector()); let mut benchmark = || { // Work already queued at frame start delays the frame in @@ -599,10 +766,16 @@ impl<'a, 'measurement> BenchAppContext<'a, 'measurement> { let events = collector.finish(); self.report - .record_frame_timings(events.iter().filter(|event| match event { + .record_frame_timings(events.frame_events.iter().filter(|event| match event { FrameEvent::Draw(timing) => timing.window_id == window_id, FrameEvent::Present(timing) => timing.window_id == window_id, })); + // Foreground work isn't attributed to a window, so unlike frame + // timings above it isn't filtered by `window_id`. A benchmark app + // hosts one window at a time, so this cannot pick up unrelated + // windows' work. + self.report + .record_foreground_events(events.foreground_events()); self.replace_bencher(bencher); } @@ -951,6 +1124,130 @@ mod tests { use std::{rc::Rc, sync::Arc}; use super::*; + use crate::profiler::journal::install_test_foreground_journal; + + #[test] + fn foreground_work_reports_long_task_without_window_draw() { + let (journal, _journal_guard) = install_test_foreground_journal(1024, 64); + let dispatcher = Arc::new(ThreadedDispatcher::new()); + let foreground_executor = ForegroundExecutor::new(dispatcher); + + let trace_scope = TraceScope::start(journal.collector()); + + // A single foreground task poll that never touches a window, akin + // to the stall a debounced background computation can cause. + let task = foreground_executor.spawn(async move { + std::thread::sleep(Duration::from_millis(60)); + }); + run_task_to_completion(&foreground_executor, task); + + let events = trace_scope.finish(); + assert!( + events.frame_events.is_empty(), + "no window was involved, so no frame events should be recorded" + ); + + let report = BenchReport::default(); + report.record_foreground_events(events.foreground_events()); + + let summary = report + .foreground_work() + .expect("a long task poll should be reported even without a window draw"); + // The spawned task's own poll is one sample; the tiny wrapper poll + // that observes its completion in `run_task_to_completion` folds + // into a second, near-zero sample rather than being dropped. + assert!(summary.count >= 1, "expected at least one recorded item"); + assert!( + summary.max >= Duration::from_millis(55), + "expected the long poll's duration to be recorded, got {:?}", + summary.max + ); + // `total` is an exact sum, while `max` may be rounded up to its + // histogram bucket's boundary, so compare each against the expected + // floor directly instead of against each other. + assert!( + summary.total >= Duration::from_millis(55), + "expected the long poll's duration to be included in the total, got {:?}", + summary.total + ); + } + + #[test] + fn foreground_work_excludes_setup_before_trace_scope_starts() { + let (journal, _journal_guard) = install_test_foreground_journal(1024, 64); + let dispatcher = Arc::new(ThreadedDispatcher::new()); + let foreground_executor = ForegroundExecutor::new(dispatcher); + + // Fixture/setup work that must not be attributed to the measurement: + // a long poll recorded before the trace scope (and its journal + // collector) is created. + let setup_task = foreground_executor.spawn(async move { + std::thread::sleep(Duration::from_millis(80)); + }); + run_task_to_completion(&foreground_executor, setup_task); + + let trace_scope = TraceScope::start(journal.collector()); + + let measured_task = foreground_executor.spawn(async move { + std::thread::sleep(Duration::from_millis(10)); + }); + run_task_to_completion(&foreground_executor, measured_task); + + let events = trace_scope.finish(); + let report = BenchReport::default(); + report.record_foreground_events(events.foreground_events()); + + let summary = report + .foreground_work() + .expect("the measured task's poll should be reported"); + assert!( + summary.max < Duration::from_millis(40), + "setup work's 80ms poll must not leak into the measured summary, got {:?}", + summary.max + ); + assert!( + summary.total < Duration::from_millis(40), + "setup work's 80ms poll must not leak into the measured total, got {:?}", + summary.total + ); + } + + #[test] + fn bench_task_reports_long_task_without_window() { + let platform = bench_platform(None, Arc::new(crate::NoopTextSystem::new())); + let report = BenchReport::default(); + let name = "bench_task_reports_long_task_without_window"; + + let mut criterion = criterion::Criterion::default() + .without_plots() + .sample_size(10) + .warm_up_time(Duration::from_millis(1)) + .measurement_time(Duration::from_millis(1)); + + criterion.bench_function(name, |bencher| { + let mut cx = BenchAppContext::new_with_platform_and_report( + platform.clone(), + Some(name), + bencher, + report.clone(), + ); + cx.bench_task(|cx| { + cx.foreground_executor().spawn(async move { + std::thread::sleep(Duration::from_millis(20)); + }) + }); + cx.teardown(); + }); + + let summary = report + .foreground_work() + .expect("bench_task should report foreground work with no window involved"); + assert!( + summary.max >= Duration::from_millis(15), + "expected a ~20ms task poll to be recorded, got {:?}", + summary.max + ); + } #[test] fn task_completion_supports_non_send_foreground_output() { diff --git a/crates/gpui/src/profiler/journal.rs b/crates/gpui/src/profiler/journal.rs index ffd694b914..761181a0ad 100644 --- a/crates/gpui/src/profiler/journal.rs +++ b/crates/gpui/src/profiler/journal.rs @@ -553,8 +553,11 @@ pub(crate) fn install_foreground_journal() -> ForegroundJournal { }) } +/// Restores the previous foreground journal on drop, so a test's writer +/// (turn depth, pending frames, retained-since-boundary state) never leaks +/// into a later test that happens to reuse the same test-harness thread. #[cfg(test)] -pub(super) struct TestForegroundJournalGuard { +pub(crate) struct TestForegroundJournalGuard { previous: Option, _not_send: std::marker::PhantomData>, } @@ -568,8 +571,12 @@ impl Drop for TestForegroundJournalGuard { } } +/// Installs a fresh journal for the duration of a test, isolated from +/// whatever a previous test left on this thread. Used by tests outside this +/// module (e.g. `bench_context`) that need to observe journal entries +/// without interference from the shared per-thread journal. #[cfg(test)] -pub(super) fn install_test_foreground_journal( +pub(crate) fn install_test_foreground_journal( capacity: usize, pending_capacity: usize, ) -> (ForegroundJournal, TestForegroundJournalGuard) {