Fling: the vsync clock, the frame ask, and a report that can say what it measured

Iris, from her phone: "some stuttering when flinging in particular.
Harder to notice with my finger directly moving the scroll." Her fling
phase was 103fps on a 120Hz screen at p50 6.3ms.

Two of the four things found are corrections to the instrument, not the
renderer. The swapchain acquire -- `get_current_texture`, which *blocks*
until the compositor frees an image -- was inside the span the report
called iris's CPU work, so a fling comfortably ahead of the display read
as milliseconds of being slow. A frame is now three measured parts
(`FrameParts`: build, acquire, submit), per phase as well as per run. And
nothing could say a frame was never *produced*: `late` counts frames that
cost too much, which a reader does not see, while a frame that never
happens leaves the last one up for two refreshes, which is the stutter.
`PhaseStats::missed` counts vsyncs nothing was drawn for. It closes on
the emulator: 1548 frames + 452 missed over 33.0s at 60Hz is 1980
vsyncs.

The other two are the frame loop. `Choreographer.postFrameCallback`
schedules for the next vsync after the call, and iris asked at the *end*
of the callback -- so any frame whose work ran past the boundary
registered too late and got the vsync after, one frame over budget
silently costing a second. It is asked for immediately after
`tick_animations` now, on both backends. And the fling was advanced on
`Instant::now()` rather than the vsync `do_frame` carries: frames are
presented on an even cadence whatever clock computes them, so sampling
the spline at "whenever the callback ran" moves the content unevenly with
no frame late enough to appear in any report -- and a drag never had it,
which is the asymmetry Iris described. `PointerClock` is `DeviceClock`
and the view keeps one, anchored by whichever of a touch or a frame comes
first, so a fling is advanced on the clock its velocity was measured on.

`opt-level` for the Android release build goes from "s" to 3. The table
in RUST.md picked "s" on bytes alone; over the same warm fling eight
times iris's own per-frame work is p90 0.15ms/p99 0.42ms at "s" against
p90 0.09ms/p99 0.26ms at 3, for 1.8 MB of arm64 APK.

