From e2a1fadbecccdea1e2eac63357d633fd62420ee1 Mon Sep 17 00:00:00 2001 From: iris <2+iris@noreply.localhost> Date: Sat, 5 Sep 2026 18:47:01 -0400 Subject: [PATCH] iris: FrameReport CPU/GPU split, force-gles backend switch, iris-scroll.sh rig Splits each frame sample at queue.submit into redraw-to-submit (iris's own CPU work) and submit-to-after-present (driver/GPU wait), so RUST.md's I5 "where does iris's frame time go" question can be answered with a number per half instead of a single total. Adds a force-gles Cargo feature that switches the Android wgpu::Instance from Backends::PRIMARY to Backends::GL at compile time (no runtime env-var path exists into an already-launched Android process on this machine), for isolating SwiftShader-Vulkan vs. GLES/virgl as the software-mode gap's cause. app/iris-scroll.sh extracts transcript-bench.sh's exact 24-swipe/6-cycle gesture loop for iris's own demo app, which transcript-bench.sh cannot drive directly since it opens a session through the Compose app's own UI. Verification (this pass, on a disk-pressure-limited host running low on space): cargo fmt --all clean, no diff. cargo clippy --workspace --all-targets: no warnings from this diff (pre-existing future-incompat notices from wgpu/winit/naga only). cargo test --workspace and cargo ndk for iris-android-app --features transcript-screen were verified clean by the previous pass on this identical diff (fmt/clippy/test/ndk all clean, per that pass's own report); not re-run here because the host's disk was 93% full and a concurrent ai-server rebuild (stable toolchain moved to 1.98.1, rebuilding aws-lc-sys from scratch) had driven I/O pressure to ~60%, so a repeat cargo test --workspace sat 50+ minutes doing no useful work and was stopped rather than left to make the disk situation worse. Co-Authored-By: Claude Fable 5.1 --- app/iris-scroll.sh | 34 ++++++++++ iris/Cargo.toml | 10 +++ iris/android-app/Cargo.toml | 4 ++ iris/core/src/render/frame_report.rs | 92 +++++++++++++++++++++++++++- iris/src/android/render.rs | 29 ++++++++- iris/src/android/view.rs | 4 +- 6 files changed, 166 insertions(+), 7 deletions(-) create mode 100755 app/iris-scroll.sh diff --git a/app/iris-scroll.sh b/app/iris-scroll.sh new file mode 100755 index 0000000..538d9f0 --- /dev/null +++ b/app/iris-scroll.sh @@ -0,0 +1,34 @@ +#!/bin/sh +# RUST.md's I5 "Where iris's frame time goes" pass (2026-09-05). The same +# 24-swipe/6-cycle loop as transcript-bench.sh's, extracted for iris's own +# demo app -- transcript-bench.sh itself is Compose-specific (opens by +# session title through the Compose app's own UI) and cannot be called +# directly against dev.iris.android.demo. +# +# MUST be run from inside this checkout (not /tmp): ui-trace/adb pick which +# emulator to target from the current directory's basename (the +# per-checkout-AVD rule), and a previous pass lost two attempts to a `cd` +# into /tmp that made this resolve to a nonexistent "tmp" checkout. +set -eu +cd "$(dirname "$0")" +. ./android-env.sh >/dev/null 2>&1 + +cycles=${1:-6} + +ui-trace record -d 3000 --do "tap 'Reset frame report'" -o /tmp/iris-bench-reset.txt >/dev/null +adb logcat -c + +DO="" +i=0 +while [ "$i" -lt "$cycles" ]; do + DO="$DO --do 'swipe 540 700 540 1600 200' --do 'wait 500'" + DO="$DO --do 'swipe 540 700 540 1600 200' --do 'wait 500'" + DO="$DO --do 'swipe 540 1600 540 700 200' --do 'wait 500'" + DO="$DO --do 'swipe 540 1600 540 700 200' --do 'wait 500'" + i=$((i + 1)) +done +eval ui-trace record -d $((cycles * 16000 + 20000)) $DO -o /tmp/iris-bench-scroll.txt >/dev/null + +ui-trace record -d 3000 --do "tap 'Frame report'" -o /tmp/iris-bench-report.txt >/dev/null +sleep 1 +adb logcat -d -s iris-android-app:I | grep "iris frame report:" diff --git a/iris/Cargo.toml b/iris/Cargo.toml index ddb4445..980afdd 100644 --- a/iris/Cargo.toml +++ b/iris/Cargo.toml @@ -57,6 +57,16 @@ send_wrapper = "0.6.0" # installs it -- this crate never installs a logger itself. log = "0.4.28" +[features] +# RUST.md's I5 "Where iris's frame time goes" diagnosis: forces the Android +# `wgpu::Instance` to `Backends::GL` instead of `Backends::PRIMARY`, so the +# same build can be measured against SwiftShader's software Vulkan ICD (the +# default) or virgl's GLES path, without a second env-var plumbing path that +# nothing on this machine can hand to an already-launched Android process +# (there is no `am start` environment and no system-property reader here to +# add one). Android-only; `android/render.rs` is the only reader. +force-gles = [] + [dev-dependencies] tokio = { workspace = true, features = ["sync", "rt", "rt-multi-thread", "time"] } # The tabs example's widget tree. A dev-dependency cycle back to this diff --git a/iris/android-app/Cargo.toml b/iris/android-app/Cargo.toml index fc5d751..776cbb4 100644 --- a/iris/android-app/Cargo.toml +++ b/iris/android-app/Cargo.toml @@ -37,6 +37,10 @@ serde_json = { version = "1", features = ["float_roundtrip"], optional = true } default = ["tabs-screen"] tabs-screen = ["dep:tabs-ui"] transcript-screen = ["dep:transcript-ui", "dep:client-core", "dep:event-model", "dep:serde_json"] +# RUST.md's I5 "Where iris's frame time goes": forces the GLES backend +# instead of SwiftShader's software Vulkan. See `iris/Cargo.toml`'s own doc +# on the feature this forwards to. +force-gles = ["iris/force-gles"] [profile.release] panic = "abort" diff --git a/iris/core/src/render/frame_report.rs b/iris/core/src/render/frame_report.rs index 89a3433..e944d90 100644 --- a/iris/core/src/render/frame_report.rs +++ b/iris/core/src/render/frame_report.rs @@ -35,6 +35,12 @@ const RING_CAPACITY: usize = 4096; /// ever called from a button tap, not once per frame. pub struct FrameReport { ring: Box<[Duration; RING_CAPACITY]>, + /// The `submit_to_present` half of each sample in `ring`, same index, + /// 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. + submit_ring: Box<[Duration; RING_CAPACITY]>, /// How many of `ring`'s slots hold a real sample -- saturates at /// `RING_CAPACITY`, unlike `total_frames` below which keeps counting. len: usize, @@ -56,6 +62,20 @@ 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. + pub cpu_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 + /// fenced against the GPU actually finishing, so this is "how long the + /// CPU was blocked handing the frame off", not the frame's true GPU + /// time -- still enough to separate "iris is slow building the frame" + /// from "iris is slow handing it to the driver". + pub gpu_wait_p50: Duration, } impl std::fmt::Display for FrameStats { @@ -71,6 +91,13 @@ impl std::fmt::Display for FrameStats { self.p90.as_secs_f64() * 1000.0, self.p99.as_secs_f64() * 1000.0, self.worst.as_secs_f64() * 1000.0, + )?; + write!( + f, + " cpu_p50={:.1}ms gpu_wait_p50={:.1}ms (redraw-start-to-submit vs. \ + submit-to-after-present)", + self.cpu_p50.as_secs_f64() * 1000.0, + self.gpu_wait_p50.as_secs_f64() * 1000.0, ) } } @@ -79,6 +106,7 @@ impl FrameReport { pub fn new() -> Self { Self { ring: Box::new([Duration::ZERO; RING_CAPACITY]), + submit_ring: Box::new([Duration::ZERO; RING_CAPACITY]), len: 0, pos: 0, total_frames: 0, @@ -86,13 +114,27 @@ impl FrameReport { } } - /// Record one frame's elapsed wall time. O(1), no allocation. + /// 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.ring[self.pos] = elapsed; + 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; self.pos = (self.pos + 1) % RING_CAPACITY; self.len = (self.len + 1).min(RING_CAPACITY); self.total_frames += 1; - if elapsed > JANK_THRESHOLD { + if total > JANK_THRESHOLD { self.janky_frames += 1; } } @@ -118,6 +160,21 @@ impl FrameReport { let mut samples: Vec = self.ring[..self.len].to_vec(); samples.sort_unstable(); let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)]; + + // Separate arrays rather than subtracting the two medians above: + // 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 median = |mut v: Vec| { + v.sort_unstable(); + v[v.len() / 2] + }; + Some(FrameStats { total_frames: self.total_frames, janky_percent: 100.0 * self.janky_frames as f64 / self.total_frames as f64, @@ -125,6 +182,8 @@ impl FrameReport { p90: pct(90), p99: pct(99), worst: *samples.last().expect("len > 0 checked above"), + cpu_p50: median(cpu_samples), + gpu_wait_p50: median(submit_samples), }) } } @@ -196,6 +255,33 @@ mod tests { assert_eq!(r.report().unwrap().janky_percent, 0.0); } + #[test] + fn record_without_a_split_reports_the_whole_frame_as_cpu() { + // A caller that never measured the split (plain `record`) should + // 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)); + 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() { + 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)); + 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)); + } + #[test] fn ring_wraps_without_growing_past_capacity() { let mut r = FrameReport::new(); diff --git a/iris/src/android/render.rs b/iris/src/android/render.rs index 4d27e51..25649e2 100644 --- a/iris/src/android/render.rs +++ b/iris/src/android/render.rs @@ -6,6 +6,7 @@ use android_view::{ }; use iris_core::{UiData, UiRenderNode, UiRenderState}; use pollster::FutureExt; +use std::time::{Duration, Instant}; use wgpu::{ rwh::{DisplayHandle, HandleError, HasDisplayHandle, HasWindowHandle, WindowHandle}, *, @@ -51,8 +52,19 @@ pub struct AndroidRenderer { impl AndroidRenderer { pub fn new(window: NativeWindow, width: u32, height: u32) -> Self { + // `force-gles` (RUST.md's I5 "Where iris's frame time goes") swaps + // the software-Vulkan (SwiftShader) path for GLES/virgl on the same + // build, to isolate whether the backend itself explains the frame + // time gap against Compose. `cfg!` rather than a runtime switch: + // there is no way to hand an env var to an already-launched Android + // process on this machine (see the feature's doc in Cargo.toml). + let backends = if cfg!(feature = "force-gles") { + Backends::GL + } else { + Backends::PRIMARY + }; let instance = Instance::new(&InstanceDescriptor { - backends: Backends::PRIMARY, + backends, ..Default::default() }); @@ -128,7 +140,18 @@ impl AndroidRenderer { self.ui.update(&self.device, &self.queue, ui, render); } - pub fn draw(&mut self) { + /// 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 { let output = self.surface.get_current_texture().unwrap(); let view = output .texture @@ -151,8 +174,10 @@ impl AndroidRenderer { self.ui.draw(render_pass); } + let submit_start = Instant::now(); self.queue.submit(std::iter::once(encoder.finish())); output.present(); + submit_start.elapsed() } pub fn size(&self) -> iris_core::util::Vec2 { diff --git a/iris/src/android/view.rs b/iris/src/android/view.rs index 501421b..f735c21 100644 --- a/iris/src/android/view.rs +++ b/iris/src/android/view.rs @@ -282,11 +282,11 @@ impl IrisViewPeer { return; }; renderer.update(&mut self.rsc.ui, &mut self.render); - renderer.draw(); + let submit_to_present = renderer.draw(); self.state .android_state_mut() .frame_report - .record(frame_start.elapsed()); + .record_split(frame_start.elapsed(), submit_to_present); let ui_state = self.state.android_state(); log::debug!( "render(): after update active={} root_px={:?}",