From 42d54eec9566c6fdce1bafa4ec8e75e725a17ecf Mon Sep 17 00:00:00 2001 From: iris <2+iris@noreply.localhost> Date: Wed, 9 Sep 2026 00:49:28 -0400 Subject: [PATCH] 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 --- AGENTS.md | 15 ++ app-rust/Cargo.toml | 12 +- app-rust/src/android/bench_client.rs | 4 +- app-rust/tests/fling_profile.rs | 121 ++++++++++ docs/RUST.md | 65 +++++ docs/SCROLL.md | 11 + iris/core/src/render/frame_report.rs | 342 ++++++++++++++++++++++----- iris/core/src/render/mod.rs | 2 +- iris/src/android/render.rs | 39 +-- iris/src/android/view.rs | 154 ++++++++---- iris/src/default/mod.rs | 16 +- iris/src/default/render.rs | 12 +- iris/src/diagnostics.rs | 14 +- iris/src/harness.rs | 17 +- iris/src/sense.rs | 28 ++- iris/src/sense_tests.rs | 4 +- 16 files changed, 703 insertions(+), 153 deletions(-) create mode 100644 app-rust/tests/fling_profile.rs diff --git a/AGENTS.md b/AGENTS.md index c9724ce..f0025f4 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -389,6 +389,21 @@ Each exists because something was invisible without it. since the rig lives in iris and the app's examples do not). The emulator is for JNI, the IME, insets, the surface lifecycle and one verification run before a build goes to the phone -- not for iterating on layout. +- **`app-rust/tests/fling_profile.rs`** is what a fling frame costs on + the CPU, at layer 1 -- `cargo test --release --test fling_profile -- + --ignored --nocapture`, from `app-rust/`. It flings the real transcript + screen over the bench fixture eight times, out and back, and prints the + per-frame distribution with a count of how many frames did any layout at + all. `#[ignore]`d and assertion-free, so `run-tests.sh` neither runs it + nor can fail on it; **release or the numbers mean nothing**, since text + shaping dominates. Two things it established on 2026-09-09 that are + worth not re-deriving: only about one fling frame in six lays anything + out (the rest are moved on the GPU through `move_offsets`), and the + multi-millisecond spikes are all in the *first* pass over a stretch of + transcript -- every later pass over the same rows is p99 0.26ms. So a + warm fling is not CPU-bound in iris, and a phone report showing + otherwise is measuring something else. It cannot answer anything about + the GPU, the swapchain or the phone's own clock. - **The emulator is a GLES rig, deliberately** (Iris, 2026-09-08; docs/RUST.md). Its guest has no hardware Vulkan -- only SwiftShader in software -- while its GLES *is* the host's real GPU through virgl at diff --git a/app-rust/Cargo.toml b/app-rust/Cargo.toml index a759027..7be123c 100644 --- a/app-rust/Cargo.toml +++ b/app-rust/Cargo.toml @@ -111,7 +111,17 @@ panic = "abort" strip = true lto = "fat" codegen-units = 1 -opt-level = "s" +# **Speed, not size** (2026-09-09). This was `"s"`, chosen when the +# question was why the APK was double the Compose one -- but that was +# measured in bytes only, and `"s"` costs the loop vectorisation and +# inlining a renderer runs on. Measured with +# `app-rust/tests/fling_profile.rs`, the same warm fling eight times over: +# iris's own per-frame work is p90 0.15ms / p99 0.42ms at `"s"` and +# p90 0.09ms / p99 0.26ms at `3`, so about a third of the CPU half of a +# scrolling frame was being paid for 1.9 MB of download. The same +# argument the table in docs/RUST.md gives for refusing `"z"`, applied one +# level further up. +opt-level = 3 [profile.android-dev] inherits = "dev" diff --git a/app-rust/src/android/bench_client.rs b/app-rust/src/android/bench_client.rs index d257ef4..a122d55 100644 --- a/app-rust/src/android/bench_client.rs +++ b/app-rust/src/android/bench_client.rs @@ -821,7 +821,8 @@ impl BenchClient { format!( "frames:\n {} frames over {:.1}s at {:.0}Hz ({:.1}ms budget)\n \ late: {late} ({late_pct:.1}%)\n total p50 {:.1}ms p90 {:.1}ms \ - p99 {:.1}ms\n worst {:.1}ms\n cpu_p50 {:.1}ms gpu_wait_p50 {:.1}ms", + p99 {:.1}ms\n worst {:.1}ms\n build_p50 {:.1}ms acquire_p50 \ + {:.1}ms submit_p50 {:.1}ms", stats.total_frames, total_seconds, refresh_hz, @@ -831,6 +832,7 @@ impl BenchClient { stats.p99.as_secs_f64() * 1000.0, stats.worst.as_secs_f64() * 1000.0, stats.cpu_p50.as_secs_f64() * 1000.0, + stats.acquire_p50.as_secs_f64() * 1000.0, stats.gpu_wait_p50.as_secs_f64() * 1000.0, ) } diff --git a/app-rust/tests/fling_profile.rs b/app-rust/tests/fling_profile.rs new file mode 100644 index 0000000..635d956 --- /dev/null +++ b/app-rust/tests/fling_profile.rs @@ -0,0 +1,121 @@ +//! A profiling run rather than a test: what a fling frame costs on the +//! CPU, at layer 1 (docs/RUST.md's "Three test layers") -- the real +//! transcript screen over the real bench fixture, with no window, no +//! compositor and no GPU, on a clock this file owns. It exists so "the +//! fling stutters" can be attributed rather than guessed at, and it is +//! kept between investigations rather than rewritten each time (Iris, +//! 2026-09-09: "please keep the profiling rig around for future use"). +//! +//! cargo test --release --test fling_profile -- --ignored --nocapture +//! +//! `#[ignore]`d because it asserts nothing -- it prints a distribution, +//! so `run-tests.sh` neither runs it nor can fail on it. **Release, or +//! the numbers mean nothing**: layout is dominated by text shaping, which +//! is an order of magnitude slower unoptimised. +//! +//! What it cannot answer: anything about the GPU, the present queue, or +//! the phone's own clock. It measures the CPU half of a frame, which is +//! where `cpu_p50` in a phone bench report comes from. + +use ai_app::ui::fixture::{PHONE_FRAME_MS, PHONE_SCALE, phone_size}; +use iris::harness::{Harness, TouchScript}; +use iris::prelude::*; +use std::time::{Duration, Instant}; + +/// Passes over the same content, alternating direction. More than two +/// because the question the rig was built for is whether a frame's cost +/// is first-time work (which the first pass pays and the rest do not) or +/// work repeated every time a row comes back on screen. +const PASSES: usize = 8; +/// The velocity `bench_client.rs`'s fling phase uses, so a number here +/// and a number in a phone report describe the same gesture. +const VELOCITY: f32 = 12_000.0; +/// A fling settles on the spline's own schedule (~2s at this velocity); +/// this only stops a pass that somehow never settles from running away. +const PASS_CAP_MS: u64 = 4_000; + +fn pct(sorted: &[Duration], p: f64) -> f64 { + let i = ((sorted.len() as f64 - 1.0) * p).round() as usize; + sorted[i].as_secs_f64() * 1000.0 +} + +fn summarise(name: &str, samples: &[Duration]) { + let mut v = samples.to_vec(); + v.sort(); + let over_budget = v + .iter() + .filter(|d| **d > Duration::from_micros(8_333)) + .count(); + println!( + " {name:16} n={:<5} p50 {:.2}ms p90 {:.2}ms p99 {:.2}ms worst {:.2}ms \ + over-8.3ms {over_budget}", + v.len(), + pct(&v, 0.5), + pct(&v, 0.9), + pct(&v, 0.99), + pct(&v, 1.0), + ); +} + +#[test] +#[ignore] +fn what_a_fling_frame_costs() { + let mut h = Harness::new(phone_size(), PHONE_SCALE); + let opened = ai_app::ui::fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds"); + h.frame(0); + h.frame(PHONE_FRAME_MS); + + // The recorded flick first, so the velocity a real finger produces is + // in the log beside the scripted passes below. + let flick = TouchScript::parse(include_str!("../touch/flick-120hz.touch")).unwrap(); + h.replay(&flick); + println!( + "recorded flick released at {:?}px/s; scripted passes run at {VELOCITY}px/s", + (opened.screen.list)(&mut h.rsc).fling_velocity(), + ); + + let mut t = flick.end_ms(); + let mut all_frames = Vec::new(); + let mut all_layouts = Vec::new(); + for pass in 0..PASSES { + // Away from the newest end on the even passes and back on the + // odd ones, the same out-and-back the bench's fling phase drives. + let velocity = if pass % 2 == 0 { VELOCITY } else { -VELOCITY }; + let list = (opened.screen.list)(&mut h.rsc); + list.fling(velocity); + let id = opened.screen.list.id(); + h.rsc.ui.animate(id); + + let mut frames = Vec::new(); + let mut layouts = Vec::new(); + let end = t + PASS_CAP_MS; + while t <= end { + let at = Instant::now(); + h.frame(t); + frames.push(at.elapsed()); + layouts.push(h.render.last_layout_duration()); + t += PHONE_FRAME_MS; + if !(opened.screen.list)(&mut h.rsc).is_scrolling() { + break; + } + } + let laid_out = layouts + .iter() + .filter(|d| **d > Duration::from_micros(20)) + .count(); + println!( + "pass {pass} ({}): {} frames, {laid_out} did layout", + if velocity > 0.0 { "out " } else { "back" }, + frames.len(), + ); + summarise("frame", &frames); + all_frames.extend(frames); + all_layouts.extend(layouts); + // A moment at rest between passes, as a finger would leave. + t += 200; + } + + println!("\nall {PASSES} passes, primitives={}", h.render.active_primitive_count()); + summarise("frame", &all_frames); + summarise("layout", &all_layouts); +} diff --git a/docs/RUST.md b/docs/RUST.md index 1315559..2b06431 100644 --- a/docs/RUST.md +++ b/docs/RUST.md @@ -423,6 +423,71 @@ vectorisation on a renderer. Everything else is own rather than `release`, so the desktop build is not also optimised for size. +### The fling stutter, and what a frame report could not say (2026-09-09) + +Iris, from her phone: *"I'm noticing some stuttering when flinging in +particular. Harder to notice with my finger directly moving the scroll."* +Her report had the fling phase at 3396 frames over 33.0s -- 103fps on a +120Hz screen -- with p50 6.3ms and 13.4% "late". + +**The report was not measuring what its own labels claimed.** Three +things came out of chasing it, and the first two are corrections to the +instrument rather than to the renderer: + +1. **The swapchain acquire was counted as iris's CPU work.** + `AndroidRenderer::draw` timed `queue.submit` + `present()` and called + everything before it `redraw_to_submit`, but `get_current_texture` -- + which *blocks* until the compositor frees an image -- sits in that + span. An app comfortably ahead of the display spends most of every + frame there, so a healthy fling read as several milliseconds of iris + being slow. A frame is now three measured parts (`FrameParts`: + `build`, `acquire`, `submit`), per phase as well as per run, because + they do not divide the same way in every phase. + +2. **Nothing could say a frame was never produced.** `late` counts frames + that cost more than a budget, which is not the thing a reader sees: + a frame that is late but drawn shows up on the next vsync, while a + frame that never happens leaves the previous one on screen for two + refreshes. `PhaseStats::missed` counts vsyncs nothing was drawn for, + from the gap between consecutive frame times. + +3. **The frame loop asked for its next frame after doing the work.** + `Choreographer.postFrameCallback` schedules for the next vsync *after + the call*, so any frame whose work ran past the vsync boundary + registered too late for the next one and got the one after -- one + frame over budget silently cost a second frame as well. It is asked + for immediately after `tick_animations`, before the layout and the + draw. + +And one that is about the animation rather than the report: **the fling +was advanced on `Instant::now()`, not on the vsync the callback carried.** +`do_frame`'s `frame_time_nanos` was discarded. Frames are *presented* on +an even cadence whatever clock they are computed on, so sampling the +spline at "whenever the callback got to run" moves the content by an +uneven distance every frame -- a shimmer with no frame late enough to +appear in any report, and it is exactly the asymmetry Iris described, +since a drag's positions come from the finger's own timestamped samples +and never had it. `sense::PointerClock` is now `sense::DeviceClock` and +the view keeps **one**, anchored by whichever of a touch or a frame +arrives first, so a fling is advanced on the clock its velocity was +measured on. + +What the CPU side is *not*: `app-rust/tests/fling_profile.rs` (AGENTS.md's +rig list) puts iris's own per-frame work during a warm fling at p99 +0.26ms, with only one frame in six laying anything out at all. The +multi-millisecond spikes are first-pass only. + +### The Android release profile is `opt-level = 3`, not `"s"` (2026-09-09) + +The table above was measured in bytes only. `"s"` costs the loop +vectorisation and inlining a renderer runs on: 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`. The arm64 release APK goes +from 9,745,704 to 11,542,646 bytes (+1.8 MB) -- the same trade the table +refused for `"z"`, one level further up. Iris raised it herself +(*"I'd make sure it's in release mode"*); the build always was, and this +was the part of "release" that was not about speed. + ### Platform fonts, not bundled ones (2026-09-07) Iris: *"remove the font for now; just match what compose does."* The diff --git a/docs/SCROLL.md b/docs/SCROLL.md index 73275e4..8931a6c 100644 --- a/docs/SCROLL.md +++ b/docs/SCROLL.md @@ -90,6 +90,17 @@ layout that follows is also what keeps layout a pure function of the state (Iris, 2026-09-08). The visible consequence, and the thing that catches a test out: **`amt` does not move until the next draw.** +**Which clock a fling is ticked on.** The vsync the frame callback +carries, not `Instant::now()` -- on Android `do_frame`'s +`frame_time_nanos`, converted through the view's one `DeviceClock` +(`sense.rs`), which also dates every touch sample, so a fling is advanced +on the clock its own velocity was measured on. Frames are presented on an +even cadence whatever clock they are computed on, so sampling the spline +at "whenever the callback got to run" moves the content unevenly between +frames that are shown evenly -- a shimmer that no frame-time percentile +can see, since no frame was late. Found 2026-09-09; docs/RUST.md's +"The fling stutter" has the rest. + ### Why a remainder was not enough The `apply_scroll(&mut delta)` this replaced left the part it could not diff --git a/iris/core/src/render/frame_report.rs b/iris/core/src/render/frame_report.rs index 7d4fb4e..62830a9 100644 --- a/iris/core/src/render/frame_report.rs +++ b/iris/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/iris/core/src/render/mod.rs b/iris/core/src/render/mod.rs index 32b3071..9723a41 100644 --- a/iris/core/src/render/mod.rs +++ b/iris/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/iris/src/android/render.rs b/iris/src/android/render.rs index f01662f..1e86f98 100644 --- a/iris/src/android/render.rs +++ b/iris/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/iris/src/android/view.rs b/iris/src/android/view.rs index 07e3bad..183fc45 100644 --- a/iris/src/android/view.rs +++ b/iris/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/iris/src/default/mod.rs b/iris/src/default/mod.rs index 45a5da7..a5268c6 100644 --- a/iris/src/default/mod.rs +++ b/iris/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/iris/src/default/render.rs b/iris/src/default/render.rs index 12153e7..78deda1 100644 --- a/iris/src/default/render.rs +++ b/iris/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/iris/src/diagnostics.rs b/iris/src/diagnostics.rs index d114587..7484ae0 100644 --- a/iris/src/diagnostics.rs +++ b/iris/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/iris/src/harness.rs b/iris/src/harness.rs index c34050b..e173e49 100644 --- a/iris/src/harness.rs +++ b/iris/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/iris/src/sense.rs b/iris/src/sense.rs index bc43b82..a49539e 100644 --- a/iris/src/sense.rs +++ b/iris/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/iris/src/sense_tests.rs b/iris/src/sense_tests.rs index 466a3b2..d8f893b 100644 --- a/iris/src/sense_tests.rs +++ b/iris/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);