iris-ai/iris
1
0 Fork 0
forked from iris/iris
Code Pull Requests Activity

The frame report says what it measured: idle is not stutter, waiting is not late

Browse Source 
Iris's phone came back "now THAT is smooth", and reading that run against
the bench's own timings found three things the report was getting wrong
-- two of them shipped yesterday in the fix for the last three.

`missed vsyncs` counted idleness. Every gap between frames was treated as
cadence, so the bench's own pauses read as stutter: 276 for sixteen 300ms
rests between flings, 2410 for twelve hundred 50ms keystroke gaps, 821
for four hundred 50ms stream gaps -- each within a few percent of the
arithmetic. A gap now measures anything only if the frame before it had
asked for another one.

`late` counted the swapchain wait as cost. A well-paced loop spends each
frame blocked in the acquire, so its total sits at exactly one refresh
period and every frame lands on the budget boundary -- 0.4ms of work and
5.7ms of waiting is not a late frame. It is judged on `FrameParts::work`.

And the refresh rate is the larger of what the platform claims and what
the run sustained, because each can only be wrong one way.
`Display.getRefreshRate()` answered 60 for a run that drew 3405 frames in
33.1s, since a phone that varies its rate answers with whatever mode it
is in when asked. The first attempt at measuring it instead took the
fastest tenth of the gaps and reported 88Hz for this repo's 60Hz
emulator, whose app manages 54 -- a budget no frame there could meet,
invented out of the app's best moments, and caught only by running the
corrected report on the emulator before shipping it. A sustained rate is
a floor and cannot do that. Both are printed when they disagree.

Also corrected in the docs: "103fps on a 120Hz screen" divided the fling
phase by its whole duration, rests included. Both runs sustained ~120.3fps
through the motion, so the callback ordering was never costing frames --
what changed is the clock, which moves no frame count at all, which is
exactly why nothing in a report could show it.

`fling_profile.rs` is `frame_profile.rs` and gained a stream run, which
says where the frame time now is: folding an arriving event is 0.35ms and
applying the diff 0.41ms, while the frame is 3.86ms here and 9.5ms on the
phone. 401 events move the item count 652 -> 654, so nearly every one is
a delta into the same row -- the cost is re-shaping one growing message,
not `fold_event`'s per-event clone, which was the hypothesis and is what
measuring it ruled out.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
irisandClaude Opus 5 committed 2026-09-09 01:08:30 -04:00
1 parent 144c402181
commit faa047efbd
2 files changed
+271 -33
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

core/src/render/frame_report.rs
+270 -32
View File
@@ -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<Instant>,
/// 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<f32> {
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));
}
src/android/view.rs
+1 -1
View File
@@ -555,7 +555,7 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
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();