iris/ai-app
1
0 Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki 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 42d54eec95
commit 9bf714fa2e
6 files changed
+457 -57
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

AGENTS.md
+21 -14
View File
@@ -389,21 +389,28 @@ Each exists because something was invisible without it.
since the rig lives in iris and the app's examples do not). The emulator is for JNI, the IME, insets, the surface
lifecycle and one verification run before a build goes to the phone --
not for iterating on layout.
- **`app-rust/tests/fling_profile.rs`** is what a fling frame costs on
the CPU, at layer 1 -- `cargo test --release --test fling_profile --
--ignored --nocapture`, from `app-rust/`. It flings the real transcript
screen over the bench fixture eight times, out and back, and prints the
per-frame distribution with a count of how many frames did any layout at
all. `#[ignore]`d and assertion-free, so `run-tests.sh` neither runs it
nor can fail on it; **release or the numbers mean nothing**, since text
shaping dominates. Two things it established on 2026-09-09 that are
worth not re-deriving: only about one fling frame in six lays anything
out (the rest are moved on the GPU through `move_offsets`), and the
- **`app-rust/tests/frame_profile.rs`** is what a frame costs on the CPU,
at layer 1 -- `cargo test --release --test frame_profile -- --ignored
--nocapture`, from `app-rust/`. Two runs: a fling over the bench
fixture eight times out and back, and a reply streaming into it one
event at a time. `#[ignore]`d and assertion-free, so `run-tests.sh`
neither runs it nor can fail on it; **release or the numbers mean
nothing**, since text shaping dominates. It cannot answer anything
about the GPU, the swapchain or the phone's own clock.
What it established on 2026-09-09, worth not re-deriving. A **fling**
is not CPU-bound: only about one frame in six lays anything out (the
rest are moved on the GPU through `move_offsets`), and the
multi-millisecond spikes are all in the *first* pass over a stretch of
transcript -- every later pass over the same rows is p99 0.26ms. So a
warm fling is not CPU-bound in iris, and a phone report showing
otherwise is measuring something else. It cannot answer anything about
the GPU, the swapchain or the phone's own clock.
transcript -- every later pass over the same rows is p99 0.26ms. A
**streamed event** is, and it is not where it looks: folding the event
is 0.35ms and applying the diff to the widget tree is 0.41ms, while the
*frame* is 3.86ms here and 9.5ms on Iris's phone. 401 streamed events
move the item count from 652 to 654, so almost every one is a delta
into the same row -- the cost is re-laying out and re-shaping one
growing message on every delta, not the fold. (The fold was the
hypothesis, from `foldEvent`'s Compose lesson under "Things that have
bitten"; measuring it is what ruled it out.)
- **The emulator is a GLES rig, deliberately** (Iris, 2026-09-08;
docs/RUST.md). Its guest has no hardware Vulkan -- only SwiftShader
in software -- while its GLES *is* the host's real GPU through virgl at
app-rust/src/android/bench_client.rs
+35 -5
View File
@@ -742,10 +742,12 @@ impl BenchClient {
let platform = self.platform.clone();
let stream_tail = self.stream_tail.clone();
let ime_state = self.ime_state.clone();
let refresh_hz = platform
.as_ref()
.and_then(|p| p.refresh_rate_hz())
.unwrap_or(60.0);
// What the platform *says*, kept apart from what the run measured
// -- see where the two are resolved below. A phone that varies its
// refresh rate answers with whichever mode it is in when asked, so
// this alone judged a 120Hz run against a 60Hz budget (Iris's
// phone, 2026-09-09).
let platform_hz = platform.as_ref().and_then(|p| p.refresh_rate_hz());
let cpu_start = process_cpu_ms();
// Read at the start as well as the end, because the switch is on
// screen while a run is going: a report that only asked afterwards
@@ -802,6 +804,33 @@ impl BenchClient {
ctx.update(move |state: &mut BenchClient, rsc| {
state.running = false;
let now = Instant::now();
// **The larger of the two, because each can only be wrong
// one way.** The platform under-reports a display that
// varies its rate (60 for a run that sustained 120 on
// Iris's phone), and the sustained rate is a floor -- an
// app that cannot keep up says nothing about the panel.
// Printed together whenever they disagree, so the
// resolution is visible rather than silent.
let drawn_hz = state.android_state().frame_report.sustained_frame_hz();
let refresh_hz = match (drawn_hz, platform_hz) {
(Some(d), Some(p)) => d.max(p),
(Some(d), None) => d,
(None, Some(p)) => p,
(None, None) => 60.0,
};
let hz_line = match (drawn_hz, platform_hz) {
(Some(d), Some(p)) if d > p + 5.0 => format!(
" (sustained {d:.0}fps, so at least that; the display reported {p:.0}Hz)"
),
(Some(d), Some(_)) => format!(" (as the display reports it; drew {d:.0}fps)"),
(Some(d), None) => {
format!(" (sustained {d:.0}fps; the display would not say)")
}
(None, Some(_)) => {
" (as the display reports it; too few frames to measure)".to_string()
}
(None, None) => " (assumed -- neither measured nor reported)".to_string(),
};
let phase_lines: String = state
.android_state()
.frame_report
@@ -819,7 +848,8 @@ impl BenchClient {
let (late, late_pct) =
state.android_state().frame_report.late_at_hz(refresh_hz);
format!(
"frames:\n {} frames over {:.1}s at {:.0}Hz ({:.1}ms budget)\n \
"frames:\n {} frames over {:.1}s at {:.0}Hz{hz_line} ({:.1}ms \
budget)\n \
late: {late} ({late_pct:.1}%)\n total p50 {:.1}ms p90 {:.1}ms \
p99 {:.1}ms\n worst {:.1}ms\n build_p50 {:.1}ms acquire_p50 \
{:.1}ms submit_p50 {:.1}ms",
app-rust/tests/fling_profile.rs → app-rust/tests/frame_profile.rs
+73 -4
View File
@@ -1,12 +1,16 @@
//! A profiling run rather than a test: what a fling frame costs on the
//! CPU, at layer 1 (docs/RUST.md's "Three test layers") -- the real
//! Profiling runs rather than tests: what a frame costs on the CPU, at
//! layer 1 (docs/RUST.md's "Three test layers") -- the real
//! transcript screen over the real bench fixture, with no window, no
//! compositor and no GPU, on a clock this file owns. It exists so "the
//! fling stutters" can be attributed rather than guessed at, and it is
//! kept between investigations rather than rewritten each time (Iris,
//! 2026-09-09: "please keep the profiling rig around for future use").
//!
//! cargo test --release --test fling_profile -- --ignored --nocapture
//! cargo test --release --test frame_profile -- --ignored --nocapture
//!
//! Two runs today: `what_a_fling_frame_costs` (scrolling over transcript
//! that is already folded) and `what_a_streamed_event_costs` (a reply
//! arriving into it).
//!
//! `#[ignore]`d because it asserts nothing -- it prints a distribution,
//! so `run-tests.sh` neither runs it nor can fail on it. **Release, or
@@ -115,7 +119,72 @@ fn what_a_fling_frame_costs() {
t += 200;
}
println!("\nall {PASSES} passes, primitives={}", h.render.active_primitive_count());
println!(
"\nall {PASSES} passes, primitives={}",
h.render.active_primitive_count()
);
summarise("frame", &all_frames);
summarise("layout", &all_layouts);
}
/// The other half of a bench run, and since 2026-09-09 the expensive one:
/// what it costs to fold one arriving event into the transcript and show
/// it. The bench's stream phase measured `build p50 9.5ms` on Iris's
/// phone against a fling's 0.4ms, so this is where the frame time now is.
///
/// Reports the fold and the widget-tree apply separately, because they
/// are different problems with different fixes -- and reports how the
/// cost moves as the transcript grows, which is the shape that says
/// whether the work is per-event or per-event-times-transcript.
#[test]
#[ignore]
fn what_a_streamed_event_costs() {
let mut h = Harness::new(phone_size(), PHONE_SCALE);
let opened = ai_app::ui::fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds");
h.frame(0);
h.frame(PHONE_FRAME_MS);
let mut items = opened.items;
println!(
"backlog: {} items, then {} streamed events",
items.len(),
opened.stream_tail.len()
);
let mut fold = Vec::new();
let mut apply = Vec::new();
let mut frame = Vec::new();
let mut t = PHONE_FRAME_MS;
for (n, event) in opened.stream_tail.iter().enumerate() {
let at = Instant::now();
let old = items.clone();
let folded = ai_app::client::transcript_fold::fold_event(&items, event);
fold.push(at.elapsed());
items = folded;
let at = Instant::now();
opened.screen.apply(&mut h.rsc, &old, &items);
apply.push(at.elapsed());
t += PHONE_FRAME_MS;
let at = Instant::now();
h.frame(t);
frame.push(at.elapsed());
// Where the cost sits as the transcript grows -- one line early,
// one late, is enough to see a per-event cost from a quadratic.
if n == 0 || n == opened.stream_tail.len() - 1 {
println!(
" event {n:>3} of {}: items={} fold {:?} apply {:?}",
opened.stream_tail.len(),
items.len(),
fold[n],
apply[n],
);
}
}
summarise("fold", &fold);
summarise("apply", &apply);
summarise("frame", &frame);
}
docs/RUST.md
+57 -1
View File
@@ -472,11 +472,67 @@ the view keeps **one**, anchored by whichever of a touch or a frame
arrives first, so a fling is advanced on the clock its velocity was
measured on.
What the CPU side is *not*: `app-rust/tests/fling_profile.rs` (AGENTS.md's
What the CPU side is *not*: `app-rust/tests/frame_profile.rs` (AGENTS.md's
rig list) puts iris's own per-frame work during a warm fling at p99
0.26ms, with only one frame in six laying anything out at all. The
multi-millisecond spikes are first-pass only.
**The result, from Iris's phone the same day: "now THAT is smooth. I
couldn't actually see any lag myself."** With three corrections to what
the report meant, found by reading that run against the bench's own
timings:
- **The frame rate never was the problem, and the first reading of it was
wrong.** "103fps on a 120Hz screen" divided the fling phase's frames by
its whole duration, which includes sixteen deliberate 300ms rests. Both
runs sustained ~120.3fps through the motion itself. So the callback
ordering was not costing frames -- what changed is the *clock*, which
moves no frame count and is the whole point: an uneven sample of an
even cadence cannot show up in any frame-time percentile.
- **`missed vsyncs` counted idleness.** Every gap was treated as cadence,
so the bench's own pauses read as stutter: 276 for sixteen 300ms rests,
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.
- **`late` counted the vsync 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. It is
judged on `FrameParts::work` -- the total minus the acquire -- now.
- **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. And `FrameReport::sustained_frame_hz` is a *floor*:
an app that cannot keep up says nothing about the panel. The first
version of it took the fastest tenth of the gaps rather than the
sustained rate and reported **88Hz for this repo's 60Hz emulator**,
whose app manages 51 -- 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. The two are printed together
whenever they disagree.
The signature of the fixed loop, from that run: `build p50 0.4ms,
acquire p50 5.7ms, submit p50 1.7ms` -- four tenths of a millisecond of
work and the rest of the refresh period spent waiting its turn.
### Streaming is where the frame time is now (2026-09-09)
Measured after the fling was fixed, and it is not where it looks.
`frame_profile.rs`'s stream run: folding an arriving event is 0.35ms and
applying the diff to the widget tree is 0.41ms, while the frame that
follows is 3.86ms on this desktop and 9.5ms of `build` on Iris's phone --
over a 120Hz budget on its own. 401 streamed events move the item count
from 652 to 654, so nearly every one is a *delta into the same row*: the
cost is re-laying out and re-shaping one growing markdown message on
every delta.
`fold_event`'s `items.to_vec()` per event was the hypothesis -- it is the
exact shape of the Compose lesson in AGENTS.md's "Things that have
bitten" -- and measuring it is what ruled it out. **Not yet designed**:
making a row's text append incrementally rather than reshape touches how
`TranscriptRow` holds its shaped text, which is load-bearing enough to
raise before building.
### The Android release profile is `opt-level = 3`, not `"s"` (2026-09-09)
The table above was measured in bytes only. `"s"` costs the loop
iris/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));
}
iris/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();