`app-rust/tests/fling_profile.rs` is the rig that established what a
fling frame actually costs and is kept for next time (Iris: "please keep
the profiling rig around for future use"): only one frame in six lays
anything out, and the multi-millisecond spikes are all first-pass.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
irisandClaude Opus 5 committed 2026-09-09 00:49:28 -04:00
1 parent 227f5e1295
commit 144c402181
10 files changed
+470 -144

No files matched your search

+285 -57
View File
@@ -49,6 +49,29 @@ pub struct PhaseStats {
pub p90: Duration, pub p90: Duration,
pub p99: Duration, pub p99: Duration,
pub worst: Duration, pub worst: Duration,
/// This phase's own medians of the three parts a frame is made of --
/// see [`FrameParts`]. Per phase as well as per run because the parts
/// do not divide the same way in every phase: a fling frame spends
/// most of itself in `acquire` (waiting its turn at the swapchain,
/// which is the display pacing the app and not work) while a
/// streaming frame spends it in `build`, and a run-wide median cannot
/// say that.
/// Vsyncs that went by with no frame produced for them, counted from
/// the gap between consecutive frames rather than from their cost.
///
/// **`late` and this are different questions and the second is the
/// one a reader sees.** A frame can be over budget and still be shown
/// on the next vsync; a frame that is never produced leaves the
/// previous one on screen for two refreshes, which is the stutter.
/// Nothing in a report could say this before 2026-09-09 -- the two
/// were folded together under `late`, so "we drew every frame, some
/// slowly" and "we skipped 1 frame in 8" read identically.
///
/// Zero on the first frame of a run, whose gap is unknowable.
pub missed: u64,
pub build_p50: Duration,
pub acquire_p50: Duration,
pub submit_p50: Duration,
/// `false` if this phase's frame count exceeds how many samples of it /// `false` if this phase's frame count exceeds how many samples of it
/// are still in the ring -- the percentiles above are then computed /// are still in the ring -- the percentiles above are then computed
/// over whatever survived, not the whole phase. UI_RULES.md: this is /// over whatever survived, not the whole phase. UI_RULES.md: this is
@@ -71,7 +94,11 @@ impl std::fmt::Display for PhaseStats {
" (ring evicted some of this phase)" " (ring evicted some of this phase)"
}, },
)?; )?;
writeln!(f, " late: {} ({:.1}%)", self.late, self.late_percent)?; writeln!(
f,
" late: {} ({:.1}%) missed vsyncs: {}",
self.late, self.late_percent, self.missed,
)?;
writeln!( writeln!(
f, f,
" total p50 {:.1}ms p90 {:.1}ms p99 {:.1}ms", " total p50 {:.1}ms p90 {:.1}ms p99 {:.1}ms",
@@ -79,10 +106,78 @@ impl std::fmt::Display for PhaseStats {
self.p90.as_secs_f64() * 1000.0, self.p90.as_secs_f64() * 1000.0,
self.p99.as_secs_f64() * 1000.0, self.p99.as_secs_f64() * 1000.0,
)?; )?;
writeln!(
f,
" build p50 {:.1}ms acquire p50 {:.1}ms submit p50 {:.1}ms",
self.build_p50.as_secs_f64() * 1000.0,
self.acquire_p50.as_secs_f64() * 1000.0,
self.submit_p50.as_secs_f64() * 1000.0,
)?;
write!(f, " worst {:.1}ms", self.worst.as_secs_f64() * 1000.0) write!(f, " worst {:.1}ms", self.worst.as_secs_f64() * 1000.0)
} }
} }
/// The parts one frame's wall time divides into, measured rather than
/// inferred: what a caller hands [`FrameReport::record`].
///
/// The three are consecutive and together they are `total`, so whatever
/// is left after `acquire` and `submit` is the frame's own work -- laying
/// out, shaping text, building primitives and recording the render pass.
/// That leftover is what a report calls `build`.
///
/// **`acquire` is the one that is not work.** It is the wait inside
/// `Surface::get_current_texture` for a swapchain image to come free,
/// which is the display pacing the app: an app that draws faster than the
/// screen refreshes spends *most* of every frame there, and that is the
/// healthy state rather than a slow one. It was inside the CPU half until
/// 2026-09-09, which made a fling's frames read as several milliseconds
/// of iris being slow when they were milliseconds of iris waiting its
/// turn -- UI_RULES.md's rule against presenting an inferred value as a
/// measured one, arriving in a diagnostic.
#[derive(Clone, Copy, Default, Debug)]
pub struct FrameParts {
/// Redraw start to after `present()` was called -- the span the whole
/// report is about.
pub total: Duration,
/// The wait for a swapchain image (`get_current_texture`).
pub acquire: Duration,
/// `queue.submit` plus `present()`.
pub submit: Duration,
}
impl FrameParts {
/// A frame measured as one span, with no parts -- honest for a caller
/// that never measured them (they read as zero and `build` reads as
/// the whole frame) rather than fabricating a split.
pub fn whole(total: Duration) -> Self {
Self {
total,
acquire: Duration::ZERO,
submit: Duration::ZERO,
}
}
/// The two waits a renderer's `draw` measures, with `total` left at
/// zero for the frame loop around it to fill in -- it is the only
/// caller that knows when the frame started.
pub fn waits(acquire: Duration, submit: Duration) -> Self {
Self {
total: Duration::ZERO,
acquire,
submit,
}
}
/// 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.
pub fn build(&self) -> Duration {
self.total
.saturating_sub(self.acquire)
.saturating_sub(self.submit)
}
}
/// A per-frame wall-time report iris keeps of itself, because `dumpsys /// A per-frame wall-time report iris keeps of itself, because `dumpsys
/// gfxinfo` cannot see a `SurfaceView`'s own GPU-drawn frames at all /// gfxinfo` cannot see a `SurfaceView`'s own GPU-drawn frames at all
/// (RUST.md's I5 box, "Measurements taken" (b)): it instruments Android's /// (RUST.md's I5 box, "Measurements taken" (b)): it instruments Android's
@@ -111,8 +206,21 @@ pub struct FrameReport {
/// same lifetime -- kept as a second ring rather than a ring of pairs so /// same lifetime -- kept as a second ring rather than a ring of pairs so
/// the existing `ring`/percentile code above is untouched (RUST.md's I5 /// the existing `ring`/percentile code above is untouched (RUST.md's I5
/// "Where iris's frame time goes" CPU/GPU split, added 2026-09-05). /// "Where iris's frame time goes" CPU/GPU split, added 2026-09-05).
/// `ring[i] - submit_ring[i]` is that frame's `redraw_to_submit` half. /// See [`FrameParts`] for how the three rings divide a frame up.
submit_ring: Box<[Duration; RING_CAPACITY]>, submit_ring: Box<[Duration; RING_CAPACITY]>,
/// The `acquire` half of each sample in `ring`, same index, same
/// lifetime -- see [`FrameParts::acquire`], which is the part that is
/// a wait rather than work.
acquire_ring: Box<[Duration; RING_CAPACITY]>,
/// 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.
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>,
/// The absolute (0-based, since the last `reset`) frame index each /// The absolute (0-based, since the last `reset`) frame index each
/// `ring`/`submit_ring` slot's sample belongs to -- what `phase_stats` /// `ring`/`submit_ring` slot's sample belongs to -- what `phase_stats`
/// slices against `PhaseMark::start_index` to tell which recorded /// slices against `PhaseMark::start_index` to tell which recorded
@@ -145,12 +253,18 @@ pub struct FrameStats {
pub p90: Duration, pub p90: Duration,
pub p99: Duration, pub p99: Duration,
pub worst: Duration, pub worst: Duration,
/// Median of `redraw_to_submit` -- iris's own CPU work (layout, text, /// Median of [`FrameParts::build`] -- iris's own CPU work per frame:
/// primitive building) up to and including building the `queue.submit` /// laying out, shaping text, building primitives and recording the
/// call, per frame. RUST.md's I5 "Where iris's frame time goes" split, /// render pass. RUST.md's I5 "Where iris's frame time goes" split,
/// added 2026-09-05 to answer "CPU or GPU?" with a number rather than a /// added 2026-09-05 to answer "CPU or GPU?" with a number rather than
/// guess. /// a guess, and corrected on 2026-09-09 to stop counting the
/// swapchain wait below as iris's own work.
pub cpu_p50: Duration, pub cpu_p50: Duration,
/// Median of [`FrameParts::acquire`]: the wait for a swapchain image.
/// **Not work** -- see that field's doc. A large number here beside a
/// small `cpu_p50` is an app comfortably ahead of the display, which
/// is what it should look like.
pub acquire_p50: Duration,
/// Median of `submit_to_present` -- the `queue.submit` call itself plus /// Median of `submit_to_present` -- the `queue.submit` call itself plus
/// `present()`, i.e. wherever the driver/GPU/compositor wait actually /// `present()`, i.e. wherever the driver/GPU/compositor wait actually
/// happens. Same caveat as the type's own doc: `present()` is not /// happens. Same caveat as the type's own doc: `present()` is not
@@ -177,9 +291,10 @@ impl std::fmt::Display for FrameStats {
)?; )?;
write!( write!(
f, f,
" cpu_p50={:.1}ms gpu_wait_p50={:.1}ms (redraw-start-to-submit vs. \ " cpu_p50={:.1}ms acquire_p50={:.1}ms gpu_wait_p50={:.1}ms (own work vs. \
submit-to-after-present)", waiting for a swapchain image vs. submit-to-after-present)",
self.cpu_p50.as_secs_f64() * 1000.0, self.cpu_p50.as_secs_f64() * 1000.0,
self.acquire_p50.as_secs_f64() * 1000.0,
self.gpu_wait_p50.as_secs_f64() * 1000.0, self.gpu_wait_p50.as_secs_f64() * 1000.0,
) )
} }
@@ -190,6 +305,9 @@ impl FrameReport {
Self { Self {
ring: Box::new([Duration::ZERO; RING_CAPACITY]), ring: Box::new([Duration::ZERO; RING_CAPACITY]),
submit_ring: Box::new([Duration::ZERO; RING_CAPACITY]), 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,
index_ring: Box::new([0; RING_CAPACITY]), index_ring: Box::new([0; RING_CAPACITY]),
len: 0, len: 0,
pos: 0, pos: 0,
@@ -199,28 +317,26 @@ impl FrameReport {
} }
} }
/// Record one frame's elapsed wall time, with no CPU/GPU split (the /// Record one frame, split into [`FrameParts`]. O(1), no allocation.
/// `submit_to_present` half is recorded as zero, so `cpu_p50` reads as ///
/// the whole frame and `gpu_wait_p50` as nothing -- honest for a caller /// One entry point rather than one per shape of measurement: a caller
/// that never measured the split, rather than fabricating one). O(1), /// with nothing but a total passes `FrameParts::whole(total)`, which
/// no allocation. /// says so in the type instead of leaving the report to guess from a
pub fn record(&mut self, elapsed: Duration) { /// zero.
self.record_split(elapsed, Duration::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),
/// Record one frame's elapsed wall time, split at `queue.submit`: None => Duration::ZERO,
/// `submit_to_present` is the `queue.submit()` call plus `present()`; };
/// `total - submit_to_present` is everything before it (layout, text, self.last_at = Some(at);
/// primitive building). RUST.md's I5 "Where iris's frame time goes" self.ring[self.pos] = parts.total;
/// CPU/GPU split, added 2026-09-05. O(1), no allocation. self.submit_ring[self.pos] = parts.submit;
pub fn record_split(&mut self, total: Duration, submit_to_present: Duration) { self.acquire_ring[self.pos] = parts.acquire;
self.ring[self.pos] = total;
self.submit_ring[self.pos] = submit_to_present;
self.index_ring[self.pos] = self.total_frames; self.index_ring[self.pos] = self.total_frames;
self.pos = (self.pos + 1) % RING_CAPACITY; self.pos = (self.pos + 1) % RING_CAPACITY;
self.len = (self.len + 1).min(RING_CAPACITY); self.len = (self.len + 1).min(RING_CAPACITY);
self.total_frames += 1; self.total_frames += 1;
if total > JANK_THRESHOLD { if parts.total > JANK_THRESHOLD {
self.janky_frames += 1; self.janky_frames += 1;
} }
} }
@@ -236,9 +352,20 @@ impl FrameReport {
self.pos = 0; self.pos = 0;
self.total_frames = 0; self.total_frames = 0;
self.janky_frames = 0; self.janky_frames = 0;
self.last_at = None;
self.phases.clear(); self.phases.clear();
} }
/// One recorded slot's three parts, back as the type they were
/// recorded in.
fn parts(&self, slot: usize) -> FrameParts {
FrameParts {
total: self.ring[slot],
acquire: self.acquire_ring[slot],
submit: self.submit_ring[slot],
}
}
/// Marks the start of a named phase at the current moment -- every /// Marks the start of a named phase at the current moment -- every
/// frame recorded from here until the next `mark_phase` (or `reset`) /// frame recorded from here until the next `mark_phase` (or `reset`)
/// belongs to it. RUST.md's "Benchmark v2": a scripted bench run calls /// belongs to it. RUST.md's "Benchmark v2": a scripted bench run calls
@@ -281,13 +408,13 @@ impl FrameReport {
None => (self.total_frames, now), None => (self.total_frames, now),
}; };
let frames = end_index.saturating_sub(phase.start_index); let frames = end_index.saturating_sub(phase.start_index);
let mut samples: Vec<Duration> = (0..self.len) let slots: Vec<usize> = (0..self.len)
.filter(|&j| { .filter(|&j| {
let idx = self.index_ring[j]; let idx = self.index_ring[j];
idx >= phase.start_index && idx < end_index idx >= phase.start_index && idx < end_index
}) })
.map(|j| self.ring[j])
.collect(); .collect();
let mut samples: Vec<Duration> = slots.iter().map(|&j| self.ring[j]).collect();
let complete = samples.len() as u64 >= frames; let complete = samples.len() as u64 >= frames;
if samples.is_empty() { if samples.is_empty() {
return PhaseStats { return PhaseStats {
@@ -300,9 +427,40 @@ impl FrameReport {
p90: Duration::ZERO, p90: Duration::ZERO,
p99: Duration::ZERO, p99: Duration::ZERO,
worst: Duration::ZERO, worst: Duration::ZERO,
missed: 0,
build_p50: Duration::ZERO,
acquire_p50: Duration::ZERO,
submit_p50: Duration::ZERO,
complete, complete,
}; };
} }
// Each part gets its own sort: medians do not distribute
// over subtraction, so `build`'s median is not `total`'s
// minus the other two.
let part_p50 = |part: &dyn Fn(usize) -> Duration| {
let mut v: Vec<Duration> = slots.iter().map(|&j| part(j)).collect();
v.sort_unstable();
v[v.len() / 2]
};
// A gap of more than one and a half budgets means at
// least one vsync came and went unanswered; the count is
// how many, so a frame arriving three periods late says 2.
//
// **The phase's own first frame is skipped**: its gap
// reaches back into the previous phase, across whatever
// the run did between the two -- a bench pausing a second
// between phases would otherwise open each one with sixty
// "missed" frames nobody was waiting for.
let missed: u64 = slots
.iter()
.filter(|&&j| self.index_ring[j] > phase.start_index)
.map(|&j| self.gap_ring[j])
.filter(|gap| *gap > budget.mul_f64(1.5))
.map(|gap| (gap.as_secs_f64() / budget.as_secs_f64()).round() as u64 - 1)
.sum();
let build_p50 = part_p50(&|j| self.parts(j).build());
let acquire_p50 = part_p50(&|j| self.acquire_ring[j]);
let submit_p50 = part_p50(&|j| self.submit_ring[j]);
samples.sort_unstable(); samples.sort_unstable();
let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)]; 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 = samples.iter().filter(|&&d| d > budget).count() as u64;
@@ -316,6 +474,10 @@ impl FrameReport {
p90: pct(90), p90: pct(90),
p99: pct(99), p99: pct(99),
worst: *samples.last().expect("checked not empty above"), worst: *samples.last().expect("checked not empty above"),
missed,
build_p50,
acquire_p50,
submit_p50,
complete, complete,
} }
}) })
@@ -337,11 +499,8 @@ impl FrameReport {
// medians do not distribute over subtraction, and each needs its // medians do not distribute over subtraction, and each needs its
// own sort. // own sort.
let submit_samples: Vec<Duration> = self.submit_ring[..self.len].to_vec(); let submit_samples: Vec<Duration> = self.submit_ring[..self.len].to_vec();
let cpu_samples: Vec<Duration> = self.ring[..self.len] let acquire_samples: Vec<Duration> = self.acquire_ring[..self.len].to_vec();
.iter() let cpu_samples: Vec<Duration> = (0..self.len).map(|j| self.parts(j).build()).collect();
.zip(self.submit_ring[..self.len].iter())
.map(|(&total, &submit_to_present)| total.saturating_sub(submit_to_present))
.collect();
let median = |mut v: Vec<Duration>| { let median = |mut v: Vec<Duration>| {
v.sort_unstable(); v.sort_unstable();
v[v.len() / 2] v[v.len() / 2]
@@ -355,6 +514,7 @@ impl FrameReport {
p99: pct(99), p99: pct(99),
worst: *samples.last().expect("len > 0 checked above"), worst: *samples.last().expect("len > 0 checked above"),
cpu_p50: median(cpu_samples), cpu_p50: median(cpu_samples),
acquire_p50: median(acquire_samples),
gpu_wait_p50: median(submit_samples), gpu_wait_p50: median(submit_samples),
}) })
} }
@@ -400,7 +560,7 @@ mod tests {
#[test] #[test]
fn one_frame_is_every_percentile_and_the_worst() { fn one_frame_is_every_percentile_and_the_worst() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.record(Duration::from_millis(10)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(10)));
let stats = r.report().unwrap(); let stats = r.report().unwrap();
assert_eq!(stats.total_frames, 1); assert_eq!(stats.total_frames, 1);
assert_eq!(stats.p50, Duration::from_millis(10)); assert_eq!(stats.p50, Duration::from_millis(10));
@@ -415,7 +575,7 @@ mod tests {
// 100 samples, 1ms..=100ms, fed out of order so the ring's own // 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. // order is not what gives the right answer -- the sort has to.
for ms in (1..=100).rev() { for ms in (1..=100).rev() {
r.record(Duration::from_millis(ms)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(ms)));
} }
let stats = r.report().unwrap(); let stats = r.report().unwrap();
assert_eq!(stats.total_frames, 100); assert_eq!(stats.total_frames, 100);
@@ -428,8 +588,14 @@ mod tests {
#[test] #[test]
fn jank_threshold_matches_gfxinfos_60hz_budget() { fn jank_threshold_matches_gfxinfos_60hz_budget() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.record(Duration::from_nanos(16_666_667)); // exactly on budget: not janky r.record(
r.record(Duration::from_nanos(16_666_668)); // one ns over: janky Instant::now(),
FrameParts::whole(Duration::from_nanos(16_666_667)),
); // exactly on budget: not janky
r.record(
Instant::now(),
FrameParts::whole(Duration::from_nanos(16_666_668)),
); // one ns over: janky
let stats = r.report().unwrap(); let stats = r.report().unwrap();
assert_eq!(stats.janky_percent, 50.0); assert_eq!(stats.janky_percent, 50.0);
} }
@@ -440,12 +606,12 @@ mod tests {
// the percentage must reset to 0, not divide by a stale count. // the percentage must reset to 0, not divide by a stale count.
let mut r = FrameReport::new(); let mut r = FrameReport::new();
for _ in 0..10 { for _ in 0..10 {
r.record(Duration::from_millis(50)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(50)));
} }
assert_eq!(r.report().unwrap().janky_percent, 100.0); assert_eq!(r.report().unwrap().janky_percent, 100.0);
r.reset(); r.reset();
assert!(r.report().is_none()); assert!(r.report().is_none());
r.record(Duration::from_millis(1)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1)));
assert_eq!(r.report().unwrap().janky_percent, 0.0); assert_eq!(r.report().unwrap().janky_percent, 0.0);
} }
@@ -455,32 +621,94 @@ mod tests {
// not fabricate a GPU-wait number -- it reads as zero, and the CPU // not fabricate a GPU-wait number -- it reads as zero, and the CPU
// half reads as the whole frame. // half reads as the whole frame.
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.record(Duration::from_millis(20)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(20)));
let stats = r.report().unwrap(); let stats = r.report().unwrap();
assert_eq!(stats.cpu_p50, Duration::from_millis(20)); assert_eq!(stats.cpu_p50, Duration::from_millis(20));
assert_eq!(stats.gpu_wait_p50, Duration::ZERO); assert_eq!(stats.gpu_wait_p50, Duration::ZERO);
} }
#[test] #[test]
fn record_split_reports_each_halfs_own_median() { fn each_part_reports_its_own_median_and_build_excludes_the_wait() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
// Three frames: total is always 30ms, but the CPU/GPU-wait split // Three frames of the same 30ms total, with the split moving:
// moves, so the two medians must be independent of each other and // each part needs its own sort, and `build` is what is left after
// of `total`'s own median. // both waits -- not the total, which is the bug this replaced
r.record_split(Duration::from_millis(30), Duration::from_millis(5)); // (the swapchain wait used to be counted as iris's own work).
r.record_split(Duration::from_millis(30), Duration::from_millis(10)); for (acquire, submit) in [(5, 2), (10, 3), (20, 4)] {
r.record_split(Duration::from_millis(30), Duration::from_millis(20)); r.record(
Instant::now(),
FrameParts {
total: Duration::from_millis(30),
acquire: Duration::from_millis(acquire),
submit: Duration::from_millis(submit),
},
);
}
let stats = r.report().unwrap(); let stats = r.report().unwrap();
assert_eq!(stats.p50, Duration::from_millis(30)); assert_eq!(stats.p50, Duration::from_millis(30));
assert_eq!(stats.gpu_wait_p50, Duration::from_millis(10)); assert_eq!(stats.acquire_p50, Duration::from_millis(10));
assert_eq!(stats.cpu_p50, Duration::from_millis(20)); assert_eq!(stats.gpu_wait_p50, Duration::from_millis(3));
// 30-5-2=23, 30-10-3=17, 30-20-4=6 -> median 17.
assert_eq!(stats.cpu_p50, Duration::from_millis(17));
}
#[test]
fn a_gap_of_more_than_one_vsync_is_counted_as_a_missed_frame() {
// Cost and cadence are separate questions: every frame here is
// well inside its budget, so `late` is zero, and the run still
// skipped three vsyncs -- which is what a reader sees as a
// stutter and what nothing in a report could say before.
let mut r = FrameReport::new();
let base = Instant::now();
let budget = Duration::from_nanos(16_666_667);
r.mark_phase("fling");
// Frames at 0, 1, 2, 4 (one skipped), 5, 8 (two skipped) budgets.
for step in [0u32, 1, 2, 4, 5, 8] {
r.record(
base + budget * step,
FrameParts::whole(Duration::from_millis(2)),
);
}
let phase = r.phase_stats(Instant::now(), 60.0).remove(0);
assert_eq!(phase.late, 0, "no frame here was over its budget");
assert_eq!(phase.missed, 3);
}
#[test]
fn a_phase_does_not_inherit_the_pause_before_it() {
// The half the fix above had no reason to touch: a bench rests
// between phases, and that rest reaches the next phase's first
// frame as its gap. Charging it there would open every phase with
// a large invented `missed`.
let mut r = FrameReport::new();
let base = Instant::now();
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));
}
// 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));
}
let phases = r.phase_stats(Instant::now(), 60.0);
assert_eq!(phases[0].missed, 0);
assert_eq!(
phases[1].missed, 0,
"the rest between phases is not a stutter"
);
} }
#[test] #[test]
fn ring_wraps_without_growing_past_capacity() { fn ring_wraps_without_growing_past_capacity() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
for i in 0..(RING_CAPACITY * 2) { for i in 0..(RING_CAPACITY * 2) {
r.record(Duration::from_millis(1 + (i % 5) as u64)); r.record(
Instant::now(),
FrameParts::whole(Duration::from_millis(1 + (i % 5) as u64)),
);
} }
let stats = r.report().unwrap(); let stats = r.report().unwrap();
// total_frames keeps the full count even once the ring has wrapped. // total_frames keeps the full count even once the ring has wrapped.
@@ -494,7 +722,7 @@ mod tests {
#[test] #[test]
fn no_marks_means_no_phases() { fn no_marks_means_no_phases() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.record(Duration::from_millis(5)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(5)));
assert!(r.phase_stats(Instant::now(), 60.0).is_empty()); assert!(r.phase_stats(Instant::now(), 60.0).is_empty());
} }
@@ -503,11 +731,11 @@ mod tests {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.mark_phase("a"); r.mark_phase("a");
for _ in 0..5 { for _ in 0..5 {
r.record(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))); // 10ms: late at 60Hz (16.7ms budget)... no, 10<16.7, not late
} }
r.mark_phase("b"); r.mark_phase("b");
for _ in 0..3 { for _ in 0..3 {
r.record(Duration::from_millis(20)); // 20ms: late at 60Hz r.record(Instant::now(), FrameParts::whole(Duration::from_millis(20))); // 20ms: late at 60Hz
} }
let now = Instant::now(); let now = Instant::now();
let phases = r.phase_stats(now, 60.0); let phases = r.phase_stats(now, 60.0);
@@ -529,7 +757,7 @@ mod tests {
fn the_last_phase_runs_until_now() { fn the_last_phase_runs_until_now() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.mark_phase("only"); r.mark_phase("only");
r.record(Duration::from_millis(1)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1)));
std::thread::sleep(Duration::from_millis(20)); std::thread::sleep(Duration::from_millis(20));
let now = Instant::now(); let now = Instant::now();
let phases = r.phase_stats(now, 60.0); let phases = r.phase_stats(now, 60.0);
@@ -541,7 +769,7 @@ mod tests {
fn reset_clears_phase_marks() { fn reset_clears_phase_marks() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
r.mark_phase("a"); r.mark_phase("a");
r.record(Duration::from_millis(1)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1)));
r.reset(); r.reset();
assert!(r.phase_stats(Instant::now(), 60.0).is_empty()); assert!(r.phase_stats(Instant::now(), 60.0).is_empty());
} }
@@ -550,7 +778,7 @@ mod tests {
fn late_at_hz_uses_the_given_refresh_rate_not_the_fixed_60hz_constant() { fn late_at_hz_uses_the_given_refresh_rate_not_the_fixed_60hz_constant() {
let mut r = FrameReport::new(); let mut r = FrameReport::new();
// 10ms is under 60Hz's 16.7ms budget but over 120Hz's 8.3ms one. // 10ms is under 60Hz's 16.7ms budget but over 120Hz's 8.3ms one.
r.record(Duration::from_millis(10)); r.record(Instant::now(), FrameParts::whole(Duration::from_millis(10)));
assert_eq!(r.late_at_hz(60.0), (0, 0.0)); assert_eq!(r.late_at_hz(60.0), (0, 0.0));
assert_eq!(r.late_at_hz(120.0), (1, 100.0)); assert_eq!(r.late_at_hz(120.0), (1, 100.0));
} }
+1 -1
View File
@@ -24,7 +24,7 @@ mod util;
pub use atlas::*; pub use atlas::*;
pub use data::{Mask, MaskIdx, MoveIdx, MoveOffset}; pub use data::{Mask, MaskIdx, MoveIdx, MoveOffset};
pub use frame_report::{FrameReport, FrameStats, JANK_THRESHOLD}; pub use frame_report::{FrameParts, FrameReport, FrameStats, JANK_THRESHOLD};
pub use primitive::*; pub use primitive::*;
pub use sdf::{distance_from_rect, rounded_rect_coverage}; pub use sdf::{distance_from_rect, rounded_rect_coverage};
+24 -15
View File
@@ -4,9 +4,9 @@ use android_view::{
jni::{JavaVM, objects::GlobalRef}, jni::{JavaVM, objects::GlobalRef},
ndk::native_window::NativeWindow, ndk::native_window::NativeWindow,
}; };
use iris_core::{UiData, UiRenderNode, UiRenderState}; use iris_core::{FrameParts, UiData, UiRenderNode, UiRenderState};
use pollster::FutureExt; use pollster::FutureExt;
use std::time::{Duration, Instant}; use std::time::Instant;
use wgpu::{ use wgpu::{
rwh::{DisplayHandle, HandleError, HasDisplayHandle, HasWindowHandle, WindowHandle}, rwh::{DisplayHandle, HandleError, HasDisplayHandle, HasWindowHandle, WindowHandle},
*, *,
@@ -415,18 +415,26 @@ impl AndroidRenderer {
self.frame_count self.frame_count
} }
/// Draws and presents one frame, returning the time spent in /// Draws and presents one frame, returning the two parts of it that
/// `queue.submit` plus `present()` -- wherever a driver/GPU/compositor /// are waits rather than work: the `get_current_texture` acquire and
/// wait would actually show up. The caller (`android::view::render`) /// `queue.submit` + `present()`. The caller
/// already times the whole frame from its own `redraw_to_submit` start; /// (`android::view::render`) times the whole frame and fills in
/// subtracting this from that total is `redraw_to_submit` itself /// `FrameParts::total`, so whatever is left over is iris's own work.
/// (layout, text, primitive building, and this method's own render-pass ///
/// recording). RUST.md's I5 "Where iris's frame time goes" diagnosis, /// **The acquire is why this returns two numbers and not one.**
/// added 2026-09-05 -- see `iris_core::FrameReport::record_split`'s own /// `get_current_texture` blocks until the compositor hands back a
/// doc for the caveat this shares: `present()` is not fenced against /// swapchain image, which on an app comfortably ahead of the display
/// the GPU actually finishing, so this is "how long the CPU was blocked /// is most of every frame -- so counting it as CPU work (which this
/// handing the frame off", not confirmed GPU time. /// did until 2026-09-09) reports a fling as milliseconds of iris
pub fn draw(&mut self) -> Duration { /// being slow when they are milliseconds of iris waiting its turn.
///
/// RUST.md's I5 "Where iris's frame time goes" diagnosis, added
/// 2026-09-05 -- see `iris_core::FrameParts`'s own doc for the caveat
/// the submit half shares: `present()` is not fenced against the GPU
/// actually finishing, so it is "how long the CPU was blocked handing
/// the frame off", not confirmed GPU time.
pub fn draw(&mut self) -> FrameParts {
let acquire_start = Instant::now();
let output = match self.surface.get_current_texture() { let output = match self.surface.get_current_texture() {
CurrentSurfaceTexture::Success(texture) CurrentSurfaceTexture::Success(texture)
| CurrentSurfaceTexture::Suboptimal(texture) => texture, | CurrentSurfaceTexture::Suboptimal(texture) => texture,
@@ -435,6 +443,7 @@ impl AndroidRenderer {
// which is new. // which is new.
other => panic!("no surface texture to draw into: {other:?}"), other => panic!("no surface texture to draw into: {other:?}"),
}; };
let acquire = acquire_start.elapsed();
let view = output let view = output
.texture .texture
.create_view(&TextureViewDescriptor::default()); .create_view(&TextureViewDescriptor::default());
@@ -459,7 +468,7 @@ impl AndroidRenderer {
let submit_start = Instant::now(); let submit_start = Instant::now();
self.queue.submit(std::iter::once(encoder.finish())); self.queue.submit(std::iter::once(encoder.finish()));
self.queue.present(output); self.queue.present(output);
submit_start.elapsed() FrameParts::waits(acquire, submit_start.elapsed())
} }
/// Physical pixels -- the unit layout and hit-testing use, matching /// Physical pixels -- the unit layout and hit-testing use, matching
+96 -44
View File
@@ -312,11 +312,14 @@ pub struct IrisViewPeer<State: AndroidAppState> {
pub(super) render: UiRenderState, pub(super) render: UiRenderState,
pub(super) state: State, pub(super) state: State,
task_recv: TaskMsgReceiver<AndroidRsc<State>>, task_recv: TaskMsgReceiver<AndroidRsc<State>>,
/// Anchored on the first `MotionEvent` this view receives and never /// The one ruler this view dates everything on: touch samples in
/// re-anchored after -- how `on_touch_event` dates every touch sample. /// `on_touch_event` and the `Choreographer` frame time in `do_frame`.
/// Its path out is the peer's own drop: it holds nothing but three /// Anchored by whichever of the two arrives first and never
/// numbers and is meaningless to any other view. /// re-anchored after, which is what lets a fling be advanced on the
input_clock: Option<PointerClock>, /// same clock the gesture that launched it was measured on. Its path
/// out is the peer's own drop: it holds nothing but three numbers and
/// is meaningless to any other view.
device_clock: Option<DeviceClock>,
} }
impl<State: 'static, I: RscIdx<AndroidRsc<State>>> std::ops::Index<I> for AndroidRsc<State> { impl<State: 'static, I: RscIdx<AndroidRsc<State>>> std::ops::Index<I> for AndroidRsc<State> {
@@ -390,6 +393,22 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
} }
} }
/// The view's one clock, anchoring it on `nanos` if nothing has yet
/// -- see the `device_clock` field. Either source may be the first to
/// arrive: a frame callback fires before any touch on an app that
/// animates at startup, and a touch arrives first on one that does
/// not.
///
/// `oldest` is the earliest sample the anchoring event carries, which
/// matters only when this is the call that anchors -- see
/// `DeviceClock::anchored`. A frame time carries no batch, so it
/// passes its own time for both.
fn device_clock(&mut self, event_time: i64, oldest: i64) -> DeviceClock {
*self
.device_clock
.get_or_insert_with(|| DeviceClock::anchored(Instant::now(), event_time, oldest))
}
fn window_size(&self) -> Vec2 { fn window_size(&self) -> Vec2 {
let ui_state = self.state.android_state(); let ui_state = self.state.android_state();
match &ui_state.renderer { match &ui_state.renderer {
@@ -412,7 +431,7 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
/// every level the app's already-`Debug` install lets through /// every level the app's already-`Debug` install lets through
/// regardless of target, so they filled the whole ring in under ten /// regardless of target, so they filled the whole ring in under ten
/// seconds at 120Hz and left `Copy report` nothing else to show. /// seconds at 120Hz and left `Copy report` nothing else to show.
fn render(&mut self, ctx: &mut CallbackCtx) { fn render(&mut self, ctx: &mut CallbackCtx, now: Instant) {
if self.state.android_state().renderer.is_none() { if self.state.android_state().renderer.is_none() {
return; return;
} }
@@ -476,12 +495,31 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
// both count. See `iris_core::FrameReport`'s own doc for exactly // both count. See `iris_core::FrameReport`'s own doc for exactly
// what this does and does not measure. // what this does and does not measure.
let frame_start = Instant::now(); let frame_start = Instant::now();
// Anything moving on its own -- today a `LazySpan` coasting through a // Anything moving on its own -- today a `LazySpan` coasting
// fling -- is advanced here, before the draw, and asks for the // through a fling -- is advanced here, before the draw. **On
// next frame at the end of this one. See // `now`, not on `frame_start`**: `now` is the vsync the
// `UiData::tick_animations`; `default/mod.rs`'s // `Choreographer` handed this callback, which is evenly spaced,
// `RedrawRequested` arm is the same two lines for winit. // while `frame_start` is whenever the callback actually got to
let animating = self.rsc.ui.tick_animations(frame_start); // run. The frames are *presented* on the even cadence either way,
// so sampling the animation on the uneven one moves the content by
// an uneven distance per frame -- a fling that shimmers with no
// frame late enough to show up in a report. See
// `UiData::tick_animations` and `sense::DeviceClock`;
// `default/mod.rs`'s `RedrawRequested` arm is the winit half.
let animating = self.rsc.ui.tick_animations(now);
// **Asked for before the work, not after it.** A frame callback is
// one-shot, so an animation that wants another frame has to say so
// every frame -- and `Choreographer.postFrameCallback` schedules
// for the next vsync *after the call*. Asking at the end of this
// function meant any frame whose work ran past the vsync boundary
// (the swapchain acquire below alone can sit most of a frame)
// registered too late for the next one and got the one after --
// so one frame over budget silently cost a second frame as well.
// Unlike `after_input`, which only has to ask when input dirtied
// something.
if animating {
ctx.view.post_frame_callback(&mut ctx.env);
}
let ui_state = self.state.android_state_mut(); let ui_state = self.state.android_state_mut();
self.render.update(&ui_state.root, &mut self.rsc); self.render.update(&ui_state.root, &mut self.rsc);
let ui_state = self.state.android_state_mut(); let ui_state = self.state.android_state_mut();
@@ -509,18 +547,16 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
renderer.wgpu_errors.snapshot().len(), renderer.wgpu_errors.snapshot().len(),
); );
} }
let submit_to_present = renderer.draw(); let mut parts = renderer.draw();
parts.total = frame_start.elapsed();
// Dated on `now` -- the vsync this frame was for -- so the gap
// between consecutive frames is the display's own cadence and
// `PhaseStats::missed` counts vsyncs nothing was drawn for.
self.state self.state
.android_state_mut() .android_state_mut()
.frame_report .frame_report
.record_split(frame_start.elapsed(), submit_to_present); .record(now, parts);
crate::diagnostics::log_frame(&self.render, frame_start, submit_to_present, animating); crate::diagnostics::log_frame(&self.render, now, parts, animating);
// A frame callback is one-shot, so an animation that wants
// another frame has to say so every frame -- unlike `after_input`,
// which only has to ask when input dirtied something.
if animating {
ctx.view.post_frame_callback(&mut ctx.env);
}
if crate::diagnostics::trace_enabled() { if crate::diagnostics::trace_enabled() {
let ui_state = self.state.android_state(); let ui_state = self.state.android_state();
log::debug!( log::debug!(
@@ -632,28 +668,32 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
// -- see `AndroidUiState::content_scale`'s field comment. // -- see `AndroidUiState::content_scale`'s field comment.
let x = event.x(&mut ctx.env); let x = event.x(&mut ctx.env);
let y = event.y(&mut ctx.env); let y = event.y(&mut ctx.env);
// The event's own clock, converted through one anchor taken on the // The event's own clock, converted through the view's one anchor
// first touch this view ever sees. Android reports sample times in // -- taken on whichever of a touch or a frame callback came first.
// the `SystemClock.uptimeMillis()` base, which is the same // Android reports sample times in the `SystemClock.uptimeMillis()`
// `CLOCK_MONOTONIC` an `Instant` reads, so a single // base, which is the same `CLOCK_MONOTONIC` an `Instant` reads, so
// `(Instant, nanos)` pair converts every later sample exactly. // a single `(Instant, nanos)` pair converts every later sample
// Anchoring **once** rather than per event is what keeps the times // exactly. Anchoring **once** rather than per event is what keeps
// ordered, and anchoring on the first event's *oldest* sample // the times ordered, and anchoring on the first event's *oldest*
// rather than on its own time is what keeps that event's batch // sample rather than on its own time is what keeps that event's
// from collapsing onto one instant -- `sense::PointerClock`'s doc // batch from collapsing onto one instant -- `sense::DeviceClock`'s
// has both, and owns the arithmetic so it can be unit-tested off a // doc has both, and owns the arithmetic so it can be unit-tested
// device (`sense_tests.rs`). See `CursorState::time`. // off a device (`sense_tests.rs`). See `CursorState::time`.
let event_time = event.event_time_nanos(&mut ctx.env); let event_time = event.event_time_nanos(&mut ctx.env);
if self.input_clock.is_none() {
let history = event.history_size(&mut ctx.env); let history = event.history_size(&mut ctx.env);
let mut clock = match self.device_clock {
Some(clock) => clock,
// Only the call that anchors needs the batch's oldest sample,
// so the JNI read for it stays off the per-event path.
None => {
let oldest = if history > 0 { let oldest = if history > 0 {
event.historical_event_time_nanos(&mut ctx.env, 0) event.historical_event_time_nanos(&mut ctx.env, 0)
} else { } else {
event_time event_time
}; };
self.input_clock = Some(PointerClock::anchored(Instant::now(), event_time, oldest)); self.device_clock(event_time, oldest)
} }
let mut clock = self.input_clock.expect("anchored just above"); };
// `iris::input`'s own doc (`sense::log_input_event`): collected // `iris::input`'s own doc (`sense::log_input_event`): collected
// only when tracing is on, since this is otherwise a `Vec` per // only when tracing is on, since this is otherwise a `Vec` per
// `MotionEvent` for a line nobody is reading -- the JNI reads // `MotionEvent` for a line nobody is reading -- the JNI reads
@@ -676,12 +716,11 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
// motion the finger actually made; only the last sample ends the // motion the finger actually made; only the last sample ends the
// frame (`after_input`). // frame (`after_input`).
if matches!(action, MotionAction::Move) { if matches!(action, MotionAction::Move) {
let history = event.history_size(&mut ctx.env);
// Android documents the historical samples as oldest first and // Android documents the historical samples as oldest first and
// the event's own sample as the newest of the batch; everything // the event's own sample as the newest of the batch; everything
// downstream (`VelocityTracker`, `DragArbiter`'s long-press // downstream (`VelocityTracker`, `DragArbiter`'s long-press
// clock) assumes it, so say so here rather than at each reader. // clock) assumes it, so say so here rather than at each reader.
// `PointerClock::sample` is what asserts it, and it carries the // `DeviceClock::sample` is what asserts it, and it carries the
// last sample seen *across* events, so the first sample of // last sample seen *across* events, so the first sample of
// every event is checked against the previous event's last one // every event is checked against the previous event's last one
// rather than against the anchor. // rather than against the anchor.
@@ -702,7 +741,7 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
let event_at = clock.sample(event_time); let event_at = clock.sample(event_time);
let event_ms = clock.ms_since_anchor(event_time); let event_ms = clock.ms_since_anchor(event_time);
self.input_clock = Some(clock); self.device_clock = Some(clock);
let ui_state = self.state.android_state_mut(); let ui_state = self.state.android_state_mut();
ui_state.cursor.time = event_at; ui_state.cursor.time = event_at;
match action { match action {
@@ -837,7 +876,7 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
.as_mut() .as_mut()
.expect("checked Some above") .expect("checked Some above")
.resize(width as u32, height as u32); .resize(width as u32, height as u32);
self.render(ctx); self.render(ctx, Instant::now());
return; return;
} }
@@ -888,7 +927,7 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
); );
self.rsc.ui.textures.reupload(); self.rsc.ui.textures.reupload();
self.state.android_state_mut().renderer = Some(renderer); self.state.android_state_mut().renderer = Some(renderer);
self.render(ctx); self.render(ctx, Instant::now());
} }
Err(report) => { Err(report) => {
// One line for logcat (UI_RULES.md: "the full text for // One line for logcat (UI_RULES.md: "the full text for
@@ -930,9 +969,20 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
self.state.android_state_mut().renderer = None; self.state.android_state_mut().renderer = None;
} }
fn do_frame(&mut self, ctx: &mut CallbackCtx, _frame_time_nanos: i64) { fn do_frame(&mut self, ctx: &mut CallbackCtx, frame_time_nanos: i64) {
self.drain_tasks(); self.drain_tasks();
self.render(ctx); // The vsync this frame is for, dated on the same ruler touch
// samples are (`DeviceClock`), rather than `Instant::now()` here:
// this callback runs some variable distance after that vsync --
// behind `drain_tasks`, behind whatever else the UI thread was
// doing -- and anything advanced by that variable amount moves
// unevenly between frames the display shows evenly. `at` rather
// than `sample`, since a frame time is not part of the touch
// samples' own ordering.
let now = self
.device_clock(frame_time_nanos, frame_time_nanos)
.at(frame_time_nanos);
self.render(ctx, now);
} }
/// Where `AndroidRedrawHandle::request_redraw` (`android/render.rs`) /// Where `AndroidRedrawHandle::request_redraw` (`android/render.rs`)
@@ -946,7 +996,9 @@ impl<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
/// one. /// one.
fn delayed_callback(&mut self, ctx: &mut CallbackCtx) { fn delayed_callback(&mut self, ctx: &mut CallbackCtx) {
self.drain_tasks(); self.drain_tasks();
self.render(ctx); // No vsync to date this one on -- it is a background task's
// "there is new state", not a frame the display asked for.
self.render(ctx, Instant::now());
} }
fn as_input_connection(&mut self) -> Option<&mut dyn InputConnection> { fn as_input_connection(&mut self) -> Option<&mut dyn InputConnection> {
@@ -1072,7 +1124,7 @@ pub fn new_peer<'local, State: AndroidAppState>(
render, render,
state, state,
task_recv, task_recv,
input_clock: None, device_clock: None,
}; };
let id = android_view::register_view_peer(peer); let id = android_view::register_view_peer(peer);
super::insets::register(id, shared); super::insets::register(id, shared);
+11 -5
View File
@@ -342,14 +342,20 @@ impl<State: DefaultAppState> AppState for DefaultApp<State> {
let frame_start = std::time::Instant::now(); let frame_start = std::time::Instant::now();
let animating = rsc.ui_mut().tick_animations(frame_start); let animating = rsc.ui_mut().tick_animations(frame_start);
let ui_state = state.default_state_mut(); let ui_state = state.default_state_mut();
render.update(&ui_state.root, rsc); // Asked for before the work rather than after it, the same
ui_state.renderer.update(&mut rsc.ui, render); // way `IrisViewPeer::render` does and for the same reason
let draw_start = std::time::Instant::now(); // -- see the longer comment there. winit coalesces
ui_state.renderer.draw(); // repeated requests, so the only thing the order changes
crate::diagnostics::log_frame(render, frame_start, draw_start.elapsed(), animating); // is whether the request is in before this frame's draw
// can push it past a vsync boundary.
if animating { if animating {
ui_state.window.request_redraw(); ui_state.window.request_redraw();
} }
render.update(&ui_state.root, rsc);
ui_state.renderer.update(&mut rsc.ui, render);
let mut parts = ui_state.renderer.draw();
parts.total = frame_start.elapsed();
crate::diagnostics::log_frame(render, frame_start, parts, animating);
// I4 (RUST.md): only produces a `TreeUpdate` when the named // I4 (RUST.md): only produces a `TreeUpdate` when the named
// set actually changed this frame -- see `AccessTree`'s doc // set actually changed this frame -- see `AccessTree`'s doc
// comment. `render` reflects the draw that just happened, // comment. `render` reflects the draw that just happened,
+10 -2
View File
@@ -1,7 +1,8 @@
use crate::task::RequestRedraw; use crate::task::RequestRedraw;
use iris_core::{UiData, UiRenderNode, UiRenderState, util::Vec2}; use iris_core::{FrameParts, UiData, UiRenderNode, UiRenderState, util::Vec2};
use pollster::FutureExt; use pollster::FutureExt;
use std::sync::Arc; use std::sync::Arc;
use std::time::Instant;
use wgpu::*; use wgpu::*;
use winit::{dpi::PhysicalSize, window::Window}; use winit::{dpi::PhysicalSize, window::Window};
@@ -28,7 +29,11 @@ impl UiRenderer {
self.ui.update(&self.device, &self.queue, ui, render); self.ui.update(&self.device, &self.queue, ui, render);
} }
pub fn draw(&mut self) { /// The two waits, so a desktop frame divides up the same way an
/// Android one does -- see `AndroidRenderer::draw` for why the
/// swapchain acquire is measured apart from the work.
pub fn draw(&mut self) -> FrameParts {
let acquire_start = Instant::now();
let output = match self.surface.get_current_texture() { let output = match self.surface.get_current_texture() {
CurrentSurfaceTexture::Success(texture) CurrentSurfaceTexture::Success(texture)
| CurrentSurfaceTexture::Suboptimal(texture) => texture, | CurrentSurfaceTexture::Suboptimal(texture) => texture,
@@ -39,6 +44,7 @@ impl UiRenderer {
// comment was written about. // comment was written about.
other => panic!("no surface texture to draw into: {other:?}"), other => panic!("no surface texture to draw into: {other:?}"),
}; };
let acquire = acquire_start.elapsed();
let view = output let view = output
.texture .texture
.create_view(&TextureViewDescriptor::default()); .create_view(&TextureViewDescriptor::default());
@@ -60,6 +66,7 @@ impl UiRenderer {
self.ui.draw(render_pass); self.ui.draw(render_pass);
} }
let submit_start = Instant::now();
self.queue.submit(std::iter::once(encoder.finish())); self.queue.submit(std::iter::once(encoder.finish()));
// Immediately before presenting, so the windowing system can schedule // Immediately before presenting, so the windowing system can schedule
// the frame. On Wayland this is what ties the commit to the surface's // the frame. On Wayland this is what ties the commit to the surface's
@@ -69,6 +76,7 @@ impl UiRenderer {
// starts, with nothing left to flush it. // starts, with nothing left to flush it.
self.window.pre_present_notify(); self.window.pre_present_notify();
self.queue.present(output); self.queue.present(output);
FrameParts::waits(acquire, submit_start.elapsed())
} }
pub fn resize(&mut self, size: &PhysicalSize<u32>) { pub fn resize(&mut self, size: &PhysicalSize<u32>) {
+8 -6
View File
@@ -26,9 +26,9 @@
//! has open at the same time this was written. `set_trace` is the whole //! has open at the same time this was written. `set_trace` is the whole
//! surface a button needs; wiring one is a follow-up. //! surface a button needs; wiring one is a follow-up.
use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::atomic::{AtomicBool, Ordering};
use std::time::{Duration, Instant}; use std::time::Instant;
use iris_core::UiRenderState; use iris_core::{FrameParts, UiRenderState};
static TRACE: AtomicBool = AtomicBool::new(false); static TRACE: AtomicBool = AtomicBool::new(false);
@@ -61,7 +61,7 @@ pub fn trace_enabled() -> bool {
/// its own draw call are the only two `Instant` pairs in the whole path -- /// its own draw call are the only two `Instant` pairs in the whole path --
/// see each call site's own comment for why it is not restructured to fit /// see each call site's own comment for why it is not restructured to fit
/// this instead. /// this instead.
pub fn log_frame(render: &UiRenderState, now: Instant, draw: Duration, animating: bool) { pub fn log_frame(render: &UiRenderState, now: Instant, parts: FrameParts, animating: bool) {
if !trace_enabled() { if !trace_enabled() {
return; return;
} }
@@ -71,12 +71,14 @@ pub fn log_frame(render: &UiRenderState, now: Instant, draw: Duration, animating
.unwrap_or_else(|| "none".to_string()); .unwrap_or_else(|| "none".to_string());
log::debug!( log::debug!(
target: "iris::frame", target: "iris::frame",
"iris frame: n={} now={}ms since_input={since_input} layout={:?} draw={:?} \ "iris frame: n={} now={}ms since_input={since_input} layout={:?} build={:?} \
redraw={:?} primitives={} animating={animating}", acquire={:?} submit={:?} redraw={:?} primitives={} animating={animating}",
render.frame_number(), render.frame_number(),
now.duration_since(render.epoch()).as_millis(), now.duration_since(render.epoch()).as_millis(),
render.last_layout_duration(), render.last_layout_duration(),
draw, parts.build(),
parts.acquire,
parts.submit,
render.last_redraw_kind(), render.last_redraw_kind(),
render.active_primitive_count(), render.active_primitive_count(),
); );
+12 -5
View File
@@ -359,14 +359,21 @@ impl Harness {
update(&mut self.state, &mut self.rsc); update(&mut self.state, &mut self.rsc);
} }
let now = self.at(t_ms); let now = self.at(t_ms);
let at = Instant::now();
let animating = self.rsc.ui.tick_animations(now); let animating = self.rsc.ui.tick_animations(now);
self.render.update(&self.state.root, &mut self.rsc); self.render.update(&self.state.root, &mut self.rsc);
// No GPU here, so there is no draw phase to time -- `draw` is // No GPU here, so there is nothing to acquire and nothing to
// always zero. `layout`/`redraw`/`primitives` are still real, // submit: the frame is all `build`, which is honest rather than
// because `render.update` just ran; see // zero-filled (`FrameParts::whole`). `layout`/`redraw`/
// `iris::diagnostics::log_frame`'s own doc for why this reads // `primitives` are still real, because `render.update` just ran;
// see `iris::diagnostics::log_frame`'s own doc for why this reads
// those back rather than timing anything itself. // those back rather than timing anything itself.
crate::diagnostics::log_frame(&self.render, now, Duration::ZERO, animating); crate::diagnostics::log_frame(
&self.render,
now,
FrameParts::whole(at.elapsed()),
animating,
);
} }
/// Frames every `step_ms` up to and including `end_ms` -- what a /// Frames every `step_ms` up to and including `end_ms` -- what a
+21 -7
View File
@@ -816,14 +816,27 @@ pub fn log_input_event(action: &str, x: f32, y: f32, t_ms: u64, historical: &[(u
); );
} }
/// Converts a platform's own monotonic input timestamps into [`Instant`]s /// Converts a platform's own monotonic timestamps into [`Instant`]s
/// through **one** anchor taken at the first event, so that every sample /// through **one** anchor, so that everything this process is told the
/// this process ever sees is dated on a single ruler. /// time of is dated on a single ruler.
///
/// Two kinds of timestamp go through it on Android and they have to agree,
/// which is why there is one type and not one per source: a touch
/// sample's `MotionEvent` time, and the `Choreographer` frame time a
/// `doFrame` callback carries. Both are `CLOCK_MONOTONIC` in nanoseconds
/// (`SystemClock.uptimeMillis`'s base and `System.nanoTime`'s are the same
/// clock), so one `(Instant, nanos)` pair converts either exactly, and a
/// fling launched by a gesture is then advanced on the clock its velocity
/// was measured on.
/// ///
/// A fresh `Instant::now()` per event, minus each sample's age inside it, /// A fresh `Instant::now()` per event, minus each sample's age inside it,
/// can date a later event's first sample before the previous event's last /// can date a later event's first sample before the previous event's last
/// one whenever delivery jitters by more than the batch spans -- which /// one whenever delivery jitters by more than the batch spans -- which
/// [`VelocityTracker`] would rightly reject. /// [`VelocityTracker`] would rightly reject. The same jitter in a *frame*
/// clock is what makes a fling stutter: the display presents frames on an
/// even cadence, so sampling the animation at "whenever the callback got
/// to run" moves the content by an uneven distance each time even when no
/// frame is late.
/// ///
/// The anchor is taken from the **earliest sample of the first event**, /// The anchor is taken from the **earliest sample of the first event**,
/// not from that event's own time: an event batches samples that are by /// not from that event's own time: an event batches samples that are by
@@ -834,16 +847,17 @@ pub fn log_input_event(action: &str, x: f32, y: f32, t_ms: u64, historical: &[(u
/// view sees is a `Move` (the `Down` went to another view, or the view was /// view sees is a `Move` (the `Down` went to another view, or the view was
/// attached mid-gesture). Found by review, 2026-09-07. /// attached mid-gesture). Found by review, 2026-09-07.
#[derive(Clone, Copy)] #[derive(Clone, Copy)]
pub struct PointerClock { pub struct DeviceClock {
anchor_at: Instant, anchor_at: Instant,
anchor_nanos: i64, anchor_nanos: i64,
last_nanos: i64, last_nanos: i64,
} }
impl PointerClock { impl DeviceClock {
/// `now` is when the first event arrived, `event_time` its own /// `now` is when the first event arrived, `event_time` its own
/// timestamp, and `oldest` the timestamp of the earliest sample it /// timestamp, and `oldest` the timestamp of the earliest sample it
/// carries -- equal to `event_time` when it batches none. /// carries -- equal to `event_time` when it batches none, which is
/// also what a frame time anchoring this passes for both.
pub fn anchored(now: Instant, event_time: i64, oldest: i64) -> Self { pub fn anchored(now: Instant, event_time: i64, oldest: i64) -> Self {
let batch_span = Duration::from_nanos(event_time.saturating_sub(oldest).max(0) as u64); let batch_span = Duration::from_nanos(event_time.saturating_sub(oldest).max(0) as u64);
Self { Self {
+2 -2
View File
@@ -338,7 +338,7 @@ fn the_first_events_batched_samples_are_dated_apart() {
let now = Instant::now(); let now = Instant::now();
// A 120Hz batch: three historical samples at 0/4/8ms and the event's // A 120Hz batch: three historical samples at 0/4/8ms and the event's
// own at 12ms. // own at 12ms.
let clock = PointerClock::anchored(now, 12 * MS, 0); let clock = DeviceClock::anchored(now, 12 * MS, 0);
assert_eq!( assert_eq!(
clock.at(12 * MS), clock.at(12 * MS),
@@ -363,7 +363,7 @@ fn the_first_events_batched_samples_are_dated_apart() {
#[test] #[test]
fn the_clock_orders_samples_across_events() { fn the_clock_orders_samples_across_events() {
const MS: i64 = 1_000_000; const MS: i64 = 1_000_000;
let mut clock = PointerClock::anchored(Instant::now(), 12 * MS, 0); let mut clock = DeviceClock::anchored(Instant::now(), 12 * MS, 0);
let first = clock.sample(12 * MS); let first = clock.sample(12 * MS);
let second = clock.sample(28 * MS); let second = clock.sample(28 * MS);
assert!(second > first); assert!(second > first);