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
This commit is contained in:
Anthony Eid authored and GitHub committed 2026-08-21 19:46:11 +00:00
1 parent f36aec822b
commit 7316cf7745
2 files changed
+319 -15

No files matched your search

+310 -13
View File
@@ -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<Item = &'i ForegroundEvent>) {
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>) -> 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<ForegroundWorkSummary> {
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<u64>) {
@@ -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<u64>) {
let max_foreground_time = Duration::from_nanos(histogram.max());
eprintln!(" samples: {}", histogram.len());
eprintln!(
" mean: {}",
@@ -219,6 +315,7 @@ struct WindowFrameSnapshot {
draw: Histogram<u64>,
present_interval: Histogram<u64>,
invalidations_per_frame: Histogram<u64>,
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<u64>,
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<FrameEvent> {
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<FrameEvent>,
journal_entries: Vec<ForegroundJournalEntry>,
}
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<Item = &ForegroundEvent> {
self.journal_entries.iter().filter_map(|entry| match entry {
ForegroundJournalEntry::Event(event) => Some(event),
_ => None,
})
}
}
@@ -281,8 +435,10 @@ impl<Output> Drop for MeasuredTaskOutput<Output> {
.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() {
+9 -2
View File
@@ -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<ForegroundJournalWriter>,
_not_send: std::marker::PhantomData<std::rc::Rc<()>>,
}
@@ -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) {