diff --git a/core/src/render/frame_report.rs b/core/src/render/frame_report.rs index 7d4fb4e..62830a9 100644 --- a/core/src/render/frame_report.rs +++ b/core/src/render/frame_report.rs @@ -49,6 +49,29 @@ pub struct PhaseStats { pub p90: Duration, pub p99: 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 /// are still in the ring -- the percentiles above are then computed /// 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)" }, )?; - writeln!(f, " late: {} ({:.1}%)", self.late, self.late_percent)?; + writeln!( + f, + " late: {} ({:.1}%) missed vsyncs: {}", + self.late, self.late_percent, self.missed, + )?; writeln!( f, " 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.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) } } +/// 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 /// gfxinfo` cannot see a `SurfaceView`'s own GPU-drawn frames at all /// (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 /// 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). - /// `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]>, + /// 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, /// 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 @@ -145,12 +253,18 @@ pub struct FrameStats { pub p90: Duration, pub p99: Duration, pub worst: Duration, - /// Median of `redraw_to_submit` -- iris's own CPU work (layout, text, - /// primitive building) up to and including building the `queue.submit` - /// call, per frame. 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 - /// guess. + /// Median of [`FrameParts::build`] -- iris's own CPU work per frame: + /// laying out, shaping text, building primitives and recording the + /// 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 guess, and corrected on 2026-09-09 to stop counting the + /// swapchain wait below as iris's own work. 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 /// `present()`, i.e. wherever the driver/GPU/compositor wait actually /// happens. Same caveat as the type's own doc: `present()` is not @@ -177,9 +291,10 @@ impl std::fmt::Display for FrameStats { )?; write!( f, - " cpu_p50={:.1}ms gpu_wait_p50={:.1}ms (redraw-start-to-submit vs. \ - submit-to-after-present)", + " cpu_p50={:.1}ms acquire_p50={:.1}ms gpu_wait_p50={:.1}ms (own work vs. \ + waiting for a swapchain image vs. submit-to-after-present)", 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, ) } @@ -190,6 +305,9 @@ impl FrameReport { Self { 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]), len: 0, pos: 0, @@ -199,28 +317,26 @@ impl FrameReport { } } - /// Record one frame's elapsed wall time, with no CPU/GPU split (the - /// `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 - /// that never measured the split, rather than fabricating one). O(1), - /// no allocation. - pub fn record(&mut self, elapsed: Duration) { - self.record_split(elapsed, Duration::ZERO); - } - - /// Record one frame's elapsed wall time, split at `queue.submit`: - /// `submit_to_present` is the `queue.submit()` call plus `present()`; - /// `total - submit_to_present` is everything before it (layout, text, - /// primitive building). RUST.md's I5 "Where iris's frame time goes" - /// CPU/GPU split, added 2026-09-05. O(1), no allocation. - pub fn record_split(&mut self, total: Duration, submit_to_present: Duration) { - self.ring[self.pos] = total; - self.submit_ring[self.pos] = submit_to_present; + /// Record one frame, split into [`FrameParts`]. O(1), no allocation. + /// + /// One entry point rather than one per shape of measurement: a caller + /// 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, + }; + self.last_at = Some(at); + self.ring[self.pos] = parts.total; + self.submit_ring[self.pos] = parts.submit; + self.acquire_ring[self.pos] = parts.acquire; self.index_ring[self.pos] = self.total_frames; self.pos = (self.pos + 1) % RING_CAPACITY; self.len = (self.len + 1).min(RING_CAPACITY); self.total_frames += 1; - if total > JANK_THRESHOLD { + if parts.total > JANK_THRESHOLD { self.janky_frames += 1; } } @@ -236,9 +352,20 @@ impl FrameReport { self.pos = 0; self.total_frames = 0; self.janky_frames = 0; + self.last_at = None; 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 /// frame recorded from here until the next `mark_phase` (or `reset`) /// belongs to it. RUST.md's "Benchmark v2": a scripted bench run calls @@ -281,13 +408,13 @@ impl FrameReport { None => (self.total_frames, now), }; let frames = end_index.saturating_sub(phase.start_index); - let mut samples: Vec = (0..self.len) + let slots: Vec = (0..self.len) .filter(|&j| { let idx = self.index_ring[j]; idx >= phase.start_index && idx < end_index }) - .map(|j| self.ring[j]) .collect(); + let mut samples: Vec = slots.iter().map(|&j| self.ring[j]).collect(); let complete = samples.len() as u64 >= frames; if samples.is_empty() { return PhaseStats { @@ -300,9 +427,40 @@ impl FrameReport { p90: Duration::ZERO, p99: Duration::ZERO, worst: Duration::ZERO, + missed: 0, + build_p50: Duration::ZERO, + acquire_p50: Duration::ZERO, + submit_p50: Duration::ZERO, 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 = 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(); let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)]; let late = samples.iter().filter(|&&d| d > budget).count() as u64; @@ -316,6 +474,10 @@ impl FrameReport { p90: pct(90), p99: pct(99), worst: *samples.last().expect("checked not empty above"), + missed, + build_p50, + acquire_p50, + submit_p50, complete, } }) @@ -337,11 +499,8 @@ impl FrameReport { // medians do not distribute over subtraction, and each needs its // own sort. let submit_samples: Vec = self.submit_ring[..self.len].to_vec(); - let cpu_samples: Vec = self.ring[..self.len] - .iter() - .zip(self.submit_ring[..self.len].iter()) - .map(|(&total, &submit_to_present)| total.saturating_sub(submit_to_present)) - .collect(); + let acquire_samples: Vec = self.acquire_ring[..self.len].to_vec(); + let cpu_samples: Vec = (0..self.len).map(|j| self.parts(j).build()).collect(); let median = |mut v: Vec| { v.sort_unstable(); v[v.len() / 2] @@ -355,6 +514,7 @@ impl FrameReport { p99: pct(99), worst: *samples.last().expect("len > 0 checked above"), cpu_p50: median(cpu_samples), + acquire_p50: median(acquire_samples), gpu_wait_p50: median(submit_samples), }) } @@ -400,7 +560,7 @@ mod tests { #[test] fn one_frame_is_every_percentile_and_the_worst() { 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(); assert_eq!(stats.total_frames, 1); 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 // order is not what gives the right answer -- the sort has to. 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(); assert_eq!(stats.total_frames, 100); @@ -428,8 +588,14 @@ mod tests { #[test] fn jank_threshold_matches_gfxinfos_60hz_budget() { let mut r = FrameReport::new(); - r.record(Duration::from_nanos(16_666_667)); // exactly on budget: not janky - r.record(Duration::from_nanos(16_666_668)); // one ns over: janky + r.record( + 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(); 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. let mut r = FrameReport::new(); 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); r.reset(); 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); } @@ -455,32 +621,94 @@ 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(Duration::from_millis(20)); + r.record(Instant::now(), FrameParts::whole(Duration::from_millis(20))); let stats = r.report().unwrap(); assert_eq!(stats.cpu_p50, Duration::from_millis(20)); assert_eq!(stats.gpu_wait_p50, Duration::ZERO); } #[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(); - // Three frames: total is always 30ms, but the CPU/GPU-wait split - // moves, so the two medians must be independent of each other and - // of `total`'s own median. - r.record_split(Duration::from_millis(30), Duration::from_millis(5)); - r.record_split(Duration::from_millis(30), Duration::from_millis(10)); - r.record_split(Duration::from_millis(30), Duration::from_millis(20)); + // Three frames of the same 30ms total, with the split moving: + // each part needs its own sort, and `build` is what is left after + // both waits -- not the total, which is the bug this replaced + // (the swapchain wait used to be counted as iris's own work). + for (acquire, submit) in [(5, 2), (10, 3), (20, 4)] { + 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(); assert_eq!(stats.p50, Duration::from_millis(30)); - assert_eq!(stats.gpu_wait_p50, Duration::from_millis(10)); - assert_eq!(stats.cpu_p50, Duration::from_millis(20)); + assert_eq!(stats.acquire_p50, Duration::from_millis(10)); + 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] fn ring_wraps_without_growing_past_capacity() { let mut r = FrameReport::new(); 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(); // total_frames keeps the full count even once the ring has wrapped. @@ -494,7 +722,7 @@ mod tests { #[test] fn no_marks_means_no_phases() { 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()); } @@ -503,11 +731,11 @@ mod tests { let mut r = FrameReport::new(); r.mark_phase("a"); 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"); 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 phases = r.phase_stats(now, 60.0); @@ -529,7 +757,7 @@ mod tests { fn the_last_phase_runs_until_now() { let mut r = FrameReport::new(); 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)); let now = Instant::now(); let phases = r.phase_stats(now, 60.0); @@ -541,7 +769,7 @@ mod tests { fn reset_clears_phase_marks() { let mut r = FrameReport::new(); r.mark_phase("a"); - r.record(Duration::from_millis(1)); + r.record(Instant::now(), FrameParts::whole(Duration::from_millis(1))); r.reset(); 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() { let mut r = FrameReport::new(); // 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(120.0), (1, 100.0)); } diff --git a/core/src/render/mod.rs b/core/src/render/mod.rs index 32b3071..9723a41 100644 --- a/core/src/render/mod.rs +++ b/core/src/render/mod.rs @@ -24,7 +24,7 @@ mod util; pub use atlas::*; 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 sdf::{distance_from_rect, rounded_rect_coverage}; diff --git a/src/android/render.rs b/src/android/render.rs index f01662f..1e86f98 100644 --- a/src/android/render.rs +++ b/src/android/render.rs @@ -4,9 +4,9 @@ use android_view::{ jni::{JavaVM, objects::GlobalRef}, ndk::native_window::NativeWindow, }; -use iris_core::{UiData, UiRenderNode, UiRenderState}; +use iris_core::{FrameParts, UiData, UiRenderNode, UiRenderState}; use pollster::FutureExt; -use std::time::{Duration, Instant}; +use std::time::Instant; use wgpu::{ rwh::{DisplayHandle, HandleError, HasDisplayHandle, HasWindowHandle, WindowHandle}, *, @@ -415,18 +415,26 @@ impl AndroidRenderer { self.frame_count } - /// Draws and presents one frame, returning the time spent in - /// `queue.submit` plus `present()` -- wherever a driver/GPU/compositor - /// wait would actually show up. The caller (`android::view::render`) - /// already times the whole frame from its own `redraw_to_submit` start; - /// subtracting this from that total is `redraw_to_submit` itself - /// (layout, text, primitive building, and this method's own render-pass - /// recording). RUST.md's I5 "Where iris's frame time goes" diagnosis, - /// added 2026-09-05 -- see `iris_core::FrameReport::record_split`'s own - /// doc for the caveat this shares: `present()` is not fenced against - /// the GPU actually finishing, so this is "how long the CPU was blocked - /// handing the frame off", not confirmed GPU time. - pub fn draw(&mut self) -> Duration { + /// Draws and presents one frame, returning the two parts of it that + /// are waits rather than work: the `get_current_texture` acquire and + /// `queue.submit` + `present()`. The caller + /// (`android::view::render`) times the whole frame and fills in + /// `FrameParts::total`, so whatever is left over is iris's own work. + /// + /// **The acquire is why this returns two numbers and not one.** + /// `get_current_texture` blocks until the compositor hands back a + /// swapchain image, which on an app comfortably ahead of the display + /// is most of every frame -- so counting it as CPU work (which this + /// did until 2026-09-09) reports a fling as milliseconds of iris + /// 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() { CurrentSurfaceTexture::Success(texture) | CurrentSurfaceTexture::Suboptimal(texture) => texture, @@ -435,6 +443,7 @@ impl AndroidRenderer { // which is new. other => panic!("no surface texture to draw into: {other:?}"), }; + let acquire = acquire_start.elapsed(); let view = output .texture .create_view(&TextureViewDescriptor::default()); @@ -459,7 +468,7 @@ impl AndroidRenderer { let submit_start = Instant::now(); self.queue.submit(std::iter::once(encoder.finish())); self.queue.present(output); - submit_start.elapsed() + FrameParts::waits(acquire, submit_start.elapsed()) } /// Physical pixels -- the unit layout and hit-testing use, matching diff --git a/src/android/view.rs b/src/android/view.rs index 07e3bad..183fc45 100644 --- a/src/android/view.rs +++ b/src/android/view.rs @@ -312,11 +312,14 @@ pub struct IrisViewPeer { pub(super) render: UiRenderState, pub(super) state: State, task_recv: TaskMsgReceiver>, - /// Anchored on the first `MotionEvent` this view receives and never - /// re-anchored after -- how `on_touch_event` dates every touch sample. - /// Its path out is the peer's own drop: it holds nothing but three - /// numbers and is meaningless to any other view. - input_clock: Option, + /// The one ruler this view dates everything on: touch samples in + /// `on_touch_event` and the `Choreographer` frame time in `do_frame`. + /// Anchored by whichever of the two arrives first and never + /// re-anchored after, which is what lets a fling be advanced on the + /// 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, } impl>> std::ops::Index for AndroidRsc { @@ -390,6 +393,22 @@ impl IrisViewPeer { } } + /// 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 { let ui_state = self.state.android_state(); match &ui_state.renderer { @@ -412,7 +431,7 @@ impl IrisViewPeer { /// every level the app's already-`Debug` install lets through /// regardless of target, so they filled the whole ring in under ten /// 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() { return; } @@ -476,12 +495,31 @@ impl IrisViewPeer { // both count. See `iris_core::FrameReport`'s own doc for exactly // what this does and does not measure. let frame_start = Instant::now(); - // Anything moving on its own -- today a `LazySpan` coasting through a - // fling -- is advanced here, before the draw, and asks for the - // next frame at the end of this one. See - // `UiData::tick_animations`; `default/mod.rs`'s - // `RedrawRequested` arm is the same two lines for winit. - let animating = self.rsc.ui.tick_animations(frame_start); + // Anything moving on its own -- today a `LazySpan` coasting + // through a fling -- is advanced here, before the draw. **On + // `now`, not on `frame_start`**: `now` is the vsync the + // `Choreographer` handed this callback, which is evenly spaced, + // while `frame_start` is whenever the callback actually got to + // 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(); self.render.update(&ui_state.root, &mut self.rsc); let ui_state = self.state.android_state_mut(); @@ -509,18 +547,16 @@ impl IrisViewPeer { 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 .android_state_mut() .frame_report - .record_split(frame_start.elapsed(), submit_to_present); - crate::diagnostics::log_frame(&self.render, frame_start, submit_to_present, 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); - } + .record(now, parts); + crate::diagnostics::log_frame(&self.render, now, parts, animating); if crate::diagnostics::trace_enabled() { let ui_state = self.state.android_state(); log::debug!( @@ -632,28 +668,32 @@ impl ViewPeer for IrisViewPeer { // -- see `AndroidUiState::content_scale`'s field comment. let x = event.x(&mut ctx.env); let y = event.y(&mut ctx.env); - // The event's own clock, converted through one anchor taken on the - // first touch this view ever sees. Android reports sample times in - // the `SystemClock.uptimeMillis()` base, which is the same - // `CLOCK_MONOTONIC` an `Instant` reads, so a single - // `(Instant, nanos)` pair converts every later sample exactly. - // Anchoring **once** rather than per event is what keeps the times - // ordered, and anchoring on the first event's *oldest* sample - // rather than on its own time is what keeps that event's batch - // from collapsing onto one instant -- `sense::PointerClock`'s doc - // has both, and owns the arithmetic so it can be unit-tested off a - // device (`sense_tests.rs`). See `CursorState::time`. + // The event's own clock, converted through the view's one anchor + // -- taken on whichever of a touch or a frame callback came first. + // Android reports sample times in the `SystemClock.uptimeMillis()` + // base, which is the same `CLOCK_MONOTONIC` an `Instant` reads, so + // a single `(Instant, nanos)` pair converts every later sample + // exactly. Anchoring **once** rather than per event is what keeps + // the times ordered, and anchoring on the first event's *oldest* + // sample rather than on its own time is what keeps that event's + // batch from collapsing onto one instant -- `sense::DeviceClock`'s + // doc has both, and owns the arithmetic so it can be unit-tested + // off a device (`sense_tests.rs`). See `CursorState::time`. 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 oldest = if history > 0 { - event.historical_event_time_nanos(&mut ctx.env, 0) - } else { - event_time - }; - self.input_clock = Some(PointerClock::anchored(Instant::now(), event_time, oldest)); - } - let mut clock = self.input_clock.expect("anchored just above"); + 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 { + event.historical_event_time_nanos(&mut ctx.env, 0) + } else { + event_time + }; + self.device_clock(event_time, oldest) + } + }; // `iris::input`'s own doc (`sense::log_input_event`): collected // only when tracing is on, since this is otherwise a `Vec` per // `MotionEvent` for a line nobody is reading -- the JNI reads @@ -676,12 +716,11 @@ impl ViewPeer for IrisViewPeer { // motion the finger actually made; only the last sample ends the // frame (`after_input`). if matches!(action, MotionAction::Move) { - let history = event.history_size(&mut ctx.env); // Android documents the historical samples as oldest first and // the event's own sample as the newest of the batch; everything // downstream (`VelocityTracker`, `DragArbiter`'s long-press // 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 // every event is checked against the previous event's last one // rather than against the anchor. @@ -702,7 +741,7 @@ impl ViewPeer for IrisViewPeer { let event_at = clock.sample(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(); ui_state.cursor.time = event_at; match action { @@ -837,7 +876,7 @@ impl ViewPeer for IrisViewPeer { .as_mut() .expect("checked Some above") .resize(width as u32, height as u32); - self.render(ctx); + self.render(ctx, Instant::now()); return; } @@ -888,7 +927,7 @@ impl ViewPeer for IrisViewPeer { ); self.rsc.ui.textures.reupload(); self.state.android_state_mut().renderer = Some(renderer); - self.render(ctx); + self.render(ctx, Instant::now()); } Err(report) => { // One line for logcat (UI_RULES.md: "the full text for @@ -930,9 +969,20 @@ impl ViewPeer for IrisViewPeer { 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.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`) @@ -946,7 +996,9 @@ impl ViewPeer for IrisViewPeer { /// one. fn delayed_callback(&mut self, ctx: &mut CallbackCtx) { 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> { @@ -1072,7 +1124,7 @@ pub fn new_peer<'local, State: AndroidAppState>( render, state, task_recv, - input_clock: None, + device_clock: None, }; let id = android_view::register_view_peer(peer); super::insets::register(id, shared); diff --git a/src/default/mod.rs b/src/default/mod.rs index 45a5da7..a5268c6 100644 --- a/src/default/mod.rs +++ b/src/default/mod.rs @@ -342,14 +342,20 @@ impl AppState for DefaultApp { let frame_start = std::time::Instant::now(); let animating = rsc.ui_mut().tick_animations(frame_start); let ui_state = state.default_state_mut(); - render.update(&ui_state.root, rsc); - ui_state.renderer.update(&mut rsc.ui, render); - let draw_start = std::time::Instant::now(); - ui_state.renderer.draw(); - crate::diagnostics::log_frame(render, frame_start, draw_start.elapsed(), animating); + // Asked for before the work rather than after it, the same + // way `IrisViewPeer::render` does and for the same reason + // -- see the longer comment there. winit coalesces + // repeated requests, so the only thing the order changes + // is whether the request is in before this frame's draw + // can push it past a vsync boundary. if animating { 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 // set actually changed this frame -- see `AccessTree`'s doc // comment. `render` reflects the draw that just happened, diff --git a/src/default/render.rs b/src/default/render.rs index 12153e7..78deda1 100644 --- a/src/default/render.rs +++ b/src/default/render.rs @@ -1,7 +1,8 @@ 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 std::sync::Arc; +use std::time::Instant; use wgpu::*; use winit::{dpi::PhysicalSize, window::Window}; @@ -28,7 +29,11 @@ impl UiRenderer { 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() { CurrentSurfaceTexture::Success(texture) | CurrentSurfaceTexture::Suboptimal(texture) => texture, @@ -39,6 +44,7 @@ impl UiRenderer { // comment was written about. other => panic!("no surface texture to draw into: {other:?}"), }; + let acquire = acquire_start.elapsed(); let view = output .texture .create_view(&TextureViewDescriptor::default()); @@ -60,6 +66,7 @@ impl UiRenderer { self.ui.draw(render_pass); } + let submit_start = Instant::now(); self.queue.submit(std::iter::once(encoder.finish())); // Immediately before presenting, so the windowing system can schedule // 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. self.window.pre_present_notify(); self.queue.present(output); + FrameParts::waits(acquire, submit_start.elapsed()) } pub fn resize(&mut self, size: &PhysicalSize) { diff --git a/src/diagnostics.rs b/src/diagnostics.rs index d114587..7484ae0 100644 --- a/src/diagnostics.rs +++ b/src/diagnostics.rs @@ -26,9 +26,9 @@ //! has open at the same time this was written. `set_trace` is the whole //! surface a button needs; wiring one is a follow-up. 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); @@ -61,7 +61,7 @@ pub fn trace_enabled() -> bool { /// 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 /// 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() { return; } @@ -71,12 +71,14 @@ pub fn log_frame(render: &UiRenderState, now: Instant, draw: Duration, animating .unwrap_or_else(|| "none".to_string()); log::debug!( target: "iris::frame", - "iris frame: n={} now={}ms since_input={since_input} layout={:?} draw={:?} \ - redraw={:?} primitives={} animating={animating}", + "iris frame: n={} now={}ms since_input={since_input} layout={:?} build={:?} \ + acquire={:?} submit={:?} redraw={:?} primitives={} animating={animating}", render.frame_number(), now.duration_since(render.epoch()).as_millis(), render.last_layout_duration(), - draw, + parts.build(), + parts.acquire, + parts.submit, render.last_redraw_kind(), render.active_primitive_count(), ); diff --git a/src/harness.rs b/src/harness.rs index c34050b..e173e49 100644 --- a/src/harness.rs +++ b/src/harness.rs @@ -359,14 +359,21 @@ impl Harness { update(&mut self.state, &mut self.rsc); } let now = self.at(t_ms); + let at = Instant::now(); let animating = self.rsc.ui.tick_animations(now); self.render.update(&self.state.root, &mut self.rsc); - // No GPU here, so there is no draw phase to time -- `draw` is - // always zero. `layout`/`redraw`/`primitives` are still real, - // because `render.update` just ran; see - // `iris::diagnostics::log_frame`'s own doc for why this reads + // No GPU here, so there is nothing to acquire and nothing to + // submit: the frame is all `build`, which is honest rather than + // zero-filled (`FrameParts::whole`). `layout`/`redraw`/ + // `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. - 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 diff --git a/src/sense.rs b/src/sense.rs index bc43b82..a49539e 100644 --- a/src/sense.rs +++ b/src/sense.rs @@ -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 -/// through **one** anchor taken at the first event, so that every sample -/// this process ever sees is dated on a single ruler. +/// Converts a platform's own monotonic timestamps into [`Instant`]s +/// through **one** anchor, so that everything this process is told the +/// 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, /// 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 -/// [`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**, /// 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 /// attached mid-gesture). Found by review, 2026-09-07. #[derive(Clone, Copy)] -pub struct PointerClock { +pub struct DeviceClock { anchor_at: Instant, anchor_nanos: i64, last_nanos: i64, } -impl PointerClock { +impl DeviceClock { /// `now` is when the first event arrived, `event_time` its own /// 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 { let batch_span = Duration::from_nanos(event_time.saturating_sub(oldest).max(0) as u64); Self { diff --git a/src/sense_tests.rs b/src/sense_tests.rs index 466a3b2..d8f893b 100644 --- a/src/sense_tests.rs +++ b/src/sense_tests.rs @@ -338,7 +338,7 @@ fn the_first_events_batched_samples_are_dated_apart() { let now = Instant::now(); // A 120Hz batch: three historical samples at 0/4/8ms and the event's // own at 12ms. - let clock = PointerClock::anchored(now, 12 * MS, 0); + let clock = DeviceClock::anchored(now, 12 * MS, 0); assert_eq!( clock.at(12 * MS), @@ -363,7 +363,7 @@ fn the_first_events_batched_samples_are_dated_apart() { #[test] fn the_clock_orders_samples_across_events() { 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 second = clock.sample(28 * MS); assert!(second > first);