diff --git a/core/src/render/frame_report.rs b/core/src/render/frame_report.rs index 62830a9..6813b5d 100644 --- a/core/src/render/frame_report.rs +++ b/core/src/render/frame_report.rs @@ -18,6 +18,12 @@ pub const JANK_THRESHOLD: Duration = Duration::from_nanos(16_666_667); /// this so `phase_stats` never has to report a phase as partially evicted. const RING_CAPACITY: usize = 16384; +/// How many measurable frame-to-frame gaps [`FrameReport:: +/// sustained_frame_hz`] needs before it will answer at all. A tenth of a +/// second's worth at any plausible rate -- enough for a rate to mean +/// something, and little enough that any real phase has it. +const MIN_CADENCE_SAMPLES: usize = 12; + /// One `mark_phase` call: the wall-clock instant and the (0-based, /// never-reset-by-`reset`-except-at-`reset`-time) absolute frame index at /// which a phase began -- `phase_stats` slices `index_ring` against this to @@ -43,6 +49,23 @@ pub struct PhaseStats { /// case is named in the `Display` rather than silently under-counted. pub frames: u64, pub duration: Duration, + /// Frames whose **work** exceeded the budget -- `total` minus the + /// swapchain wait, since a frame held back by the display was ready + /// on time and the display was not. + /// + /// Judging the total instead is what this did until 2026-09-09, and + /// it does not survive the app being *well* paced: a loop that draws + /// in 0.4ms and then waits its turn measures one whole refresh period + /// per frame, so every frame sits exactly on the budget and `late` + /// becomes a coin toss on noise. See [`Self::missed`] for the + /// question "did a frame fail to arrive", which is the one a reader + /// actually sees. + /// + /// On a backend that blocks in `present()` rather than in the + /// acquire -- GLES, and so this repo's emulator -- the wait lands in + /// `submit` instead and this over-counts. Named rather than + /// corrected, since correcting it would mean guessing which part of + /// `submit` was a wait. pub late: u64, pub late_percent: f64, pub p50: Duration, @@ -168,14 +191,23 @@ impl FrameParts { } } - /// What is left once the two measured waits are taken off: this - /// frame's own work. Saturating, since the three come from different - /// `Instant` pairs on a clock a caller owns. + /// What is left once the two measured waits are taken off: laying + /// out, shaping text, building primitives and recording the render + /// pass. Saturating, since the three come from different `Instant` + /// pairs on a clock a caller owns. pub fn build(&self) -> Duration { self.total .saturating_sub(self.acquire) .saturating_sub(self.submit) } + + /// Everything that was not waiting for the display's permission to + /// draw -- `build` plus `submit`. What a frame had to finish before + /// it could be shown, and so what a budget is meaningfully compared + /// against; see [`PhaseStats::late`]. + pub fn work(&self) -> Duration { + self.total.saturating_sub(self.acquire) + } } /// A per-frame wall-time report iris keeps of itself, because `dumpsys @@ -215,12 +247,22 @@ pub struct FrameReport { /// How long before each sample the *previous* frame was, same index, /// same lifetime -- the frame's own cadence rather than its cost. See /// [`PhaseStats::missed`] for why a report needs both. + /// + /// **`Duration::ZERO` means "no cadence information", not "no gap".** + /// Two frames say nothing about the display's rhythm unless the app + /// was actually trying to draw between them: the first frame after a + /// `reset` has nothing before it, and a frame that follows an *idle* + /// one is separated by however long nobody wanted anything drawn. + /// Counting those was this counter's first version, and it reported + /// a bench's own deliberate pauses as stutter -- 276 "missed" frames + /// for sixteen 300ms rests between flings, and 2410 for twelve + /// hundred 50ms gaps between keystrokes (Iris's phone, 2026-09-09). gap_ring: Box<[Duration; RING_CAPACITY]>, - /// When the last recorded frame was, on whatever clock the caller - /// dates its frames with -- `None` until the first one since a - /// `reset`, whose gap is unknowable and is recorded as zero rather - /// than guessed at. - last_at: Option, + /// When the last recorded frame was and whether it had asked for + /// another -- `None` until the first frame since a `reset`. The flag + /// is what makes the next frame's gap a measurement rather than a + /// record of how long the app sat idle. + last_frame: Option<(Instant, bool)>, /// The absolute (0-based, since the last `reset`) frame index each /// `ring`/`submit_ring` slot's sample belongs to -- what `phase_stats` /// slices against `PhaseMark::start_index` to tell which recorded @@ -307,7 +349,7 @@ impl FrameReport { submit_ring: Box::new([Duration::ZERO; RING_CAPACITY]), acquire_ring: Box::new([Duration::ZERO; RING_CAPACITY]), gap_ring: Box::new([Duration::ZERO; RING_CAPACITY]), - last_at: None, + last_frame: None, index_ring: Box::new([0; RING_CAPACITY]), len: 0, pos: 0, @@ -323,12 +365,14 @@ impl FrameReport { /// with nothing but a total passes `FrameParts::whole(total)`, which /// says so in the type instead of leaving the report to guess from a /// zero. - pub fn record(&mut self, at: Instant, parts: FrameParts) { - self.gap_ring[self.pos] = match self.last_at { - Some(last) => at.saturating_duration_since(last), - None => Duration::ZERO, + pub fn record(&mut self, at: Instant, parts: FrameParts, animating: bool) { + self.gap_ring[self.pos] = match self.last_frame { + Some((last, true)) => at.saturating_duration_since(last), + // Nothing was moving, so the distance to this frame is idle + // time rather than cadence -- see `gap_ring`'s own doc. + Some((_, false)) | None => Duration::ZERO, }; - self.last_at = Some(at); + self.last_frame = Some((at, animating)); self.ring[self.pos] = parts.total; self.submit_ring[self.pos] = parts.submit; self.acquire_ring[self.pos] = parts.acquire; @@ -352,7 +396,7 @@ impl FrameReport { self.pos = 0; self.total_frames = 0; self.janky_frames = 0; - self.last_at = None; + self.last_frame = None; self.phases.clear(); } @@ -455,6 +499,7 @@ impl FrameReport { .iter() .filter(|&&j| self.index_ring[j] > phase.start_index) .map(|&j| self.gap_ring[j]) + .filter(|gap| !gap.is_zero()) .filter(|gap| *gap > budget.mul_f64(1.5)) .map(|gap| (gap.as_secs_f64() / budget.as_secs_f64()).round() as u64 - 1) .sum(); @@ -463,7 +508,10 @@ impl FrameReport { let submit_p50 = part_p50(&|j| self.submit_ring[j]); samples.sort_unstable(); let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)]; - let late = samples.iter().filter(|&&d| d > budget).count() as u64; + let late = slots + .iter() + .filter(|&&j| self.parts(j).work() > budget) + .count() as u64; PhaseStats { name: phase.name.clone(), frames, @@ -484,6 +532,34 @@ impl FrameReport { .collect() } + /// The rate frames were actually **sustained** at, in Hz, over the + /// stretches where the app was animating -- measurable gaps divided + /// into their own total, so idle time is excluded by construction. + /// + /// **This is a floor on the display's refresh rate, never a reading + /// of it.** You cannot observe a cadence faster than you draw, so an + /// app that never keeps up says nothing about the panel; a caller + /// resolves it by taking whichever of this and the platform's own + /// answer is *larger*. That matters in both directions and each has + /// been seen: `Display.getRefreshRate()` answered 60 for a run that + /// sustained 120.3fps, because a phone that varies its rate answers + /// with whatever mode it happens to be in when asked -- and this + /// answered 88 on an emulator whose display is 60Hz and whose app + /// managed 51, because an earlier version took the fastest tenth of + /// the gaps rather than the sustained rate. The fastest tenth is a + /// measurement of the best moment; the budget wants the rhythm. + /// + /// `None` under `MIN_CADENCE_SAMPLES` measurable gaps, which is the + /// honest answer for a run too short or too idle to have seen one. + pub fn sustained_frame_hz(&self) -> Option { + let gaps = self.gap_ring[..self.len].iter().filter(|g| !g.is_zero()); + let (count, total) = gaps.fold((0u32, Duration::ZERO), |(n, sum), g| (n + 1, sum + *g)); + if (count as usize) < MIN_CADENCE_SAMPLES || total.is_zero() { + return None; + } + Some(count as f32 / total.as_secs_f32()) + } + /// `None` if nothing has been recorded since the last reset -- the /// "no frames recorded, scroll first" case, not a zeroed report that /// would read as a real (perfect) measurement. @@ -534,9 +610,11 @@ impl FrameReport { return (0, 0.0); } let budget = Duration::from_secs_f64(1.0 / refresh_hz as f64); - let late = self.ring[..self.len] - .iter() - .filter(|&&d| d > budget) + // The frame's work, not its total -- the same rule and the same + // reason as `PhaseStats::late`, which this is the run-wide half + // of. + let late = (0..self.len) + .filter(|&j| self.parts(j).work() > budget) .count() as u64; (late, 100.0 * late as f64 / self.len as f64) } @@ -560,7 +638,11 @@ mod tests { #[test] fn one_frame_is_every_percentile_and_the_worst() { let mut r = FrameReport::new(); - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(10))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(10)), + true, + ); let stats = r.report().unwrap(); assert_eq!(stats.total_frames, 1); assert_eq!(stats.p50, Duration::from_millis(10)); @@ -575,7 +657,11 @@ mod tests { // 100 samples, 1ms..=100ms, fed out of order so the ring's own // order is not what gives the right answer -- the sort has to. for ms in (1..=100).rev() { - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(ms))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(ms)), + true, + ); } let stats = r.report().unwrap(); assert_eq!(stats.total_frames, 100); @@ -591,10 +677,12 @@ mod tests { r.record( Instant::now(), FrameParts::whole(Duration::from_nanos(16_666_667)), + true, ); // exactly on budget: not janky r.record( Instant::now(), FrameParts::whole(Duration::from_nanos(16_666_668)), + true, ); // one ns over: janky let stats = r.report().unwrap(); assert_eq!(stats.janky_percent, 50.0); @@ -606,12 +694,20 @@ mod tests { // the percentage must reset to 0, not divide by a stale count. let mut r = FrameReport::new(); for _ in 0..10 { - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(50))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(50)), + true, + ); } assert_eq!(r.report().unwrap().janky_percent, 100.0); r.reset(); assert!(r.report().is_none()); - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(1)), + true, + ); assert_eq!(r.report().unwrap().janky_percent, 0.0); } @@ -621,7 +717,11 @@ mod tests { // not fabricate a GPU-wait number -- it reads as zero, and the CPU // half reads as the whole frame. let mut r = FrameReport::new(); - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(20))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(20)), + true, + ); let stats = r.report().unwrap(); assert_eq!(stats.cpu_p50, Duration::from_millis(20)); assert_eq!(stats.gpu_wait_p50, Duration::ZERO); @@ -642,6 +742,7 @@ mod tests { acquire: Duration::from_millis(acquire), submit: Duration::from_millis(submit), }, + true, ); } let stats = r.report().unwrap(); @@ -667,6 +768,7 @@ mod tests { r.record( base + budget * step, FrameParts::whole(Duration::from_millis(2)), + true, ); } let phase = r.phase_stats(Instant::now(), 60.0).remove(0); @@ -674,6 +776,109 @@ mod tests { assert_eq!(phase.missed, 3); } + #[test] + fn an_idle_gap_is_not_a_missed_frame() { + // What the first version of this counter got wrong on Iris's + // phone: a bench rests 300ms between flings and types one + // character per 50ms, and every one of those gaps was reported as + // stutter (276 and 2410 "missed" frames, which is exactly the + // rests). A frame that did not ask for another one is idle, and + // the distance to whatever comes next says nothing. + let mut r = FrameReport::new(); + let base = Instant::now(); + let budget = Duration::from_nanos(16_666_667); + r.mark_phase("fling"); + // Two frames of real animation, then one that stops animating, + // then a long rest before the next burst. + r.record(base, FrameParts::whole(Duration::ZERO), true); + r.record(base + budget, FrameParts::whole(Duration::ZERO), true); + r.record(base + budget * 2, FrameParts::whole(Duration::ZERO), false); + r.record( + base + Duration::from_millis(300), + FrameParts::whole(Duration::ZERO), + true, + ); + let phase = r.phase_stats(Instant::now(), 60.0).remove(0); + assert_eq!( + phase.missed, 0, + "a rest nobody was waiting through is not a stutter" + ); + } + + #[test] + fn a_sustained_120hz_run_measures_120_whatever_the_platform_says() { + // Iris's phone, 2026-09-09: the display reported 60Hz for a run + // that drew at 120, so every phase was judged against twice the + // budget it should have been. + let mut r = FrameReport::new(); + let base = Instant::now(); + let period = Duration::from_nanos(8_333_333); + for step in 0..120u32 { + r.record( + base + period * step, + FrameParts::whole(Duration::ZERO), + true, + ); + } + let hz = r.sustained_frame_hz().expect("120 gaps is plenty"); + assert!((hz - 120.0).abs() < 1.0, "measured {hz}Hz, expected ~120"); + } + + #[test] + fn an_app_that_cannot_keep_up_does_not_claim_a_faster_display() { + // The other direction, and the one the first version of this got + // wrong: this repo's emulator draws about 51fps on a 60Hz + // display, and taking the fastest tenth of the gaps reported + // 88Hz -- a budget no frame there could meet, invented out of the + // app's best moments. A sustained rate cannot do that, which is + // what makes a caller's `max` against the platform's own answer + // safe in both directions. + let mut r = FrameReport::new(); + let base = Instant::now(); + let mut at = base; + for step in 0..120u32 { + // Mostly slow with an occasional quick pair -- the shape that + // fooled the percentile. + at += if step % 10 == 0 { + Duration::from_millis(8) + } else { + Duration::from_millis(20) + }; + r.record(at, FrameParts::whole(Duration::ZERO), true); + } + let hz = r.sustained_frame_hz().expect("120 gaps is plenty"); + assert!( + hz < 60.0, + "measured {hz}Hz, which claims more than was drawn" + ); + } + + #[test] + fn a_frame_held_back_by_the_display_is_not_late() { + // The signature of a well-paced loop: 0.4ms of work and the rest + // of the refresh period spent waiting its turn. Judging the total + // calls every one of those frames late; judging the work calls + // none of them late, which is what they are. + let mut r = FrameReport::new(); + let base = Instant::now(); + let period = Duration::from_nanos(8_333_333); + r.mark_phase("fling"); + for step in 0..30u32 { + r.record( + base + period * step, + FrameParts { + total: Duration::from_micros(8_300), + acquire: Duration::from_micros(7_900), + submit: Duration::from_micros(200), + }, + true, + ); + } + let phase = r.phase_stats(Instant::now(), 120.0).remove(0); + assert_eq!(phase.late, 0); + assert_eq!(r.late_at_hz(120.0).0, 0); + } + #[test] fn a_phase_does_not_inherit_the_pause_before_it() { // The half the fix above had no reason to touch: a bench rests @@ -685,13 +890,21 @@ mod tests { let budget = Duration::from_nanos(16_666_667); r.mark_phase("fling"); for step in [0u32, 1, 2] { - r.record(base + budget * step, FrameParts::whole(Duration::ZERO)); + r.record( + base + budget * step, + FrameParts::whole(Duration::ZERO), + true, + ); } // A second of rest, then the next phase starts clean. let after = base + Duration::from_secs(1); r.mark_phase("type"); for step in [0u32, 1, 2] { - r.record(after + budget * step, FrameParts::whole(Duration::ZERO)); + r.record( + after + budget * step, + FrameParts::whole(Duration::ZERO), + true, + ); } let phases = r.phase_stats(Instant::now(), 60.0); assert_eq!(phases[0].missed, 0); @@ -708,6 +921,7 @@ mod tests { r.record( Instant::now(), FrameParts::whole(Duration::from_millis(1 + (i % 5) as u64)), + true, ); } let stats = r.report().unwrap(); @@ -722,7 +936,11 @@ mod tests { #[test] fn no_marks_means_no_phases() { let mut r = FrameReport::new(); - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(5))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(5)), + true, + ); assert!(r.phase_stats(Instant::now(), 60.0).is_empty()); } @@ -731,11 +949,19 @@ mod tests { let mut r = FrameReport::new(); r.mark_phase("a"); for _ in 0..5 { - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(10))); // 10ms: late at 60Hz (16.7ms budget)... no, 10<16.7, not late + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(10)), + true, + ); // 10ms: late at 60Hz (16.7ms budget)... no, 10<16.7, not late } r.mark_phase("b"); for _ in 0..3 { - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(20))); // 20ms: late at 60Hz + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(20)), + true, + ); // 20ms: late at 60Hz } let now = Instant::now(); let phases = r.phase_stats(now, 60.0); @@ -757,7 +983,11 @@ mod tests { fn the_last_phase_runs_until_now() { let mut r = FrameReport::new(); r.mark_phase("only"); - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(1)), + true, + ); std::thread::sleep(Duration::from_millis(20)); let now = Instant::now(); let phases = r.phase_stats(now, 60.0); @@ -769,7 +999,11 @@ mod tests { fn reset_clears_phase_marks() { let mut r = FrameReport::new(); r.mark_phase("a"); - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(1)), + true, + ); r.reset(); assert!(r.phase_stats(Instant::now(), 60.0).is_empty()); } @@ -778,7 +1012,11 @@ mod tests { fn late_at_hz_uses_the_given_refresh_rate_not_the_fixed_60hz_constant() { let mut r = FrameReport::new(); // 10ms is under 60Hz's 16.7ms budget but over 120Hz's 8.3ms one. - r.record(Instant::now(), FrameParts::whole(Duration::from_millis(10))); + r.record( + Instant::now(), + FrameParts::whole(Duration::from_millis(10)), + true, + ); assert_eq!(r.late_at_hz(60.0), (0, 0.0)); assert_eq!(r.late_at_hz(120.0), (1, 100.0)); } diff --git a/src/android/view.rs b/src/android/view.rs index 183fc45..17b8047 100644 --- a/src/android/view.rs +++ b/src/android/view.rs @@ -555,7 +555,7 @@ impl IrisViewPeer { self.state .android_state_mut() .frame_report - .record(now, parts); + .record(now, parts, animating); crate::diagnostics::log_frame(&self.render, now, parts, animating); if crate::diagnostics::trace_enabled() { let ui_state = self.state.android_state();