frust_shell_common/perf.rs
1//! Frame-timing and startup-span perf instrumentation shared by every shell.
2//!
3//! # What lives here
4//!
5//! - [`FrameStats`] — a per-shell recorder of one frame's pass durations
6//! (rebuild/layout/paint/encode/acquire/submit, plus a `skipped` marker the
7//! mobile dirty-gate sets), aggregated into a ring buffer
8//! plus running totals; [`FrameStats::summary`] reports p50/p95/p99 total
9//! frame time, per-pass p95, and frames-over-budget counts against the
10//! 16.6ms/8.3ms (60Hz/120Hz) targets.
11//! - [`StartupSpans`] — named monotonic timestamps from a shell's `begin()`
12//! epoch (native-lib load, init entry, adapter/device/renderer ready,
13//! first rebuild done, first frame presented — see the `SPAN_*` consts),
14//! summarized into one log line.
15//! - [`enabled`] — the process-wide on/off switch every recording API is a
16//! no-op behind (see its own docs).
17//! - [`raw_enabled`] — a second dial that, alongside
18//! [`enabled`], makes [`FrameStats::record`] additionally emit one
19//! `frust-perf raw` line per recorded frame (instead of only the
20//! rate-limited ~2s `frust-perf frame` summary [`FrameStats::emit_log`]
21//! already produces).
22//! - [`mark_scenario_start`]/[`mark_scenario_end`] — the benchmark
23//! scenario-window edges a harness slices that per-frame series by. They
24//! ride [`enabled`] alone (not the raw dial), and they are *queued* rather
25//! than logged: [`FrameStats::record`] emits each one stamped with the
26//! number of the frame that actually carried it, so a window survives the
27//! render-thread split's UI/render interleaving. The whole route is
28//! `perf-trace`-only (a release-lean build has no marker code at all) and
29//! **per-thread** — a marker belongs to the thread that raised it until
30//! that thread hands a frame off or records one. See
31//! [`mark_scenario_start`] for the route, the half-open window rule, and
32//! what happens to a marker raised on a thread that does neither.
33//!
34//! # Layering choice
35//!
36//! This lives in `frust-shell-common`, not `frust-core` — timing is
37//! shell-owned by design (`docs/CODE_STANDARDS.md`'s "no `Instant::now()` in
38//! `frust-core`/`frust-widgets`" rule binds the framework layers only;
39//! a shell reading a wall clock to time its own passes is exactly the kind
40//! of shell-facing responsibility this crate already carries alongside
41//! `theme_override`/`ffi_support`). Every recording API takes an
42//! already-measured [`std::time::Duration`] rather than reading a clock
43//! itself, and [`StartupSpans`] is generic over an injectable [`Clock`] —
44//! this crate's own logic stays fully host-testable without a real clock.
45//!
46//! # Wiring
47//!
48//! This module ships the recorder + switch; the Android, iOS, and desktop
49//! shells each construct and feed a [`FrameStats`]/[`StartupSpans`] of
50//! their own.
51
52#[cfg(all(test, feature = "perf-trace"))]
53use std::cell::Cell;
54#[cfg(feature = "perf-trace")]
55use std::cell::RefCell;
56use std::collections::VecDeque;
57#[cfg(feature = "perf-trace")]
58use std::sync::OnceLock;
59use std::time::{Duration, Instant};
60
61/// Ring-buffer capacity for [`FrameStats`] — roughly 2 seconds of frames at
62/// 60Hz, enough for a stable rolling percentile without unbounded growth.
63pub const RING_CAPACITY: usize = 120;
64
65/// The 60Hz frame budget (1000/60 ms), truncated to whole microseconds.
66pub const BUDGET_60HZ: Duration = Duration::from_micros(16_667);
67
68/// The 120Hz frame budget (1000/120 ms), truncated to whole microseconds.
69pub const BUDGET_120HZ: Duration = Duration::from_micros(8_333);
70
71/// Minimum span of recorded frame time between two [`FrameStats::emit_log`]
72/// calls that [`FrameStats::should_emit`] requires — one line every ~2s of
73/// frames, measured in accumulated frame time rather than
74/// wall-clock time so it needs no clock of its own.
75const EMIT_INTERVAL: Duration = Duration::from_secs(2);
76
77// ---------------------------------------------------------------------
78// On/off switch
79// ---------------------------------------------------------------------
80//
81// The whole of this module is *runtime*-switchable via [`enabled`], but that
82// runtime dial only exists when the crate's `perf-trace` cargo feature is on.
83// Without the feature every `frust-perf`/`bench-scenario` string literal and
84// its `log::info!` emission is `#[cfg]`-compiled out entirely (release-lean
85// builds), and [`enabled`]/[`raw_enabled`] collapse to inlinable `false`
86// constants so downstream `if enabled()` branches constant-fold away — the CLI
87// turns the feature on for debug/profile builds and omits it for release (the
88// Flutter-mode-parity split, see the release-lean plan). The public perf API
89// (types, constructors, `record`/`summary`/`emit_log`/`mark_scenario_*`)
90// compiles identically in both configurations; only the string-bearing
91// emission internals are gated, so no shell call site changes.
92//
93// Sink decision (feeds the release-lean log-level ceiling): `frust-perf`
94// lines keep flowing through the `log` facade (`log::info!`), NOT a bypassing
95// `eprintln!`/platform sink. Rationale — this crate is deliberately
96// platform-free (no `android_logger`/NDK), so it cannot replicate each
97// platform's real channel (logcat on Android, the desktop/iOS stderr logger),
98// and moving Android's lines off logcat would break the benchmark harness's
99// log parsing; keeping `log::info!` guarantees byte-identical output on every
100// platform. The consequence this MUST honor: perf is stripped from release
101// by THIS FEATURE (off ⇒ code+strings gone), never by the log level. So
102// `release_max_level_warn` must be applied to RELEASE ONLY (e.g. a
103// CLI-toggled `log/release_max_level_warn` cargo feature enabled for
104// `--release` and omitted for `--profile`), never as an always-on manifest
105// feature: `release_max_level_*` keys off `debug_assertions`, which is OFF in
106// the profile profile too, so an always-on ceiling would silence profile-mode
107// perf lines. Release perf lines don't exist to strip
108// (feature off), so a release-only ceiling only removes stray non-perf
109// info/debug while profile keeps its `frust-perf` output intact.
110
111/// The process-wide perf-instrumentation switch, cached after the first
112/// call. `true` when either:
113///
114/// - the compile-time `FRUST_TRACE` define is set to a non-`"0"` value
115/// (the `--define`/`--profile` path — `--profile` builds
116/// pass `FRUST_TRACE=1` by default; `option_env!` reads whatever a
117/// build script/cargo-ndk env var set at compile time), or
118/// - the runtime `FRUST_TRACE` process environment variable is set to a
119/// non-`"0"` value (desktop dev: `FRUST_TRACE=1 cargo run -p ...`) — the
120/// compile-time-or-runtime convention every shipping `FRUST_*` knob
121/// follows.
122///
123/// Every recording API in this module (`FrameStats::record`,
124/// `StartupSpans::record`, both `emit_log`s) is a cheap no-op when this is
125/// `false` — no allocation, no clock read, on the hot path.
126///
127/// Cached in a `OnceLock`: the switch is read once per process and never
128/// changes afterward, so this is intentionally not re-evaluatable at
129/// runtime — a shell that needs to bypass the cache for testing should
130/// construct a [`FrameStats`]/[`StartupSpans`] via the explicit
131/// `*_enabled`/`begin_with` constructors instead of relying on this
132/// function's cache.
133#[cfg(feature = "perf-trace")]
134pub fn enabled() -> bool {
135 static ENABLED: OnceLock<bool> = OnceLock::new();
136 *ENABLED
137 .get_or_init(|| trace_switch(option_env!("FRUST_TRACE"), runtime_trace_var().as_deref()))
138}
139
140/// The `perf-trace` feature is off: perf instrumentation is compiled out of
141/// this build, so the switch is a compile-time `false` constant — no
142/// `OnceLock`, no environment read. `#[inline]` so every downstream
143/// `if enabled()` branch constant-folds to nothing, taking the `frust-perf`
144/// emission (and its strings) with it via LLVM dead-code elimination. Build
145/// with `--features perf-trace` (what a debug/profile build does) to restore
146/// the runtime `FRUST_TRACE` switch documented above.
147#[cfg(not(feature = "perf-trace"))]
148#[inline]
149pub fn enabled() -> bool {
150 false
151}
152
153/// Reads the runtime `FRUST_TRACE` env var, isolated into its own
154/// function so [`enabled`]'s caching is the only thing that touches the
155/// process environment — [`trace_switch`] itself stays a pure, directly
156/// unit-testable function. Compiled only under `perf-trace` (the only caller,
157/// [`enabled`]'s feature-on arm, is too).
158#[cfg(feature = "perf-trace")]
159fn runtime_trace_var() -> Option<String> {
160 std::env::var("FRUST_TRACE").ok()
161}
162
163/// The pure decision [`enabled`] caches: non-empty and not the literal
164/// string `"0"` counts as "set" for either the compile-time or runtime
165/// value; either source being set is enough. Compiled only under `perf-trace`.
166#[cfg(feature = "perf-trace")]
167fn trace_switch(compile_time: Option<&str>, runtime: Option<&str>) -> bool {
168 fn is_set_non_zero(value: Option<&str>) -> bool {
169 matches!(value, Some(v) if v != "0")
170 }
171 is_set_non_zero(compile_time) || is_set_non_zero(runtime)
172}
173
174/// The process-wide raw-per-frame-export switch, cached after
175/// the first call — parsed exactly the same compile-time-or-runtime way as
176/// [`enabled`] (via the same [`trace_switch`] decision), but reading
177/// `FRUST_TRACE_RAW` instead of `FRUST_TRACE`. This is a **second dial**,
178/// not a replacement: `FRUST_TRACE_RAW` being set implies nothing on its own
179/// — [`FrameStats::record`]'s raw per-frame line only fires when [`enabled`]
180/// is *also* true (a benchmark harness sets both `FRUST_TRACE=1` and
181/// `FRUST_TRACE_RAW=1`; see [`FrameStats::new`]).
182#[cfg(feature = "perf-trace")]
183pub fn raw_enabled() -> bool {
184 static RAW_ENABLED: OnceLock<bool> = OnceLock::new();
185 *RAW_ENABLED.get_or_init(|| {
186 trace_switch(
187 option_env!("FRUST_TRACE_RAW"),
188 runtime_trace_raw_var().as_deref(),
189 )
190 })
191}
192
193/// The `perf-trace` feature is off: the raw-per-frame dial is compiled out
194/// alongside [`enabled`], so it is a compile-time `false` constant (see
195/// [`enabled`]'s feature-off arm for the DCE rationale).
196#[cfg(not(feature = "perf-trace"))]
197#[inline]
198pub fn raw_enabled() -> bool {
199 false
200}
201
202/// Reads the runtime `FRUST_TRACE_RAW` env var, isolated for the same reason
203/// [`runtime_trace_var`] is. Compiled only under `perf-trace`.
204#[cfg(feature = "perf-trace")]
205fn runtime_trace_raw_var() -> Option<String> {
206 std::env::var("FRUST_TRACE_RAW").ok()
207}
208
209// ---------------------------------------------------------------------
210// FrameStats
211// ---------------------------------------------------------------------
212
213/// One frame's measured pass durations, as recorded by a shell's frame
214/// callback (`AndroidAppHandle::frame` / `frust_render_frame` /
215/// desktop's `RedrawRequested` handler — see `docs/ARCHITECTURE.md`'s Frame
216/// pipeline). `skipped` is set by the mobile dirty-gate for a
217/// frame whose passes never ran; its pass durations are `Duration::ZERO` in
218/// that case and it is excluded from the percentile computation in
219/// [`FrameStats::summary`] (see that method's docs) while still counting
220/// toward `total_frames`/`skipped_frames`.
221#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
222pub struct FramePasses {
223 pub rebuild: Duration,
224 pub layout: Duration,
225 pub paint: Duration,
226 /// GPU/CPU encode cost — the [`SurfaceRenderer::encode`] span
227 /// (`vello` encode + `render_to_texture`, or the CPU rasterize+upload),
228 /// with no swapchain-acquire wait folded in. Split out from the old
229 /// combined `encode_present` so encode work and the vsync/
230 /// present wait are separately attributable — the number the
231 /// render-thread-split GO/NO-GO decision is made on.
232 ///
233 /// [`SurfaceRenderer::encode`]: https://docs.rs/frust-render
234 pub encode: Duration,
235 /// Swapchain-**acquire** cost — the [`SurfaceRenderer::acquire`] span,
236 /// dominated by the blocking vsync wait (per the surface's present mode).
237 /// Split out from the old combined `present` so the blocking
238 /// vsync wait is attributable separately from the blit/submit work below —
239 /// the S5 GPU-saturation-vs-blit-cost question. `acquire + submit` equals the
240 /// old v2 `present` span, so cross-baseline math is unchanged.
241 ///
242 /// [`SurfaceRenderer::acquire`]: https://docs.rs/frust-render
243 pub acquire: Duration,
244 /// Blit + queue-submit + present cost — the [`SurfaceRenderer::submit`]
245 /// span, the GPU/driver work after the swapchain texture is acquired. See
246 /// [`Self::acquire`] for the split rationale.
247 ///
248 /// [`SurfaceRenderer::submit`]: https://docs.rs/frust-render
249 pub submit: Duration,
250 pub skipped: bool,
251 /// This frame's real GPU time per pass, when the renderer measured it —
252 /// see [`GpuPasses`]. `None` is the ordinary case and is what the raw line
253 /// reports as `gpu_q=0`.
254 ///
255 /// Deliberately outside [`Self::total`]: GPU passes run *concurrently*
256 /// with the CPU spans above, so adding them would double-count the frame.
257 /// It is also not carried by [`RenderSpans`] — a shell attaches it with
258 /// [`Self::with_gpu`] after folding its two measured halves together,
259 /// which keeps the split's own reassembly about the spans it measured.
260 pub gpu: Option<GpuPasses>,
261}
262
263/// One frame's real GPU time, split by the spans the frust-owned render engine
264/// names — the counterpart of the CPU spans in [`FramePasses`], measured on the
265/// GPU's own clock rather than inferred from CPU wall time around a submit.
266///
267/// Produced only in a build whose device asked for GPU timestamps; every
268/// other frame carries `None` and reports `gpu_q=0`.
269/// A span may legitimately read zero — a frame with no off-screen layer does no
270/// composite work — so a zero is a measurement, not a gap.
271#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
272pub struct GpuPasses {
273 /// Work recorded ahead of the frame's own passes (the glyph-atlas replay).
274 pub prepass: Duration,
275 /// The frame's own surface passes: clear, opaque strips, alpha strips, and
276 /// the hole punch.
277 pub main: Duration,
278 /// Off-screen layer pages and filter passes.
279 pub composite: Duration,
280 /// The present-side conversion or blit into the swapchain.
281 pub blit: Duration,
282}
283
284impl GpuPasses {
285 /// The sum of the four spans — the frame's *attributed* GPU pass time.
286 ///
287 /// Queue and driver gaps between passes belong to no pass and are not
288 /// folded in, so this is a lower bound on the frame's whole GPU cost
289 /// rather than an estimate of it.
290 pub fn total(&self) -> Duration {
291 self.prepass
292 .saturating_add(self.main)
293 .saturating_add(self.composite)
294 .saturating_add(self.blit)
295 }
296}
297
298impl FramePasses {
299 /// The sum of all six pass durations — the frame's total wall time.
300 ///
301 /// The GPU spans in [`Self::gpu`] are deliberately excluded; see that
302 /// field.
303 pub fn total(&self) -> Duration {
304 self.rebuild + self.layout + self.paint + self.encode + self.acquire + self.submit
305 }
306
307 /// Attaches this frame's measured GPU pass times.
308 ///
309 /// A builder rather than a field on [`RenderSpans`]: every shell already
310 /// builds its `RenderSpans` by struct literal, and the GPU reading is
311 /// optional per frame and per tier, so `FramePasses::from_split(ui,
312 /// render).with_gpu(gpu)` adds it without touching the spans a shell
313 /// measured itself.
314 #[must_use]
315 pub fn with_gpu(mut self, gpu: GpuPasses) -> Self {
316 self.gpu = Some(gpu);
317 self
318 }
319
320 /// Recombine a render-thread-split frame's two half-measurements into the
321 /// one [`FramePasses`] the single emitter records.
322 ///
323 /// In the render-thread split the UI thread measures
324 /// `rebuild`/`layout`/`paint` ([`UiSpans`]) while the render thread measures
325 /// `encode`/`acquire`/`submit` ([`RenderSpans`]); the UI half rides across
326 /// the scene-handoff channel
327 /// ([`SceneFrame`](crate::render_split::SceneFrame)) so the render thread —
328 /// the **single emitter** — can fold both halves into one frame record.
329 /// This is a pure reassembly of the *existing* six fields: it changes no
330 /// wire format (the raw v3 line [`format_raw_frame_line`] emits is byte-for-
331 /// byte identical to a single-thread frame's), it only moves *where* each
332 /// span is measured. The `skipped` flag comes from the UI half (the frame
333 /// gate is UI-side — see [`crate::frame_gate`]).
334 pub fn from_split(ui: UiSpans, render: RenderSpans) -> Self {
335 Self {
336 rebuild: ui.rebuild,
337 layout: ui.layout,
338 paint: ui.paint,
339 encode: render.encode,
340 acquire: render.acquire,
341 submit: render.submit,
342 skipped: ui.skipped,
343 // Not a measured span either half carries: the render thread reads
344 // it off the renderer after the fact and attaches it with
345 // [`FramePasses::with_gpu`].
346 gpu: None,
347 }
348 }
349}
350
351/// The UI-thread half of a render-thread-split frame's timing: the
352/// `rebuild`/`layout`/`paint` spans measured on the UI thread,
353/// plus the frame gate's `skipped` verdict (the gate stays UI-side — see
354/// [`crate::frame_gate`]). Rides the scene-handoff channel across to the
355/// render thread, which folds it together with its own [`RenderSpans`] via
356/// [`FramePasses::from_split`] and records the result through the one emitter.
357#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
358pub struct UiSpans {
359 pub rebuild: Duration,
360 pub layout: Duration,
361 pub paint: Duration,
362 /// The frame gate's skip verdict (a skipped frame carries all-zero spans);
363 /// preserved through [`FramePasses::from_split`] into the recorded frame.
364 pub skipped: bool,
365}
366
367/// The render-thread half of a render-thread-split frame's timing: the
368/// `encode`/`acquire`/`submit` spans measured on the render thread,
369/// folded together with the UI thread's [`UiSpans`] via
370/// [`FramePasses::from_split`]. See [`FramePasses::encode`]/[`FramePasses::acquire`]/
371/// [`FramePasses::submit`] for each span's exact boundary (the v3 attribution
372/// this split preserves unchanged).
373#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]
374pub struct RenderSpans {
375 pub encode: Duration,
376 pub acquire: Duration,
377 pub submit: Duration,
378}
379
380/// A rolling summary over [`FrameStats`]'s current ring-buffer window plus
381/// the lifetime running counters — the shape [`FrameStats::emit_log`]'s log
382/// line reports and tests assert against.
383#[derive(Debug, Clone, Copy, PartialEq, Eq)]
384pub struct FrameSummary {
385 /// Frames currently held in the ring buffer (`<= RING_CAPACITY`), i.e.
386 /// how many samples the percentiles below are computed over.
387 pub frame_count: usize,
388 pub total_p50: Duration,
389 pub total_p95: Duration,
390 pub total_p99: Duration,
391 pub rebuild_p95: Duration,
392 pub layout_p95: Duration,
393 pub paint_p95: Duration,
394 /// p95 of the [`FramePasses::encode`] span (GPU/CPU encode, no vsync wait).
395 pub encode_p95: Duration,
396 /// p95 of the [`FramePasses::acquire`] span (swapchain-acquire/vsync wait).
397 pub acquire_p95: Duration,
398 /// p95 of the [`FramePasses::submit`] span (blit + queue-submit + present).
399 pub submit_p95: Duration,
400 /// Lifetime count of frames whose total exceeded [`BUDGET_60HZ`]
401 /// (16.6ms) — a running total, not windowed to the ring buffer.
402 pub over_60hz_budget: u64,
403 /// Lifetime count of frames whose total exceeded [`BUDGET_120HZ`]
404 /// (8.3ms) — a running total, not windowed to the ring buffer.
405 pub over_120hz_budget: u64,
406 /// Lifetime count of frames recorded with `FramePasses::skipped == true`
407 /// — a running total, not windowed to the ring buffer.
408 pub skipped_frames: u64,
409}
410
411/// Per-shell frame-timing recorder: a ring buffer of
412/// the last [`RING_CAPACITY`] frames' [`FramePasses`] plus lifetime running
413/// counters, aggregated on demand by [`FrameStats::summary`] and rate-limit
414/// logged by [`FrameStats::should_emit`]/[`FrameStats::emit_log`].
415///
416/// The Android, iOS, and desktop shells each construct one of these — a
417/// standalone, host-testable recorder.
418#[derive(Debug)]
419pub struct FrameStats {
420 enabled: bool,
421 /// Raw-per-frame-export mode (see [`raw_enabled`]) — always
422 /// `false` when `enabled` is `false` (the two-dial contract
423 /// [`Self::with_capacity_enabled_and_raw`] enforces). Only *read* by the
424 /// `perf-trace`-gated raw emission path in [`Self::record`], so it is dead
425 /// in a release-lean (feature-off) build (still written by constructors).
426 #[cfg_attr(not(feature = "perf-trace"), allow(dead_code))]
427 raw: bool,
428 /// Reused, cleared-and-rewritten each call so [`Self::record`]'s raw
429 /// line never grows the allocation once its capacity settles —
430 /// formatting only, no per-frame allocation growth (see
431 /// `docs/CODE_STANDARDS.md`'s Instrumentation conventions). Only ever
432 /// *read* by the `perf-trace`-gated raw emission path, so it is dead in a
433 /// release-lean (feature-off) build — the field stays (constructors still
434 /// size it) but the lint is silenced there.
435 #[cfg_attr(not(feature = "perf-trace"), allow(dead_code))]
436 raw_buf: String,
437 ring_capacity: usize,
438 ring: VecDeque<FramePasses>,
439 total_frames: u64,
440 skipped_frames: u64,
441 over_60hz: u64,
442 over_120hz: u64,
443 /// Accumulated frame total time since the last `emit_log` (or since
444 /// construction) — how [`Self::should_emit`] rate-limits without
445 /// needing its own clock (see [`EMIT_INTERVAL`]'s docs).
446 since_last_emit: Duration,
447 /// Test-only mirror of every scenario-marker line [`Self::record`] has
448 /// logged (and the queue-overflow notice beside them, when one was
449 /// emitted), in emission order — the seam the marker tests assert
450 /// against so they never have to install a global `log` sink (which
451 /// would make them order-dependent on every other test). Absent
452 /// from any non-test build, so it costs a shipped binary nothing, and
453 /// absent from a feature-off test build too — with the emission itself
454 /// compiled out there, a buffer of emitted lines would be a field
455 /// nothing ever writes.
456 #[cfg(all(test, feature = "perf-trace"))]
457 marker_log: Vec<String>,
458}
459
460impl FrameStats {
461 /// A recorder honoring the process-wide [`enabled`]/[`raw_enabled`]
462 /// switches — what every shell constructs.
463 pub fn new() -> Self {
464 let is_enabled = enabled();
465 Self::with_capacity_enabled_and_raw(RING_CAPACITY, is_enabled, is_enabled && raw_enabled())
466 }
467
468 /// Test/advanced seam: construct with an explicit enabled flag,
469 /// bypassing [`enabled`]'s cache. Every shell should prefer [`Self::new`];
470 /// this exists so tests can exercise both the enabled and disabled paths
471 /// deterministically in the same process (`enabled()`'s `OnceLock` can
472 /// only ever resolve once per process). Raw-export mode is left off; use
473 /// [`Self::with_capacity_enabled_and_raw`] to exercise it.
474 pub fn new_enabled(is_enabled: bool) -> Self {
475 Self::with_capacity_enabled(RING_CAPACITY, is_enabled)
476 }
477
478 /// Test seam: a smaller ring capacity, so eviction behavior is
479 /// exercisable without pushing [`RING_CAPACITY`] frames. Raw-export mode
480 /// is left off; use [`Self::with_capacity_enabled_and_raw`] to exercise
481 /// it.
482 pub fn with_capacity_enabled(capacity: usize, is_enabled: bool) -> Self {
483 Self::with_capacity_enabled_and_raw(capacity, is_enabled, false)
484 }
485
486 /// Test/advanced seam: construct with explicit enabled and raw-export
487 /// flags, bypassing both [`enabled`]'s and [`raw_enabled`]'s caches (see
488 /// [`Self::new_enabled`]'s docs for why a test needs to bypass the
489 /// cache). `is_raw` only takes effect when `is_enabled` is also `true` —
490 /// the same two-dial contract [`Self::new`] applies to the real
491 /// `FRUST_TRACE`/`FRUST_TRACE_RAW` switches.
492 pub fn with_capacity_enabled_and_raw(capacity: usize, is_enabled: bool, is_raw: bool) -> Self {
493 let raw = is_enabled && is_raw;
494 Self {
495 enabled: is_enabled,
496 raw,
497 // Disabled: never reserve — nothing will ever be formatted into
498 // it, mirroring the ring buffer's own no-reserve-when-disabled
499 // reasoning below.
500 // Sized for the longest line the formatter writes — the v4 shape
501 // with every `gpu_*_us` field present — so even a GPU-timed frame
502 // never grows the allocation after the first one.
503 raw_buf: if raw {
504 String::with_capacity(288)
505 } else {
506 String::new()
507 },
508 ring_capacity: capacity,
509 // Disabled: never reserve — nothing will ever be pushed, so
510 // "allocates nothing after init" holds
511 // trivially for the whole recorder's lifetime, not just after
512 // construction.
513 ring: if is_enabled {
514 VecDeque::with_capacity(capacity)
515 } else {
516 VecDeque::new()
517 },
518 total_frames: 0,
519 skipped_frames: 0,
520 over_60hz: 0,
521 over_120hz: 0,
522 since_last_emit: Duration::ZERO,
523 #[cfg(all(test, feature = "perf-trace"))]
524 marker_log: Vec::new(),
525 }
526 }
527
528 /// Record one frame's pass durations. A cheap no-op (no allocation, no
529 /// clock read — the caller already measured `passes`) when disabled.
530 /// When raw-export mode is on (see [`raw_enabled`]), additionally
531 /// formats and logs one `frust-perf raw` line for this frame — a skipped
532 /// frame (`passes.skipped`) still gets a line (all-zero pass durations,
533 /// `skipped=1`) so a harness can compute honest frame pacing across the
534 /// mobile frame gate.
535 ///
536 /// This is also the single point where a benchmark scenario marker is
537 /// emitted: every marker this frame carries — staged on this thread by
538 /// the scene handoff, or raised on this thread when there is no render
539 /// thread — is logged, in the order it was raised, stamped with **this**
540 /// frame's `n` and immediately ahead of this frame's own `frust-perf
541 /// raw` line, so a marker's frame number names the recorded frame that
542 /// actually carried it, not a guess made on whichever thread raised it
543 /// (see [`mark_scenario_start`]).
544 pub fn record(&mut self, passes: FramePasses) {
545 // Devtools frame stats fan out BEFORE the perf switch below: a devtools
546 // client subscribing to them is its own opt-in, independent of
547 // `FRUST_TRACE`. This is also the one site every shell's frame pipeline
548 // already funnels through — desktop, Android and iOS, inline and
549 // render-thread-split alike — so the publish has no per-shell copy to
550 // drift. Non-blocking, and one relaxed atomic load with no service
551 // running (see `crate::devtools::publish_frame`).
552 #[cfg(feature = "devtools")]
553 crate::devtools::publish_frame(&passes);
554
555 if !self.enabled {
556 return;
557 }
558
559 self.total_frames += 1;
560
561 // Ahead of everything else this frame emits (the `frust-perf raw`
562 // line below): a window's `start n=k` must precede frame k's own raw
563 // line in the log, and the harness's half-open `[start_n, end_n)`
564 // rule reads the numbers, not the positions.
565 #[cfg(feature = "perf-trace")]
566 self.emit_scenario_markers();
567
568 if passes.skipped {
569 self.skipped_frames += 1;
570 }
571
572 let total = passes.total();
573 if total > BUDGET_60HZ {
574 self.over_60hz += 1;
575 }
576 if total > BUDGET_120HZ {
577 self.over_120hz += 1;
578 }
579 self.since_last_emit += total;
580
581 #[cfg(feature = "perf-trace")]
582 if self.raw {
583 format_raw_frame_line(&mut self.raw_buf, self.total_frames, &passes);
584 log::info!("{}", self.raw_buf);
585 }
586
587 if self.ring.len() == self.ring_capacity {
588 self.ring.pop_front();
589 }
590 self.ring.push_back(passes);
591 }
592
593 /// Emit every scenario marker riding this frame, stamped with the frame
594 /// number [`Self::record`] just assigned it.
595 ///
596 /// Two sources, both belonging to **this** thread — which is what makes
597 /// the split and the inline executor one rule rather than two:
598 ///
599 /// - [`STAGED`] — markers put there by [`stage_markers`] when the render
600 /// channel handed this thread the very frame now being recorded. The
601 /// render-thread-split leg.
602 /// - [`PENDING`] — this thread's own raise queue. The inline (no render
603 /// thread) executor's leg, where the thread that raises a marker is the
604 /// same one that records the frame. On a render thread this is
605 /// *structurally* empty: a render thread raises no marker of its own,
606 /// and another thread's queue is unreachable from here, so nothing can
607 /// steal a marker still being built on the UI thread.
608 ///
609 /// Both drains are `is_empty` fast paths: a frame carrying no marker
610 /// allocates nothing.
611 ///
612 /// A marker line's shape is fixed (see [`format_scenario_marker`]); the
613 /// only extra line this can emit is the queue-overflow notice
614 /// [`format_marker_overflow_line`] writes, and only for a frame whose
615 /// markers arrived with a nonzero drop count (see [`MARKER_QUEUE_CAP`]).
616 #[cfg(feature = "perf-trace")]
617 fn emit_scenario_markers(&mut self) {
618 let mut markers = take_staged_markers();
619 markers.absorb(take_pending_markers());
620 for marker in markers.markers {
621 let line = format_scenario_marker(marker.edge, &marker.name, self.total_frames);
622 log::info!("{line}");
623 #[cfg(test)]
624 self.marker_log.push(line);
625 }
626 if markers.dropped > 0 {
627 let line = format_marker_overflow_line(self.total_frames, markers.dropped);
628 log::warn!("{line}");
629 #[cfg(test)]
630 self.marker_log.push(line);
631 }
632 }
633
634 /// Test-only view of the marker lines [`Self::record`] has emitted so
635 /// far, in order — see [`Self::marker_log`]'s docs.
636 /// `pub(crate)` so `render_split`'s channel tests can assert the lines a
637 /// frame carried across the handoff.
638 #[cfg(all(test, feature = "perf-trace"))]
639 pub(crate) fn marker_log(&self) -> &[String] {
640 &self.marker_log
641 }
642
643 /// Total frames ever recorded (including skipped), regardless of the
644 /// ring-buffer window.
645 pub fn total_frames(&self) -> u64 {
646 self.total_frames
647 }
648
649 /// Aggregate the current ring-buffer window plus the lifetime running
650 /// counters into a [`FrameSummary`].
651 ///
652 /// **Percentile semantics**: nearest-rank, computed over only the
653 /// *non-skipped* frames currently in the ring buffer (a skipped frame's
654 /// all-zero pass durations would otherwise silently pull percentiles
655 /// down and misrepresent real frame cost) — for a sorted-ascending
656 /// sample of `n` values, the `p`-th percentile is the value at 1-indexed
657 /// rank `ceil(p * n / 100)`, computed with integer ceiling division
658 /// (`(p * n).div_ceil(100)`) and clamped to `[1, n]`, so no floating-point
659 /// rounding is involved. An empty (or all-skipped) window reports
660 /// `Duration::ZERO` for every percentile field.
661 pub fn summary(&self) -> FrameSummary {
662 let active: Vec<&FramePasses> = self.ring.iter().filter(|p| !p.skipped).collect();
663
664 let mut totals: Vec<Duration> = active.iter().map(|p| p.total()).collect();
665 let mut rebuilds: Vec<Duration> = active.iter().map(|p| p.rebuild).collect();
666 let mut layouts: Vec<Duration> = active.iter().map(|p| p.layout).collect();
667 let mut paints: Vec<Duration> = active.iter().map(|p| p.paint).collect();
668 let mut encodes: Vec<Duration> = active.iter().map(|p| p.encode).collect();
669 let mut acquires: Vec<Duration> = active.iter().map(|p| p.acquire).collect();
670 let mut submits: Vec<Duration> = active.iter().map(|p| p.submit).collect();
671 totals.sort_unstable();
672 rebuilds.sort_unstable();
673 layouts.sort_unstable();
674 paints.sort_unstable();
675 encodes.sort_unstable();
676 acquires.sort_unstable();
677 submits.sort_unstable();
678
679 FrameSummary {
680 frame_count: self.ring.len(),
681 total_p50: nearest_rank_percentile(&totals, 50),
682 total_p95: nearest_rank_percentile(&totals, 95),
683 total_p99: nearest_rank_percentile(&totals, 99),
684 rebuild_p95: nearest_rank_percentile(&rebuilds, 95),
685 layout_p95: nearest_rank_percentile(&layouts, 95),
686 paint_p95: nearest_rank_percentile(&paints, 95),
687 encode_p95: nearest_rank_percentile(&encodes, 95),
688 acquire_p95: nearest_rank_percentile(&acquires, 95),
689 submit_p95: nearest_rank_percentile(&submits, 95),
690 over_60hz_budget: self.over_60hz,
691 over_120hz_budget: self.over_120hz,
692 skipped_frames: self.skipped_frames,
693 }
694 }
695
696 /// Whether at least [`EMIT_INTERVAL`] of frame time has accumulated
697 /// since the last [`Self::emit_log`] (or construction) — the "one line
698 /// every ~2s of frames" rate limit. Always `false` when disabled.
699 pub fn should_emit(&self) -> bool {
700 self.enabled && self.since_last_emit >= EMIT_INTERVAL
701 }
702
703 /// Emit one structured `frust-perf frame ...` line via `log::info!`
704 /// and reset the [`Self::should_emit`] accumulator. A no-op when
705 /// disabled. A shell calls this only when [`Self::should_emit`] is
706 /// `true` (it does not check it itself, so a test can force an emission
707 /// regardless of accumulated time).
708 pub fn emit_log(&mut self) {
709 if !self.enabled {
710 return;
711 }
712 // The `frust-perf frame` line (and the strings it carries) exists only
713 // under `perf-trace`; the accumulator reset below is plain bookkeeping
714 // and stays in every build so [`Self::should_emit`]'s rate limit
715 // behaves identically whether or not the feature is compiled in.
716 #[cfg(feature = "perf-trace")]
717 {
718 let s = self.summary();
719 log::info!(
720 "frust-perf frame n={} total_p50_ms={} total_p95_ms={} total_p99_ms={} \
721 rebuild_p95_ms={} layout_p95_ms={} paint_p95_ms={} encode_p95_ms={} \
722 acquire_p95_ms={} submit_p95_ms={} \
723 over_60hz={} over_120hz={} skipped={} total_frames={}",
724 s.frame_count,
725 s.total_p50.as_millis(),
726 s.total_p95.as_millis(),
727 s.total_p99.as_millis(),
728 s.rebuild_p95.as_millis(),
729 s.layout_p95.as_millis(),
730 s.paint_p95.as_millis(),
731 s.encode_p95.as_millis(),
732 s.acquire_p95.as_millis(),
733 s.submit_p95.as_millis(),
734 s.over_60hz_budget,
735 s.over_120hz_budget,
736 s.skipped_frames,
737 self.total_frames,
738 );
739 }
740 self.since_last_emit = Duration::ZERO;
741 }
742}
743
744impl Default for FrameStats {
745 fn default() -> Self {
746 Self::new()
747 }
748}
749
750/// Nearest-rank percentile over an ascending-sorted sample (see
751/// [`FrameStats::summary`]'s docs for the exact formula). `p` is a whole
752/// percentage (`50`/`95`/`99`); `sorted` must already be ascending.
753fn nearest_rank_percentile(sorted: &[Duration], p: u32) -> Duration {
754 let n = sorted.len() as u32;
755 if n == 0 {
756 return Duration::ZERO;
757 }
758 let rank = (p * n).div_ceil(100);
759 let rank = rank.clamp(1, n);
760 sorted[(rank - 1) as usize]
761}
762
763// ---------------------------------------------------------------------
764// Raw per-frame export + scenario markers
765// ---------------------------------------------------------------------
766
767/// Log-line prefix for [`FrameStats::record`]'s raw per-frame export line —
768/// parallels the `frust-perf frame`/`frust-perf startup` prefixes
769/// [`FrameStats::emit_log`]/[`StartupSpans::emit_log`] already use. A
770/// `frust-perf` string literal, so it compiles only under `perf-trace`
771/// (release-lean builds carry no `frust-perf` bytes).
772#[cfg(feature = "perf-trace")]
773const RAW_FRAME_PREFIX: &str = "frust-perf raw";
774
775/// Formats one `frust-perf raw` line into `buf` (cleared first) for frame
776/// index `n` (1-indexed — [`FrameStats::record`] passes its running
777/// `total_frames` counter, post-increment) and `passes`. Kept separate from
778/// `record`'s logging call so the line shape is directly unit-testable
779/// without a log-capture harness, and so the caller can reuse one
780/// growth-free buffer across every frame instead of formatting a fresh
781/// `String` per call (see `docs/CODE_STANDARDS.md`'s Instrumentation
782/// conventions — formatting only, no allocation growth on the hot path).
783/// Field order: `n`, `total_us`, `rebuild_us`, `layout_us`, `paint_us`,
784/// `encode_us`, `acquire_us`, `submit_us`, `skipped` (`0`/`1`), `gpu_q`
785/// (`0`/`1`), then — only when `gpu_q=1` — `gpu_total_us`, `gpu_prepass_us`,
786/// `gpu_main_us`, `gpu_composite_us`, `gpu_blit_us`. Microsecond resolution so
787/// a sub-millisecond pass still shows nonzero.
788///
789/// **Format v4 (2026-09-01):** real GPU time per pass ([`GpuPasses`]) is
790/// appended after `skipped`, additively — every v3 field keeps its name,
791/// meaning and position, so a v3 parser reads a v4 line unchanged and a v4
792/// parser reads a v3 line as `gpu_q=0`. `gpu_q` states whether this frame
793/// carries a GPU reading at all; the five `gpu_*_us` fields are **omitted
794/// entirely** when it is `0`, rather than written as zeros, so a series with no
795/// GPU timing never produces a column of zeros that reads like a measurement.
796///
797/// **Format v3 (2026-07-22):** the single `present_us` field of v2
798/// was split into separate `acquire_us` + `submit_us` fields (no combined field
799/// is kept); `acquire_us + submit_us` equals the old v2 `present_us` for
800/// cross-baseline math. **Format v2 (2026-07-21):** the single
801/// `encode_present_us` field of v1 was split into `encode_us` + `present_us`.
802/// Any harness parsing this line must handle the current field set; see
803/// `benchmarks/PROTOCOL.md`'s format-change note. Compiled only under
804/// `perf-trace` (it bears the `frust-perf raw` prefix).
805#[cfg(feature = "perf-trace")]
806fn format_raw_frame_line(buf: &mut String, n: u64, passes: &FramePasses) {
807 use std::fmt::Write as _;
808 buf.clear();
809 let _ = write!(
810 buf,
811 "{RAW_FRAME_PREFIX} n={n} total_us={} rebuild_us={} layout_us={} paint_us={} \
812 encode_us={} acquire_us={} submit_us={} skipped={} gpu_q={}",
813 passes.total().as_micros(),
814 passes.rebuild.as_micros(),
815 passes.layout.as_micros(),
816 passes.paint.as_micros(),
817 passes.encode.as_micros(),
818 passes.acquire.as_micros(),
819 passes.submit.as_micros(),
820 u8::from(passes.skipped),
821 u8::from(passes.gpu.is_some()),
822 );
823 if let Some(gpu) = passes.gpu {
824 let _ = write!(
825 buf,
826 " gpu_total_us={} gpu_prepass_us={} gpu_main_us={} gpu_composite_us={} \
827 gpu_blit_us={}",
828 gpu.total().as_micros(),
829 gpu.prepass.as_micros(),
830 gpu.main.as_micros(),
831 gpu.composite.as_micros(),
832 gpu.blit.as_micros(),
833 );
834 }
835}
836
837/// Which edge of a benchmark scenario window [`mark_scenario_start`]/
838/// [`mark_scenario_end`] raises. Compiled only under `perf-trace`, like
839/// every other piece of the marker route: a release-lean build carries
840/// neither the queues below nor the `bench-scenario-*` string literals this
841/// maps to.
842#[cfg(feature = "perf-trace")]
843#[derive(Debug, Clone, Copy, PartialEq, Eq)]
844enum MarkerEdge {
845 Start,
846 End,
847}
848
849#[cfg(feature = "perf-trace")]
850impl MarkerEdge {
851 const fn prefix(self) -> &'static str {
852 match self {
853 MarkerEdge::Start => "bench-scenario-start",
854 MarkerEdge::End => "bench-scenario-end",
855 }
856 }
857}
858
859/// One raised-but-not-yet-emitted scenario-window edge: what
860/// [`mark_scenario_start`]/[`mark_scenario_end`] queue and
861/// [`FrameStats::record`] eventually logs, stamped with the frame that
862/// carried it.
863///
864/// Deliberately opaque and `pub(crate)`: the route it travels
865/// ([`take_pending_markers`] → [`stage_markers`]) is this crate's own
866/// plumbing, so nothing outside the crate can read the edge, rewrite the
867/// name, or inject a marker that was never raised — the emitted line's shape
868/// stays this module's business alone. `Box<str>` rather than `String`: a
869/// marker name is never appended to after it is raised.
870#[cfg(feature = "perf-trace")]
871#[derive(Debug, Clone, PartialEq, Eq)]
872pub(crate) struct ScenarioMarker {
873 edge: MarkerEdge,
874 name: Box<str>,
875}
876
877/// The most markers any one leg of the route ([`PENDING`], [`STAGED`],
878/// [`crate::render_split`]'s inbox queue) holds at once.
879///
880/// A leg only grows while markers are raised faster than frames are
881/// recorded, which a benchmark process (two markers per scenario operation,
882/// about one operation per frame) never does for long; a leg that reaches
883/// this cap therefore means something is already wrong — markers raised on a
884/// thread that hands no frame off, or a render thread that has stopped
885/// recording — and the honest response is to bound the memory rather than
886/// accumulate forever. On overflow the **oldest** marker is dropped (a live
887/// window needs the newest edges) and the drop is counted; the count travels
888/// with the batch and [`FrameStats::record`] reports it on the next frame
889/// that carries markers, as its own `frust-perf marker-overflow` line —
890/// never folded into a `bench-scenario-*` line, whose shape is a parsed wire
891/// format (`benchmarks/PROTOCOL.md` §7).
892#[cfg(feature = "perf-trace")]
893pub(crate) const MARKER_QUEUE_CAP: usize = 256;
894
895/// One leg of the marker route: markers in raise order, plus how many were
896/// dropped to keep the leg inside [`MARKER_QUEUE_CAP`].
897///
898/// The drop count rides with the markers ([`Self::absorb`] sums it) rather
899/// than living in a counter of its own, so a drop that happened on the UI
900/// thread is still reported by the render thread that records the frame
901/// those markers landed on.
902#[cfg(feature = "perf-trace")]
903#[derive(Debug, Default)]
904pub(crate) struct MarkerQueue {
905 markers: VecDeque<ScenarioMarker>,
906 dropped: u64,
907}
908
909#[cfg(feature = "perf-trace")]
910impl MarkerQueue {
911 /// An empty queue that has allocated nothing — `const` so the
912 /// thread-locals below initialize with no lazy first-use branch.
913 pub(crate) const fn new() -> Self {
914 Self {
915 markers: VecDeque::new(),
916 dropped: 0,
917 }
918 }
919
920 /// Nothing to carry: no markers **and** no drop count. A queue holding
921 /// only a drop count cannot happen today (a drop happens on a push,
922 /// which leaves the pushed marker behind), but treating the count as
923 /// payload keeps a caller from stranding one behind an emptiness fast
924 /// path.
925 pub(crate) fn is_empty(&self) -> bool {
926 self.markers.is_empty() && self.dropped == 0
927 }
928
929 /// Queue one marker, dropping the oldest if that would exceed
930 /// [`MARKER_QUEUE_CAP`].
931 fn push(&mut self, marker: ScenarioMarker) {
932 if self.markers.len() >= MARKER_QUEUE_CAP {
933 self.markers.pop_front();
934 self.dropped = self.dropped.saturating_add(1);
935 }
936 self.markers.push_back(marker);
937 }
938
939 /// Move `other`'s markers (oldest first) and its drop count into this
940 /// queue, enforcing the cap again on the way in.
941 pub(crate) fn absorb(&mut self, other: MarkerQueue) {
942 self.dropped = self.dropped.saturating_add(other.dropped);
943 for marker in other.markers {
944 self.push(marker);
945 }
946 }
947
948 /// Take everything queued here, leaving this queue empty.
949 pub(crate) fn take(&mut self) -> MarkerQueue {
950 std::mem::take(self)
951 }
952
953 /// Forget everything queued here, drop count included — for a leg whose
954 /// markers no frame will ever name.
955 pub(crate) fn clear(&mut self) {
956 self.markers.clear();
957 self.dropped = 0;
958 }
959}
960
961#[cfg(feature = "perf-trace")]
962thread_local! {
963 /// The markers **this** thread has raised and not yet handed on:
964 /// [`mark_scenario_start`]/[`mark_scenario_end`] push here, nothing else
965 /// does.
966 ///
967 /// Per-thread rather than process-wide, which is what collapses the two
968 /// executors into one rule instead of a shared queue plus a flag
969 /// deciding who owns it:
970 ///
971 /// - **render-thread split** — the UI thread raises markers and is also
972 /// the thread that calls [`RenderSender::send_scene`], which moves this
973 /// queue into the inbox so the markers travel with that handoff. The
974 /// render thread's own copy of this queue is never pushed to, so
975 /// [`FrameStats::record`] draining it over there can steal nothing.
976 /// - **inline** (no render thread) — one thread raises and records, so
977 /// [`FrameStats::record`] drains this queue directly, for the frame it
978 /// is recording right now.
979 ///
980 /// Bounded at [`MARKER_QUEUE_CAP`].
981 ///
982 /// [`RenderSender::send_scene`]: crate::render_split::RenderSender::send_scene
983 static PENDING: RefCell<MarkerQueue> = const { RefCell::new(MarkerQueue::new()) };
984
985 /// The markers handed to *this* thread for the very next frame it
986 /// records — the render thread's leg of the route. [`stage_markers`]
987 /// appends, [`FrameStats::record`] drains. Per-thread for the same reason
988 /// [`PENDING`] is: the draining thread is by construction the one that
989 /// took the batch out of the inbox and is about to render and record it,
990 /// so no lock is needed and no other thread's frame can pick these up by
991 /// accident. Bounded at [`MARKER_QUEUE_CAP`].
992 static STAGED: RefCell<MarkerQueue> = const { RefCell::new(MarkerQueue::new()) };
993}
994
995/// Take the calling thread's raised-but-not-handed-on markers, leaving its
996/// queue empty — [`RenderSender::send_scene`] calls this to move them into
997/// the inbox beside the scene they belong to, and calls it again (discarding
998/// the result) on its dead-receiver path, so a queue no frame can ever name
999/// is not left growing.
1000///
1001/// [`markers_enabled`] first: this runs on every frame of every split shell,
1002/// including in a `perf-trace` build running with `FRUST_TRACE` off, so the
1003/// disabled case must cost one cached bool read and no thread-local access
1004/// at all.
1005///
1006/// [`RenderSender::send_scene`]: crate::render_split::RenderSender::send_scene
1007#[cfg(feature = "perf-trace")]
1008#[inline]
1009pub(crate) fn take_pending_markers() -> MarkerQueue {
1010 if !markers_enabled() {
1011 return MarkerQueue::new();
1012 }
1013 PENDING.with(|pending| pending.borrow_mut().take())
1014}
1015
1016/// Hand markers to the calling thread's next recorded frame, appending to
1017/// whatever is already staged there (see [`STAGED`]). Called by the render
1018/// thread as it takes a scene out of the inbox; the frame it records next is
1019/// the one that scene belongs to.
1020///
1021/// **Accepted best-effort edge**: a batch taken but then *not* rendered (the
1022/// render loop's [`RenderPhase`] cannot render it — a paused or
1023/// surface-less phase) records no frame, so its markers stay staged and
1024/// attach to the next frame this thread does record. A scenario window
1025/// bracketed across such a gap is therefore attributed to the first frame
1026/// that really rendered after it, which is the closest honest answer
1027/// available without inventing a frame that was never drawn.
1028///
1029/// [`RenderPhase`]: crate::render_split::RenderPhase
1030#[cfg(feature = "perf-trace")]
1031pub(crate) fn stage_markers(markers: MarkerQueue) {
1032 if markers.is_empty() {
1033 return;
1034 }
1035 STAGED.with(|staged| staged.borrow_mut().absorb(markers));
1036}
1037
1038/// Take this thread's staged markers, leaving the slot empty. `is_empty`
1039/// fast path first: the overwhelmingly common frame carries no marker and
1040/// must not allocate.
1041#[cfg(feature = "perf-trace")]
1042fn take_staged_markers() -> MarkerQueue {
1043 STAGED.with(|staged| {
1044 let mut staged = staged.borrow_mut();
1045 if staged.is_empty() {
1046 MarkerQueue::new()
1047 } else {
1048 staged.take()
1049 }
1050 })
1051}
1052
1053#[cfg(all(test, feature = "perf-trace"))]
1054thread_local! {
1055 /// Test-only override of [`markers_enabled`] for the **calling** thread:
1056 /// [`enabled`] caches a process environment read in a `OnceLock` and can
1057 /// never be flipped back, so a test that needs a marker actually queued
1058 /// sets this instead of relaxing production gating.
1059 ///
1060 /// Per-thread like the queues it gates, which is what lets marker tests
1061 /// run beside every other test in the process with no lock at all: a
1062 /// two-thread test arms it on each thread that raises markers (see
1063 /// [`marker_test_guard`]).
1064 static MARKERS_FORCE_ENABLED: Cell<bool> = const { Cell::new(false) };
1065}
1066
1067/// The RAII handle [`marker_test_guard`] returns: disarms the force switch
1068/// and empties this thread's queues on drop, so one test's leftovers can
1069/// never leak into the next test that runs on the same thread.
1070#[cfg(all(test, feature = "perf-trace"))]
1071pub(crate) struct MarkerTestGuard {
1072 _private: (),
1073}
1074
1075#[cfg(all(test, feature = "perf-trace"))]
1076impl Drop for MarkerTestGuard {
1077 fn drop(&mut self) {
1078 MARKERS_FORCE_ENABLED.with(|forced| forced.set(false));
1079 reset_marker_route();
1080 }
1081}
1082
1083/// Empty both of the calling thread's marker queues.
1084#[cfg(all(test, feature = "perf-trace"))]
1085fn reset_marker_route() {
1086 PENDING.with(|pending| pending.borrow_mut().clear());
1087 STAGED.with(|staged| staged.borrow_mut().clear());
1088}
1089
1090/// Start this thread's use of the marker route from a pristine queue pair
1091/// and (when `force_enabled`) with markers queueing as though `FRUST_TRACE`
1092/// were set. `pub(crate)` because `render_split`'s channel tests drive the
1093/// same route from the other end.
1094///
1095/// There is no lock: every piece of state this arms belongs to the calling
1096/// thread, so two marker tests running in parallel cannot see each other's
1097/// queues. A test that spawns its own UI thread must call this on **that**
1098/// thread too — the force switch no more crosses a thread boundary than a
1099/// queue does.
1100#[cfg(all(test, feature = "perf-trace"))]
1101pub(crate) fn marker_test_guard(force_enabled: bool) -> MarkerTestGuard {
1102 reset_marker_route();
1103 MARKERS_FORCE_ENABLED.with(|forced| forced.set(force_enabled));
1104 MarkerTestGuard { _private: () }
1105}
1106
1107/// Whether a raised marker is queued at all. The one-dial gate
1108/// ([`enabled`], not [`enabled`]-and-[`raw_enabled`]): a marker is emitted
1109/// by [`FrameStats::record`] itself, which runs whenever perf is on, so
1110/// tying markers to the raw-export dial would mean a scenario window that
1111/// exists in one capture and silently not in another.
1112#[cfg(feature = "perf-trace")]
1113#[inline]
1114fn markers_enabled() -> bool {
1115 #[cfg(test)]
1116 if MARKERS_FORCE_ENABLED.with(Cell::get) {
1117 return true;
1118 }
1119 enabled()
1120}
1121
1122/// Queue one marker onto the calling thread's [`PENDING`] queue — the single
1123/// body behind both [`mark_scenario_start`] and [`mark_scenario_end`], so the
1124/// two edges can never drift apart.
1125#[cfg(feature = "perf-trace")]
1126fn push_marker(edge: MarkerEdge, name: &str) {
1127 if !markers_enabled() {
1128 return;
1129 }
1130 PENDING.with(|pending| {
1131 pending.borrow_mut().push(ScenarioMarker {
1132 edge,
1133 name: name.into(),
1134 });
1135 });
1136}
1137
1138/// Formats one scenario-marker line — separated from the emission call for
1139/// the same directly-unit-testable reason [`format_raw_frame_line`] is.
1140/// Compiled only under `perf-trace` (it emits the `bench-scenario-*`
1141/// prefixes).
1142///
1143/// **Shape (2026-09-06):** `<prefix> n=<frame> <name>`, where `frame` is the
1144/// 1-indexed counter of the frame that carried this marker through the
1145/// pipeline — the very same counter [`format_raw_frame_line`] writes as a
1146/// raw line's own `n=`, because both are stamped by the same
1147/// [`FrameStats::record`] call. There is no config toggle back to the older
1148/// name-only `<prefix> <name>` shape; a series captured before this change
1149/// is still name-only and a harness parsing it falls back to log-position
1150/// bracketing (`benchmarks/harness/stats.py`'s `slice_scenario`).
1151#[cfg(feature = "perf-trace")]
1152fn format_scenario_marker(edge: MarkerEdge, name: &str, frame: u64) -> String {
1153 format!("{} n={frame} {name}", edge.prefix())
1154}
1155
1156/// Prefix of the queue-overflow notice (see [`MARKER_QUEUE_CAP`]).
1157/// Deliberately neither the `frust-perf raw`/`frust-perf op`/`frust-perf
1158/// plugin` prefix nor a `bench-scenario-*` one, so a harness scanning the
1159/// same log stream (`benchmarks/harness/stats.py`) reads this as an
1160/// unrelated line rather than as a malformed record of a shape it parses.
1161#[cfg(feature = "perf-trace")]
1162const MARKER_OVERFLOW_PREFIX: &str = "frust-perf marker-overflow";
1163
1164/// Formats the notice that `dropped` markers were discarded to keep a route
1165/// leg inside [`MARKER_QUEUE_CAP`], stamped with the frame whose markers
1166/// carried the count in. Kept out of the `bench-scenario-*` line itself
1167/// because that line's `<prefix> n=<u64> <name>` shape is a parsed wire
1168/// format: `stats.py`'s `parse_marker_line` reads everything after the `n=`
1169/// token as the scenario name, so an appended field would rename the window
1170/// rather than annotate it.
1171#[cfg(feature = "perf-trace")]
1172fn format_marker_overflow_line(frame: u64, dropped: u64) -> String {
1173 format!("{MARKER_OVERFLOW_PREFIX} n={frame} dropped={dropped}")
1174}
1175
1176/// Raise a `bench-scenario-start` marker for `name` — the opening edge of a
1177/// benchmark scenario window, so an external harness can slice the
1178/// per-frame `frust-perf raw` series into named scenarios without holding a
1179/// [`FrameStats`] handle itself (a marker is a scenario-boundary event, not
1180/// a per-frame one, hence a free function rather than a method).
1181///
1182/// # What the emitted `n` means
1183///
1184/// Raising a marker does **not** log it. The marker is queued, travels with
1185/// the frame the calling build hands off, and is logged by
1186/// [`FrameStats::record`] as `bench-scenario-start n=<frame> <name>` where
1187/// `<frame>` is the number of the frame that actually carried it through
1188/// the pipeline — immediately ahead of that frame's own `frust-perf raw`
1189/// line. Nothing here guesses a frame number across a thread boundary,
1190/// which is the whole point: on the render-thread split the UI thread that
1191/// raises a marker cannot know whether the render thread has recorded the
1192/// previous frame yet.
1193///
1194/// The window is **half-open**. `start` is raised in the build that also
1195/// applies the operation being measured, so `start n=k` names the window's
1196/// first frame; `end` is raised in the *next* build (the S3 convention —
1197/// `benchmarks/frust_bench/src/scenarios/s3_table.rs`), so `end n=k+1`
1198/// names the first frame *after* the window. A harness attributes the
1199/// frames with `start_n <= n < end_n` to the window — one frame, for the S3
1200/// shape (see `benchmarks/PROTOCOL.md` §7).
1201///
1202/// Two consequences worth knowing:
1203///
1204/// - Under the channel's depth-1 latest-wins slot, a build whose scene is
1205/// replaced before the render thread takes it never becomes a frame of
1206/// its own; its markers ride the frame that superseded it — the frame
1207/// that actually drew that build's result. If a window's `start` and
1208/// `end` both land on that one frame, the half-open window is empty,
1209/// which is the honest answer: the operation's own frame was dropped.
1210/// - **Raise a marker on the thread that produces frames.** A marker is
1211/// queued on the calling thread and leaves it only when that same thread
1212/// hands a frame across the render channel (the split's UI thread) or
1213/// records one itself (the inline executor). Raised anywhere else — a
1214/// `spawn_blocking` pool thread, a plugin callback thread — it belongs to
1215/// a queue no frame will ever be recorded from, and is therefore never
1216/// emitted. That is the price of never guessing a frame number across a
1217/// thread boundary: a marker attached to a frame the raiser is not
1218/// producing would be exactly the cross-thread guess this route exists to
1219/// remove. A scenario measuring off-thread work brackets it from the
1220/// build that shows the result, not from inside the worker.
1221///
1222/// A no-op unless [`enabled`] is `true`; unlike the raw per-frame line it
1223/// does **not** additionally require [`raw_enabled`], so a scenario window
1224/// is present in every perf-enabled capture. A build without the
1225/// `perf-trace` feature compiles the whole route out, leaving this an empty
1226/// function.
1227#[cfg_attr(not(feature = "perf-trace"), allow(unused_variables))]
1228pub fn mark_scenario_start(name: &str) {
1229 #[cfg(feature = "perf-trace")]
1230 push_marker(MarkerEdge::Start, name);
1231}
1232
1233/// Raise a `bench-scenario-end` marker — the closing edge of the window
1234/// [`mark_scenario_start`] opened; see its docs, which cover the gating, the
1235/// emitted `n`, and the half-open `[start_n, end_n)` rule identically. In
1236/// the S3 convention this is raised in the build *after* the measured one,
1237/// so its `n` is one past the window's last frame.
1238#[cfg_attr(not(feature = "perf-trace"), allow(unused_variables))]
1239pub fn mark_scenario_end(name: &str) {
1240 #[cfg(feature = "perf-trace")]
1241 push_marker(MarkerEdge::End, name);
1242}
1243
1244/// Emit one already-formatted benchmark trace line into the same
1245/// `log::info!` stream the per-frame `frust-perf raw` lines and the
1246/// `bench-scenario-*` markers land in.
1247///
1248/// This is the frust counterpart to the Flutter bench's `benchEmit`
1249/// (`benchmarks/flutter_bench/lib/bench/perf.dart`): a benchmark scenario that
1250/// records a per-operation measurement (e.g. S8's
1251/// `frust-perf plugin op=write type=bool n=0 us=12` per-op latency lines) hands
1252/// this an already-formatted single line, which the harness parses alongside
1253/// the frame series. Centralizing every bench line behind one gated sink keeps
1254/// per-op emission on the same two-dial switch the markers use — a no-op unless
1255/// both [`enabled`] and [`raw_enabled`] are `true`.
1256#[cfg_attr(not(feature = "perf-trace"), allow(unused_variables))]
1257pub fn bench_emit(line: &str) {
1258 #[cfg(feature = "perf-trace")]
1259 if enabled() && raw_enabled() {
1260 log::info!("{line}");
1261 }
1262}
1263
1264// ---------------------------------------------------------------------
1265// StartupSpans
1266// ---------------------------------------------------------------------
1267
1268/// Startup-span name: native library load (process/JNI load, or the C-ABI
1269/// equivalent on iOS).
1270pub const SPAN_NATIVE_LIB_LOAD: &str = "native_lib_load";
1271/// Startup-span name: entry into the shell's init function (`nativeInit` /
1272/// `frust_init` / the desktop app-construction entry point).
1273pub const SPAN_INIT_ENTRY: &str = "init_entry";
1274/// Startup-span name: the wgpu adapter is acquired.
1275pub const SPAN_ADAPTER_READY: &str = "adapter_ready";
1276/// Startup-span name: the wgpu logical device is acquired.
1277pub const SPAN_DEVICE_READY: &str = "device_ready";
1278/// Startup-span name: the vello renderer (and surface) are ready to
1279/// present.
1280pub const SPAN_RENDERER_READY: &str = "renderer_ready";
1281/// Startup-span name: a persisted GPU
1282/// pipeline cache blob was restored before surface creation — its *presence* in
1283/// the startup line is the warm-start (cache-**hit**) signal, its *absence* the
1284/// cold-start (cache-**miss**) one, so a slow first frame can be attributed to
1285/// shader-pipeline compilation vs a warm cache. Recorded only on a hit, right
1286/// before the surface (and thus the pipeline) is built.
1287pub const SPAN_PIPELINE_CACHE_RESTORED: &str = "pipeline_cache_restored";
1288/// Startup-span name: the app's first `rebuild` pass has completed.
1289pub const SPAN_FIRST_REBUILD_DONE: &str = "first_rebuild_done";
1290/// Startup-span name: the app's first
1291/// frame's GPU/CPU **encode** has completed — the boundary between the first
1292/// frame's paint/encode work and its swapchain-acquire (present) wait, so a
1293/// first-frame outlier (a 3646ms-class span) decomposes into encode vs present
1294/// exactly as the per-frame [`FramePasses`] split does.
1295pub const SPAN_FIRST_ENCODE_DONE: &str = "first_encode_done";
1296/// Startup-span name: the app's first frame has been presented to the
1297/// surface.
1298pub const SPAN_FIRST_FRAME_PRESENTED: &str = "first_frame_presented";
1299
1300/// A monotonic clock reading, injectable so [`StartupSpans`]'s deltas are
1301/// deterministically testable without a real clock. Only differences
1302/// between successive readings are meaningful — the absolute value has no
1303/// defined epoch.
1304pub trait Clock {
1305 fn now(&mut self) -> Duration;
1306}
1307
1308/// Any `FnMut() -> Duration` closure is a [`Clock`] — the lighter-weight
1309/// option for a one-off test fake (see the module docs' "injectable clock"
1310/// note).
1311impl<F: FnMut() -> Duration> Clock for F {
1312 fn now(&mut self) -> Duration {
1313 self()
1314 }
1315}
1316
1317/// The production [`Clock`]: wraps [`std::time::Instant`], monotonic for
1318/// the lifetime of the process.
1319#[derive(Debug)]
1320pub struct SystemClock {
1321 start: Instant,
1322}
1323
1324impl SystemClock {
1325 pub fn new() -> Self {
1326 Self {
1327 start: Instant::now(),
1328 }
1329 }
1330}
1331
1332impl Default for SystemClock {
1333 fn default() -> Self {
1334 Self::new()
1335 }
1336}
1337
1338impl Clock for SystemClock {
1339 fn now(&mut self) -> Duration {
1340 self.start.elapsed()
1341 }
1342}
1343
1344/// Named monotonic timestamps from a `begin()` epoch —
1345/// a shell records one named span at each startup milestone (see the
1346/// `SPAN_*` consts), then calls [`Self::emit_log`] once for a single
1347/// summary line.
1348pub struct StartupSpans<C: Clock = SystemClock> {
1349 enabled: bool,
1350 clock: C,
1351 begin: Duration,
1352 spans: Vec<(&'static str, Duration)>,
1353}
1354
1355impl StartupSpans<SystemClock> {
1356 /// Begin a span recorder honoring the process-wide [`enabled`] switch,
1357 /// using the real system clock — what every shell constructs.
1358 pub fn begin() -> Self {
1359 Self::begin_with_enabled(SystemClock::new(), enabled())
1360 }
1361}
1362
1363impl<C: Clock> StartupSpans<C> {
1364 /// Test/advanced seam: begin with an explicit clock and enabled flag,
1365 /// bypassing [`enabled`]'s cache (see [`FrameStats::new_enabled`]'s docs
1366 /// for why).
1367 pub fn begin_with_enabled(mut clock: C, is_enabled: bool) -> Self {
1368 let begin = clock.now();
1369 Self {
1370 enabled: is_enabled,
1371 clock,
1372 begin,
1373 spans: Vec::new(),
1374 }
1375 }
1376
1377 /// Record `name` at the current clock reading, as a delta from
1378 /// [`Self::begin`]'s epoch. A no-op (no clock read, no allocation) when
1379 /// disabled.
1380 pub fn record(&mut self, name: &'static str) {
1381 if !self.enabled {
1382 return;
1383 }
1384 let now = self.clock.now();
1385 self.spans.push((name, now.saturating_sub(self.begin)));
1386 }
1387
1388 /// The recorded `(name, delta)` pairs in insertion order.
1389 pub fn spans(&self) -> &[(&'static str, Duration)] {
1390 &self.spans
1391 }
1392
1393 /// Emit one `frust-perf startup ...` line via `log::info!` containing
1394 /// every recorded span's name and millisecond delta, in insertion
1395 /// order. A no-op when disabled or when nothing has been recorded.
1396 pub fn emit_log(&self) {
1397 // The `frust-perf startup` line is a gated string literal; a
1398 // release-lean (feature-off) build compiles the body away entirely
1399 // (and `enabled` is a `false` constant there anyway). Written as a
1400 // positive guard rather than an early return so the feature-off body
1401 // is simply empty, with no dangling `return`.
1402 if self.enabled && !self.spans.is_empty() {
1403 #[cfg(feature = "perf-trace")]
1404 {
1405 let mut line = String::from("frust-perf startup");
1406 for (name, delta) in &self.spans {
1407 line.push_str(&format!(" {name}={}ms", delta.as_millis()));
1408 }
1409 log::info!("{line}");
1410 }
1411 }
1412 }
1413}
1414
1415#[cfg(test)]
1416mod tests {
1417 use super::*;
1418
1419 // ---------------------------------------------------------------
1420 // trace_switch (pure, directly testable — enabled()'s OnceLock cache
1421 // is deliberately NOT re-tested here, see enabled()'s docs). The
1422 // `trace_switch` decision only exists under `perf-trace`, so these run
1423 // in the feature-on configuration only.
1424 // ---------------------------------------------------------------
1425
1426 #[cfg(feature = "perf-trace")]
1427 #[test]
1428 fn trace_switch_off_when_neither_set() {
1429 assert!(!trace_switch(None, None));
1430 }
1431
1432 #[cfg(feature = "perf-trace")]
1433 #[test]
1434 fn trace_switch_on_when_compile_time_set_non_zero() {
1435 assert!(trace_switch(Some("1"), None));
1436 }
1437
1438 #[cfg(feature = "perf-trace")]
1439 #[test]
1440 fn trace_switch_on_when_runtime_set_non_zero() {
1441 assert!(trace_switch(None, Some("1")));
1442 }
1443
1444 #[cfg(feature = "perf-trace")]
1445 #[test]
1446 fn trace_switch_off_when_either_is_literal_zero_and_other_unset() {
1447 assert!(!trace_switch(Some("0"), None));
1448 assert!(!trace_switch(None, Some("0")));
1449 }
1450
1451 #[cfg(feature = "perf-trace")]
1452 #[test]
1453 fn trace_switch_on_when_either_source_wins() {
1454 // Compile-time "0" (effectively off) but runtime "1": still on.
1455 assert!(trace_switch(Some("0"), Some("1")));
1456 assert!(trace_switch(Some("1"), Some("0")));
1457 }
1458
1459 // ---------------------------------------------------------------
1460 // Compile-out switch (perf-trace off): the runtime dial collapses to a
1461 // `false` constant and the whole public perf API stays callable + inert.
1462 // ---------------------------------------------------------------
1463
1464 #[cfg(not(feature = "perf-trace"))]
1465 #[test]
1466 fn enabled_and_raw_enabled_are_const_false_without_feature() {
1467 assert!(!enabled(), "perf-trace off ⇒ enabled() is a false constant");
1468 assert!(
1469 !raw_enabled(),
1470 "perf-trace off ⇒ raw_enabled() is a false constant"
1471 );
1472 }
1473
1474 #[cfg(not(feature = "perf-trace"))]
1475 #[test]
1476 fn disabled_build_public_api_is_callable_and_inert() {
1477 // Every public perf entry point still exists and is safe to call in a
1478 // release-lean build — it just records/emits nothing (no shell call
1479 // site changes between the two configurations).
1480 let mut stats = FrameStats::new();
1481 stats.record(passes(20, 5, 5, 2));
1482 assert_eq!(stats.total_frames(), 0, "feature-off new() is disabled");
1483 assert_eq!(stats.summary().frame_count, 0);
1484 assert!(!stats.should_emit());
1485 stats.emit_log(); // no-op, must not panic
1486
1487 let mut spans = StartupSpans::begin();
1488 spans.record(SPAN_INIT_ENTRY);
1489 assert!(spans.spans().is_empty(), "feature-off begin() is disabled");
1490 spans.emit_log(); // no-op, must not panic
1491
1492 // Free-function emitters are inert no-ops (no strings compiled in).
1493 mark_scenario_start("smoke");
1494 mark_scenario_end("smoke");
1495 bench_emit("smoke op=write");
1496 }
1497
1498 // ---------------------------------------------------------------
1499 // nearest_rank_percentile
1500 // ---------------------------------------------------------------
1501
1502 #[test]
1503 fn percentile_known_distribution_1_to_100ms() {
1504 // A sorted sample of 1ms..=100ms (n = 100): nearest-rank with
1505 // ceil(p*n/100) 1-indexed rank means p50 -> rank 50 -> value 50ms;
1506 // p95 -> rank 95 -> value 95ms; p99 -> rank 99 -> value 99ms.
1507 let sorted: Vec<Duration> = (1..=100).map(Duration::from_millis).collect();
1508 assert_eq!(
1509 nearest_rank_percentile(&sorted, 50),
1510 Duration::from_millis(50)
1511 );
1512 assert_eq!(
1513 nearest_rank_percentile(&sorted, 95),
1514 Duration::from_millis(95)
1515 );
1516 assert_eq!(
1517 nearest_rank_percentile(&sorted, 99),
1518 Duration::from_millis(99)
1519 );
1520 }
1521
1522 #[test]
1523 fn percentile_small_sample_rounds_up_rank() {
1524 // n = 4: rank(50) = ceil(200/100) = 2 -> index 1 -> value 2ms.
1525 // rank(95) = ceil(380/100) = 4 -> index 3 -> value 4ms.
1526 let sorted: Vec<Duration> = (1..=4).map(Duration::from_millis).collect();
1527 assert_eq!(
1528 nearest_rank_percentile(&sorted, 50),
1529 Duration::from_millis(2)
1530 );
1531 assert_eq!(
1532 nearest_rank_percentile(&sorted, 95),
1533 Duration::from_millis(4)
1534 );
1535 }
1536
1537 #[test]
1538 fn percentile_single_value_returns_it_for_every_percentile() {
1539 let sorted = [Duration::from_millis(42)];
1540 assert_eq!(
1541 nearest_rank_percentile(&sorted, 50),
1542 Duration::from_millis(42)
1543 );
1544 assert_eq!(
1545 nearest_rank_percentile(&sorted, 99),
1546 Duration::from_millis(42)
1547 );
1548 }
1549
1550 #[test]
1551 fn percentile_empty_sample_is_zero() {
1552 assert_eq!(nearest_rank_percentile(&[], 50), Duration::ZERO);
1553 }
1554
1555 // ---------------------------------------------------------------
1556 // FrameStats
1557 // ---------------------------------------------------------------
1558
1559 /// The `encode_ms` argument feeds the `encode` span; the `acquire`/`submit`
1560 /// spans are left zero so existing total-time assertions are unchanged by the
1561 /// v3 field split — only the per-span attribution moved.
1562 fn passes(rebuild_ms: u64, layout_ms: u64, paint_ms: u64, encode_ms: u64) -> FramePasses {
1563 FramePasses {
1564 rebuild: Duration::from_millis(rebuild_ms),
1565 layout: Duration::from_millis(layout_ms),
1566 paint: Duration::from_millis(paint_ms),
1567 encode: Duration::from_millis(encode_ms),
1568 acquire: Duration::ZERO,
1569 submit: Duration::ZERO,
1570 skipped: false,
1571 gpu: None,
1572 }
1573 }
1574
1575 #[test]
1576 fn disabled_recorder_records_nothing_and_never_allocates() {
1577 let mut stats = FrameStats::new_enabled(false);
1578 for _ in 0..500 {
1579 stats.record(passes(20, 5, 5, 2));
1580 }
1581 assert_eq!(stats.total_frames(), 0);
1582 assert_eq!(
1583 stats.ring.capacity(),
1584 0,
1585 "disabled recorder must never reserve ring capacity"
1586 );
1587 let s = stats.summary();
1588 assert_eq!(s.frame_count, 0);
1589 assert_eq!(s.total_p50, Duration::ZERO);
1590 assert!(!stats.should_emit());
1591 }
1592
1593 #[test]
1594 fn over_budget_counters_are_exact() {
1595 let mut stats = FrameStats::new_enabled(true);
1596 // Under both budgets: 5ms total.
1597 stats.record(passes(2, 1, 1, 1));
1598 // Over 8.3ms but under 16.6ms: 10ms total.
1599 stats.record(passes(4, 2, 2, 2));
1600 // Over both: 20ms total.
1601 stats.record(passes(10, 5, 3, 2));
1602
1603 let s = stats.summary();
1604 assert_eq!(
1605 s.over_120hz_budget, 2,
1606 "10ms and 20ms frames exceed the 8.3ms budget"
1607 );
1608 assert_eq!(
1609 s.over_60hz_budget, 1,
1610 "only the 20ms frame exceeds the 16.6ms budget"
1611 );
1612 }
1613
1614 #[test]
1615 fn skipped_frames_counted_but_excluded_from_percentiles() {
1616 let mut stats = FrameStats::new_enabled(true);
1617 stats.record(passes(10, 2, 2, 2)); // 16ms, non-skipped
1618 stats.record(FramePasses {
1619 skipped: true,
1620 ..Default::default()
1621 }); // 0ms, skipped
1622 stats.record(passes(10, 2, 2, 2)); // 16ms, non-skipped
1623
1624 let s = stats.summary();
1625 assert_eq!(s.skipped_frames, 1);
1626 assert_eq!(stats.total_frames(), 3);
1627 // Percentile window only has the two 16ms non-skipped frames — a
1628 // skipped frame's 0ms would otherwise pull this down.
1629 assert_eq!(s.frame_count, 3, "ring buffer holds all recorded frames...");
1630 assert_eq!(
1631 s.total_p50,
1632 Duration::from_millis(16),
1633 "...but percentiles exclude the skipped one"
1634 );
1635 }
1636
1637 #[test]
1638 fn summary_attributes_encode_acquire_and_submit_spans_separately() {
1639 // The old combined present is now two spans (acquire +
1640 // submit) beside encode. A frame that spends 6ms encoding, 9ms on the
1641 // blocking acquire (vsync wait), and 3ms on the blit/submit must report
1642 // each p95 independently — not one conflated number.
1643 let mut stats = FrameStats::new_enabled(true);
1644 stats.record(FramePasses {
1645 rebuild: Duration::from_millis(2),
1646 layout: Duration::from_millis(1),
1647 paint: Duration::from_millis(1),
1648 encode: Duration::from_millis(6),
1649 acquire: Duration::from_millis(9),
1650 submit: Duration::from_millis(3),
1651 skipped: false,
1652 gpu: None,
1653 });
1654 let s = stats.summary();
1655 assert_eq!(
1656 s.encode_p95,
1657 Duration::from_millis(6),
1658 "encode span attributed"
1659 );
1660 assert_eq!(
1661 s.acquire_p95,
1662 Duration::from_millis(9),
1663 "acquire span attributed"
1664 );
1665 assert_eq!(
1666 s.submit_p95,
1667 Duration::from_millis(3),
1668 "submit span attributed"
1669 );
1670 // Total still sums every span (22ms here).
1671 assert_eq!(s.total_p95, Duration::from_millis(22));
1672 }
1673
1674 #[test]
1675 fn from_split_recombines_the_two_half_frames_without_changing_the_record() {
1676 // The UI thread measures rebuild/layout/paint, the render
1677 // thread measures encode/acquire/submit. `from_split` folds them into
1678 // the exact same FramePasses a single-thread frame would have built —
1679 // the render-thread split moves *where* spans are measured, not the
1680 // recorded shape or wire format.
1681 let ui = UiSpans {
1682 rebuild: Duration::from_millis(2),
1683 layout: Duration::from_millis(1),
1684 paint: Duration::from_millis(1),
1685 skipped: false,
1686 };
1687 let render = RenderSpans {
1688 encode: Duration::from_millis(6),
1689 acquire: Duration::from_millis(9),
1690 submit: Duration::from_millis(3),
1691 };
1692 let split = FramePasses::from_split(ui, render);
1693 let whole = FramePasses {
1694 rebuild: Duration::from_millis(2),
1695 layout: Duration::from_millis(1),
1696 paint: Duration::from_millis(1),
1697 encode: Duration::from_millis(6),
1698 acquire: Duration::from_millis(9),
1699 submit: Duration::from_millis(3),
1700 skipped: false,
1701 gpu: None,
1702 };
1703 assert_eq!(split, whole, "split reassembly must equal the whole frame");
1704 assert_eq!(split.total(), Duration::from_millis(22));
1705 }
1706
1707 /// The raw v3 wire line a split frame produces is byte-for-byte identical
1708 /// to the single-thread frame's — asserted separately because
1709 /// [`format_raw_frame_line`] is `perf-trace`-gated emission.
1710 #[cfg(feature = "perf-trace")]
1711 #[test]
1712 fn from_split_v3_wire_format_is_identical_to_single_thread() {
1713 let ui = UiSpans {
1714 rebuild: Duration::from_millis(2),
1715 layout: Duration::from_millis(1),
1716 paint: Duration::from_millis(1),
1717 skipped: false,
1718 };
1719 let render = RenderSpans {
1720 encode: Duration::from_millis(6),
1721 acquire: Duration::from_millis(9),
1722 submit: Duration::from_millis(3),
1723 };
1724 let split = FramePasses::from_split(ui, render);
1725 let whole = FramePasses {
1726 rebuild: Duration::from_millis(2),
1727 layout: Duration::from_millis(1),
1728 paint: Duration::from_millis(1),
1729 encode: Duration::from_millis(6),
1730 acquire: Duration::from_millis(9),
1731 submit: Duration::from_millis(3),
1732 skipped: false,
1733 gpu: None,
1734 };
1735 let mut split_line = String::new();
1736 let mut whole_line = String::new();
1737 format_raw_frame_line(&mut split_line, 1, &split);
1738 format_raw_frame_line(&mut whole_line, 1, &whole);
1739 assert_eq!(
1740 split_line, whole_line,
1741 "v3 wire format is unchanged by the split"
1742 );
1743 }
1744
1745 #[test]
1746 fn from_split_preserves_the_ui_side_skipped_verdict() {
1747 // The frame gate is UI-side, so a skipped frame's verdict rides in on
1748 // the UiSpans half and must survive the fold.
1749 let ui = UiSpans {
1750 skipped: true,
1751 ..Default::default()
1752 };
1753 let split = FramePasses::from_split(ui, RenderSpans::default());
1754 assert!(split.skipped, "the UI-side skip verdict must be preserved");
1755 assert_eq!(split.total(), Duration::ZERO);
1756 }
1757
1758 #[test]
1759 fn ring_buffer_evicts_oldest_beyond_capacity() {
1760 let mut stats = FrameStats::with_capacity_enabled(3, true);
1761 stats.record(passes(1, 0, 0, 0));
1762 stats.record(passes(2, 0, 0, 0));
1763 stats.record(passes(3, 0, 0, 0));
1764 stats.record(passes(4, 0, 0, 0)); // evicts the 1ms frame
1765
1766 let s = stats.summary();
1767 assert_eq!(s.frame_count, 3);
1768 // Sample is now {2, 3, 4}ms: p50 (rank ceil(150/100)=2) -> 3ms.
1769 assert_eq!(s.total_p50, Duration::from_millis(3));
1770 // Running total_frames is unaffected by eviction.
1771 assert_eq!(stats.total_frames(), 4);
1772 }
1773
1774 #[test]
1775 fn should_emit_rate_limits_on_accumulated_frame_time() {
1776 let mut stats = FrameStats::new_enabled(true);
1777 assert!(!stats.should_emit());
1778 // 100 frames * 16ms = 1600ms < the 2s interval.
1779 for _ in 0..100 {
1780 stats.record(passes(10, 3, 2, 1));
1781 }
1782 assert!(!stats.should_emit());
1783 // 25 more frames pushes accumulated time past 2000ms.
1784 for _ in 0..25 {
1785 stats.record(passes(10, 3, 2, 1));
1786 }
1787 assert!(stats.should_emit());
1788
1789 stats.emit_log();
1790 assert!(!stats.should_emit(), "emit_log resets the accumulator");
1791 }
1792
1793 #[test]
1794 fn a_reassembled_split_frame_carries_no_gpu_reading_until_one_is_attached() {
1795 let split = FramePasses::from_split(
1796 UiSpans {
1797 rebuild: Duration::from_millis(2),
1798 ..Default::default()
1799 },
1800 RenderSpans {
1801 encode: Duration::from_millis(6),
1802 acquire: Duration::from_millis(9),
1803 submit: Duration::from_millis(3),
1804 },
1805 );
1806 assert_eq!(split.gpu, None, "neither half measures GPU time");
1807
1808 let gpu = GpuPasses {
1809 prepass: Duration::from_micros(10),
1810 main: Duration::from_micros(20),
1811 composite: Duration::from_micros(30),
1812 blit: Duration::from_micros(40),
1813 };
1814 let timed = split.with_gpu(gpu);
1815 assert_eq!(timed.gpu, Some(gpu));
1816 assert_eq!(timed.total(), split.total(), "GPU time is not frame time");
1817 assert_eq!(gpu.total(), Duration::from_micros(100));
1818 // Every other field is untouched by the attachment.
1819 assert_eq!(FramePasses { gpu: None, ..timed }, split);
1820 }
1821
1822 #[test]
1823 fn an_all_zero_gpu_reading_is_still_a_reading() {
1824 // A frame that drew nothing off-screen genuinely spent no composite
1825 // time; the distinction between "measured zero" and "not measured" is
1826 // the `Option`, never a zero value.
1827 let timed = FramePasses::default().with_gpu(GpuPasses::default());
1828 assert_eq!(timed.gpu, Some(GpuPasses::default()));
1829 assert_eq!(timed.gpu.map(|gpu| gpu.total()), Some(Duration::ZERO));
1830 assert_eq!(FramePasses::default().gpu, None);
1831 }
1832
1833 // ---------------------------------------------------------------
1834 // Raw per-frame export + scenario markers
1835 // ---------------------------------------------------------------
1836
1837 /// A raw per-frame line's parsed fields — this module's own round-trip
1838 /// check that [`format_raw_frame_line`]'s shape is exactly what a
1839 /// `key=value`-splitting harness would expect; not part of the crate's
1840 /// public API (the real harness is a separate process parsing
1841 /// `stdout`/`logcat` text, not a Rust consumer of this module). Gated with
1842 /// the emission it exercises.
1843 #[cfg(feature = "perf-trace")]
1844 struct ParsedRawFrameLine {
1845 n: u64,
1846 total_us: u128,
1847 rebuild_us: u128,
1848 layout_us: u128,
1849 paint_us: u128,
1850 encode_us: u128,
1851 acquire_us: u128,
1852 submit_us: u128,
1853 skipped: bool,
1854 /// v4's `gpu_q` marker, plus every `gpu_*_us` field it gates, in the
1855 /// order the line wrote them — absent as a group whenever `gpu_q=0`.
1856 gpu_q: bool,
1857 gpu: Vec<(String, u128)>,
1858 }
1859
1860 #[cfg(feature = "perf-trace")]
1861 fn parse_raw_frame_line(line: &str) -> Option<ParsedRawFrameLine> {
1862 let rest = line.strip_prefix(RAW_FRAME_PREFIX)?.trim_start();
1863 let mut n = None;
1864 let mut total_us = None;
1865 let mut rebuild_us = None;
1866 let mut layout_us = None;
1867 let mut paint_us = None;
1868 let mut encode_us = None;
1869 let mut acquire_us = None;
1870 let mut submit_us = None;
1871 let mut skipped = None;
1872 let mut gpu_q = None;
1873 let mut gpu = Vec::new();
1874 for field in rest.split_whitespace() {
1875 let (key, value) = field.split_once('=')?;
1876 match key {
1877 "n" => n = value.parse().ok(),
1878 "total_us" => total_us = value.parse().ok(),
1879 "rebuild_us" => rebuild_us = value.parse().ok(),
1880 "layout_us" => layout_us = value.parse().ok(),
1881 "paint_us" => paint_us = value.parse().ok(),
1882 "encode_us" => encode_us = value.parse().ok(),
1883 "acquire_us" => acquire_us = value.parse().ok(),
1884 "submit_us" => submit_us = value.parse().ok(),
1885 "skipped" => skipped = value.parse::<u8>().ok().map(|v| v != 0),
1886 "gpu_q" => gpu_q = value.parse::<u8>().ok().map(|v| v != 0),
1887 other if other.starts_with("gpu_") => {
1888 gpu.push((other.to_string(), value.parse().ok()?));
1889 }
1890 _ => {}
1891 }
1892 }
1893 Some(ParsedRawFrameLine {
1894 n: n?,
1895 total_us: total_us?,
1896 rebuild_us: rebuild_us?,
1897 layout_us: layout_us?,
1898 paint_us: paint_us?,
1899 encode_us: encode_us?,
1900 acquire_us: acquire_us?,
1901 submit_us: submit_us?,
1902 skipped: skipped?,
1903 gpu_q: gpu_q?,
1904 gpu,
1905 })
1906 }
1907
1908 #[cfg(feature = "perf-trace")]
1909 #[test]
1910 fn raw_frame_line_format_round_trips() {
1911 let mut buf = String::new();
1912 let p = FramePasses {
1913 rebuild: Duration::from_micros(1234),
1914 layout: Duration::from_micros(200),
1915 paint: Duration::from_micros(300),
1916 encode: Duration::from_micros(50),
1917 acquire: Duration::from_micros(80),
1918 submit: Duration::from_micros(40),
1919 skipped: false,
1920 gpu: None,
1921 };
1922 format_raw_frame_line(&mut buf, 42, &p);
1923 assert!(buf.starts_with(RAW_FRAME_PREFIX));
1924
1925 let parsed = parse_raw_frame_line(&buf).expect("line must parse");
1926 assert_eq!(parsed.n, 42);
1927 assert_eq!(parsed.total_us, p.total().as_micros());
1928 assert_eq!(parsed.rebuild_us, 1234);
1929 assert_eq!(parsed.layout_us, 200);
1930 assert_eq!(parsed.paint_us, 300);
1931 assert_eq!(parsed.encode_us, 50);
1932 assert_eq!(parsed.acquire_us, 80);
1933 assert_eq!(parsed.submit_us, 40);
1934 assert!(!parsed.skipped);
1935 assert!(!parsed.gpu_q, "a frame with no GPU reading reports gpu_q=0");
1936 }
1937
1938 #[cfg(feature = "perf-trace")]
1939 #[test]
1940 fn a_frame_without_a_gpu_reading_writes_gpu_q_zero_and_no_gpu_columns() {
1941 // The no-TIMESTAMP_QUERY shape: the marker says there is no reading,
1942 // and the five `gpu_*_us` fields are absent rather than written as
1943 // zeros — a column of zeros in a raw series reads like a measured
1944 // result, which is exactly what this must not produce.
1945 let mut buf = String::new();
1946 format_raw_frame_line(&mut buf, 3, &passes(10, 2, 2, 2));
1947
1948 assert!(buf.contains(" gpu_q=0"));
1949 assert!(
1950 !buf.contains("gpu_total_us"),
1951 "no gpu_* column may be emitted without a reading: {buf}"
1952 );
1953 let parsed = parse_raw_frame_line(&buf).expect("line must parse");
1954 assert!(!parsed.gpu_q);
1955 assert!(parsed.gpu.is_empty());
1956 }
1957
1958 #[cfg(feature = "perf-trace")]
1959 #[test]
1960 fn a_gpu_timed_frame_appends_every_span_in_the_declared_order() {
1961 let gpu = GpuPasses {
1962 prepass: Duration::from_micros(120),
1963 main: Duration::from_micros(2400),
1964 composite: Duration::from_micros(650),
1965 blit: Duration::from_micros(75),
1966 };
1967 let mut buf = String::new();
1968 format_raw_frame_line(&mut buf, 9, &passes(4, 1, 1, 2).with_gpu(gpu));
1969
1970 let parsed = parse_raw_frame_line(&buf).expect("line must parse");
1971 assert!(parsed.gpu_q);
1972 assert_eq!(
1973 parsed.gpu,
1974 vec![
1975 ("gpu_total_us".to_string(), 3245),
1976 ("gpu_prepass_us".to_string(), 120),
1977 ("gpu_main_us".to_string(), 2400),
1978 ("gpu_composite_us".to_string(), 650),
1979 ("gpu_blit_us".to_string(), 75),
1980 ],
1981 "field order is wire contract: {buf}"
1982 );
1983 assert_eq!(gpu.total(), Duration::from_micros(3245));
1984 }
1985
1986 #[cfg(feature = "perf-trace")]
1987 #[test]
1988 fn the_v3_prefix_of_a_v4_line_is_byte_identical() {
1989 // v4 is additive: appending the GPU fields must not perturb one byte
1990 // of what a v3 parser reads, so every series already captured stays
1991 // comparable against one captured after this change.
1992 let base = passes(4, 1, 1, 2);
1993 let mut v3_line = String::new();
1994 let mut v4_line = String::new();
1995 format_raw_frame_line(&mut v3_line, 11, &base);
1996 format_raw_frame_line(
1997 &mut v4_line,
1998 11,
1999 &base.with_gpu(GpuPasses {
2000 main: Duration::from_micros(1),
2001 ..GpuPasses::default()
2002 }),
2003 );
2004
2005 let (v3_head, v3_marker) = v3_line
2006 .rsplit_once(" gpu_q=")
2007 .expect("every v4 line carries the marker");
2008 assert_eq!(v3_marker, "0");
2009 assert!(
2010 v4_line.starts_with(v3_head),
2011 "the v3 field set must be byte-identical:\n{v3_line}\n{v4_line}"
2012 );
2013 }
2014
2015 #[cfg(feature = "perf-trace")]
2016 #[test]
2017 fn a_gpu_timed_frames_total_excludes_the_gpu_spans() {
2018 // GPU passes run concurrently with the CPU spans, so folding them into
2019 // `total_us` would double-count the frame and break every percentile
2020 // computed off it.
2021 let base = passes(4, 1, 1, 2);
2022 let timed = base.with_gpu(GpuPasses {
2023 main: Duration::from_millis(50),
2024 ..GpuPasses::default()
2025 });
2026 assert_eq!(timed.total(), base.total());
2027
2028 let mut buf = String::new();
2029 format_raw_frame_line(&mut buf, 1, &timed);
2030 let parsed = parse_raw_frame_line(&buf).expect("line must parse");
2031 assert_eq!(parsed.total_us, base.total().as_micros());
2032 }
2033
2034 #[cfg(feature = "perf-trace")]
2035 #[test]
2036 fn raw_frame_line_represents_skipped_flag() {
2037 let mut buf = String::new();
2038 let p = FramePasses {
2039 skipped: true,
2040 ..Default::default()
2041 };
2042 format_raw_frame_line(&mut buf, 7, &p);
2043
2044 let parsed = parse_raw_frame_line(&buf).expect("line must parse");
2045 assert!(parsed.skipped, "skipped frame must still be represented");
2046 assert_eq!(parsed.total_us, 0);
2047 assert_eq!(parsed.n, 7);
2048 }
2049
2050 #[cfg(feature = "perf-trace")]
2051 #[test]
2052 fn raw_enabled_record_formats_one_line_per_frame() {
2053 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, true);
2054 stats.record(passes(10, 2, 2, 2));
2055 let parsed = parse_raw_frame_line(&stats.raw_buf).expect("line must parse");
2056 assert_eq!(parsed.n, 1);
2057
2058 stats.record(passes(5, 1, 1, 1));
2059 let parsed = parse_raw_frame_line(&stats.raw_buf).expect("line must parse");
2060 assert_eq!(parsed.n, 2, "frame index advances per recorded frame");
2061 }
2062
2063 #[test]
2064 fn raw_disabled_record_never_touches_raw_line_buffer() {
2065 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, false);
2066 for _ in 0..5 {
2067 stats.record(passes(1, 1, 1, 1));
2068 }
2069 assert!(
2070 stats.raw_buf.is_empty(),
2071 "raw-export off must never format into the raw line buffer"
2072 );
2073 assert_eq!(stats.total_frames(), 5, "non-raw recording still happens");
2074 }
2075
2076 #[test]
2077 fn raw_requires_enabled_too() {
2078 // enabled=false + is_raw=true: the whole recorder (including raw)
2079 // stays off — enabled() gates raw_enabled(), not the other way
2080 // around.
2081 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, false, true);
2082 stats.record(passes(10, 2, 2, 2));
2083 assert_eq!(stats.total_frames(), 0, "disabled recorder still no-ops");
2084 assert!(stats.raw_buf.is_empty());
2085 }
2086
2087 #[cfg(feature = "perf-trace")]
2088 #[test]
2089 fn scenario_marker_format_start_and_end() {
2090 assert_eq!(
2091 format_scenario_marker(MarkerEdge::Start, "cold_start", 5),
2092 "bench-scenario-start n=5 cold_start"
2093 );
2094 assert_eq!(
2095 format_scenario_marker(MarkerEdge::End, "cold_start", 6),
2096 "bench-scenario-end n=6 cold_start"
2097 );
2098 }
2099
2100 #[cfg(feature = "perf-trace")]
2101 #[test]
2102 fn markers_raised_while_perf_is_disabled_accumulate_nothing() {
2103 // Perf off (the guard leaves the force switch clear, and no test-run
2104 // process sets FRUST_TRACE): raising markers must be safe AND must
2105 // queue nothing at all — a queue nobody ever drains is the one way
2106 // this route could leak in a shipped build.
2107 let _guard = marker_test_guard(false);
2108
2109 mark_scenario_start("smoke");
2110 mark_scenario_end("smoke");
2111
2112 assert!(
2113 take_pending_markers().is_empty(),
2114 "a disabled marker must never reach the queue"
2115 );
2116 }
2117
2118 #[cfg(feature = "perf-trace")]
2119 #[test]
2120 fn inline_executor_drains_this_threads_pending_queue_at_record() {
2121 // The inline (no render thread) path: one thread raises and records,
2122 // so `record` drains that thread's own queue for the frame it is
2123 // recording right now. No route flag decides this — the queue it
2124 // drains is simply the queue the markers were raised into.
2125 let _guard = marker_test_guard(true);
2126 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, true);
2127
2128 mark_scenario_start("s3-create1k");
2129 stats.record(passes(10, 2, 2, 2));
2130 assert_eq!(
2131 stats.marker_log(),
2132 ["bench-scenario-start n=1 s3-create1k"],
2133 "the marker rides the frame being recorded when it was raised"
2134 );
2135
2136 // The next build closes the window: S3 raises `end` one build later,
2137 // so it lands on frame 2 and the half-open window is exactly frame 1.
2138 mark_scenario_end("s3-create1k");
2139 stats.record(passes(10, 2, 2, 2));
2140 assert_eq!(
2141 stats.marker_log(),
2142 [
2143 "bench-scenario-start n=1 s3-create1k",
2144 "bench-scenario-end n=2 s3-create1k",
2145 ]
2146 );
2147
2148 // A frame carrying no marker adds no line.
2149 stats.record(passes(10, 2, 2, 2));
2150 assert_eq!(stats.marker_log().len(), 2);
2151 assert_eq!(stats.total_frames(), 3);
2152 }
2153
2154 #[cfg(feature = "perf-trace")]
2155 #[test]
2156 fn markers_are_emitted_with_raw_export_off() {
2157 // The raw-export dial gates the per-frame line, not the markers: a
2158 // window must exist in every perf-enabled capture, not only in the
2159 // ones a harness asked for raw frames in.
2160 let _guard = marker_test_guard(true);
2161 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, false);
2162
2163 mark_scenario_start("s8-write");
2164 stats.record(passes(10, 2, 2, 2));
2165
2166 assert_eq!(stats.marker_log(), ["bench-scenario-start n=1 s8-write"]);
2167 assert!(
2168 stats.raw_buf.is_empty(),
2169 "raw export stays off — only the marker line was emitted"
2170 );
2171 }
2172
2173 #[cfg(feature = "perf-trace")]
2174 #[test]
2175 fn a_disabled_recorder_emits_no_marker_line() {
2176 // `record`'s own disabled early-return covers the markers too: a
2177 // recorder that counts no frames can stamp no frame number.
2178 let _guard = marker_test_guard(true);
2179 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, false, true);
2180
2181 mark_scenario_start("s3-update");
2182 stats.record(passes(10, 2, 2, 2));
2183
2184 assert!(stats.marker_log().is_empty());
2185 assert_eq!(stats.total_frames(), 0);
2186 }
2187
2188 #[cfg(feature = "perf-trace")]
2189 #[test]
2190 fn staged_markers_ride_the_next_recorded_frame_in_order() {
2191 // The render thread's leg in isolation: whatever `stage_markers` was
2192 // handed comes out on the next frame this thread records, in the
2193 // order it was raised, and only once.
2194 let _guard = marker_test_guard(true);
2195 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, true);
2196
2197 mark_scenario_start("s3-clear");
2198 mark_scenario_end("s3-clear");
2199 stage_markers(take_pending_markers());
2200
2201 stats.record(passes(10, 2, 2, 2));
2202 assert_eq!(
2203 stats.marker_log(),
2204 [
2205 "bench-scenario-start n=1 s3-clear",
2206 "bench-scenario-end n=1 s3-clear",
2207 ],
2208 "both edges collapsing onto one frame is the empty half-open \
2209 window a dropped op frame honestly produces"
2210 );
2211
2212 stats.record(passes(10, 2, 2, 2));
2213 assert_eq!(stats.marker_log().len(), 2, "staged markers emit once");
2214 }
2215
2216 #[cfg(feature = "perf-trace")]
2217 #[test]
2218 fn stage_markers_of_an_empty_batch_is_a_no_op() {
2219 let _guard = marker_test_guard(true);
2220 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, true);
2221
2222 stage_markers(take_pending_markers());
2223 stats.record(passes(10, 2, 2, 2));
2224
2225 assert!(stats.marker_log().is_empty());
2226 }
2227
2228 #[cfg(feature = "perf-trace")]
2229 #[test]
2230 fn an_overflowing_queue_drops_the_oldest_markers_and_reports_the_count() {
2231 // The bound (`MARKER_QUEUE_CAP`): a queue that is raised into far
2232 // faster than frames are recorded must stop growing, keep the
2233 // NEWEST edges (a live window needs those), and say how many it
2234 // discarded — on a line of its own, never inside a
2235 // `bench-scenario-*` line, whose shape is a parsed wire format.
2236 let _guard = marker_test_guard(true);
2237 let mut stats = FrameStats::with_capacity_enabled_and_raw(4, true, true);
2238
2239 let raised = MARKER_QUEUE_CAP + 3;
2240 for i in 0..raised {
2241 mark_scenario_start(&format!("s3-op{i}"));
2242 }
2243 stats.record(passes(10, 2, 2, 2));
2244
2245 let log = stats.marker_log();
2246 assert_eq!(
2247 log.len(),
2248 MARKER_QUEUE_CAP + 1,
2249 "a capped queue's worth of markers, plus one overflow notice"
2250 );
2251 assert_eq!(
2252 log[0], "bench-scenario-start n=1 s3-op3",
2253 "the three OLDEST were dropped, and the survivors keep the \
2254 unannotated marker shape"
2255 );
2256 assert_eq!(
2257 log[MARKER_QUEUE_CAP - 1],
2258 format!("bench-scenario-start n=1 s3-op{}", raised - 1),
2259 "the newest raised marker survived"
2260 );
2261 assert_eq!(
2262 log[MARKER_QUEUE_CAP],
2263 "frust-perf marker-overflow n=1 dropped=3"
2264 );
2265
2266 // The count travels with the batch that carried it, so a later frame
2267 // does not re-report it.
2268 mark_scenario_end("s3-done");
2269 stats.record(passes(10, 2, 2, 2));
2270 assert_eq!(
2271 stats.marker_log()[MARKER_QUEUE_CAP + 1..],
2272 ["bench-scenario-end n=2 s3-done"]
2273 );
2274 }
2275
2276 #[test]
2277 fn disabled_should_emit_and_emit_log_are_no_ops() {
2278 let mut stats = FrameStats::new_enabled(false);
2279 assert!(!stats.should_emit());
2280 stats.emit_log(); // must not panic; nothing to assert on directly
2281 assert_eq!(stats.total_frames(), 0);
2282 }
2283
2284 // ---------------------------------------------------------------
2285 // StartupSpans
2286 // ---------------------------------------------------------------
2287
2288 /// A deterministic fake clock advancing by a fixed step each call.
2289 struct FakeClock {
2290 elapsed: Duration,
2291 step: Duration,
2292 }
2293
2294 impl Clock for FakeClock {
2295 fn now(&mut self) -> Duration {
2296 let now = self.elapsed;
2297 self.elapsed += self.step;
2298 now
2299 }
2300 }
2301
2302 #[test]
2303 fn spans_recorded_in_order_with_monotonic_nonnegative_deltas() {
2304 let clock = FakeClock {
2305 elapsed: Duration::ZERO,
2306 step: Duration::from_millis(10),
2307 };
2308 let mut spans = StartupSpans::begin_with_enabled(clock, true);
2309 spans.record(SPAN_INIT_ENTRY);
2310 spans.record(SPAN_ADAPTER_READY);
2311 spans.record(SPAN_DEVICE_READY);
2312 spans.record(SPAN_RENDERER_READY);
2313
2314 let recorded = spans.spans();
2315 assert_eq!(recorded.len(), 4);
2316 assert_eq!(recorded[0].0, SPAN_INIT_ENTRY);
2317 assert_eq!(recorded[3].0, SPAN_RENDERER_READY);
2318
2319 let mut last = Duration::ZERO;
2320 for (_, delta) in recorded {
2321 assert!(*delta >= last, "deltas must be non-decreasing");
2322 assert!(*delta >= Duration::ZERO);
2323 last = *delta;
2324 }
2325 // begin() consumed the first fake-clock reading (0ms), so the first
2326 // recorded span is 10ms, the second 20ms, etc.
2327 assert_eq!(recorded[0].1, Duration::from_millis(10));
2328 assert_eq!(recorded[1].1, Duration::from_millis(20));
2329 assert_eq!(recorded[2].1, Duration::from_millis(30));
2330 assert_eq!(recorded[3].1, Duration::from_millis(40));
2331 }
2332
2333 #[test]
2334 fn disabled_spans_record_nothing() {
2335 let clock = FakeClock {
2336 elapsed: Duration::ZERO,
2337 step: Duration::from_millis(10),
2338 };
2339 let mut spans = StartupSpans::begin_with_enabled(clock, false);
2340 spans.record(SPAN_INIT_ENTRY);
2341 assert!(spans.spans().is_empty());
2342 spans.emit_log(); // no-op, must not panic
2343 }
2344
2345 #[test]
2346 fn closure_clock_satisfies_clock_trait() {
2347 let mut n = 0u64;
2348 let clock = move || {
2349 n += 10;
2350 Duration::from_millis(n)
2351 };
2352 let mut spans = StartupSpans::begin_with_enabled(clock, true);
2353 spans.record(SPAN_FIRST_REBUILD_DONE);
2354 spans.record(SPAN_FIRST_FRAME_PRESENTED);
2355 assert_eq!(spans.spans().len(), 2);
2356 assert!(spans.spans()[1].1 >= spans.spans()[0].1);
2357 }
2358}