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 <noreply@anthropic.com>
This commit is contained in:
1 parent
0e4629361b
commit
e2a1fadbec
6 files changed
+166
-7
No files matched your search
Executable
+34
@@ -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:"
|
||||||
@@ -57,6 +57,16 @@ send_wrapper = "0.6.0"
|
|||||||
# installs it -- this crate never installs a logger itself.
|
# installs it -- this crate never installs a logger itself.
|
||||||
log = "0.4.28"
|
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]
|
[dev-dependencies]
|
||||||
tokio = { workspace = true, features = ["sync", "rt", "rt-multi-thread", "time"] }
|
tokio = { workspace = true, features = ["sync", "rt", "rt-multi-thread", "time"] }
|
||||||
# The tabs example's widget tree. A dev-dependency cycle back to this
|
# The tabs example's widget tree. A dev-dependency cycle back to this
|
||||||
|
|||||||
@@ -37,6 +37,10 @@ serde_json = { version = "1", features = ["float_roundtrip"], optional = true }
|
|||||||
default = ["tabs-screen"]
|
default = ["tabs-screen"]
|
||||||
tabs-screen = ["dep:tabs-ui"]
|
tabs-screen = ["dep:tabs-ui"]
|
||||||
transcript-screen = ["dep:transcript-ui", "dep:client-core", "dep:event-model", "dep:serde_json"]
|
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]
|
[profile.release]
|
||||||
panic = "abort"
|
panic = "abort"
|
||||||
|
|||||||
@@ -35,6 +35,12 @@ const RING_CAPACITY: usize = 4096;
|
|||||||
/// ever called from a button tap, not once per frame.
|
/// ever called from a button tap, not once per frame.
|
||||||
pub struct FrameReport {
|
pub struct FrameReport {
|
||||||
ring: Box<[Duration; RING_CAPACITY]>,
|
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
|
/// How many of `ring`'s slots hold a real sample -- saturates at
|
||||||
/// `RING_CAPACITY`, unlike `total_frames` below which keeps counting.
|
/// `RING_CAPACITY`, unlike `total_frames` below which keeps counting.
|
||||||
len: usize,
|
len: usize,
|
||||||
@@ -56,6 +62,20 @@ pub struct FrameStats {
|
|||||||
pub p90: Duration,
|
pub p90: Duration,
|
||||||
pub p99: Duration,
|
pub p99: Duration,
|
||||||
pub worst: Duration,
|
pub worst: Duration,
|
||||||
|
/// Median of `redraw_to_submit` -- iris's own CPU work (layout, text,
|
||||||
|
/// 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 {
|
impl std::fmt::Display for FrameStats {
|
||||||
@@ -71,6 +91,13 @@ impl std::fmt::Display for FrameStats {
|
|||||||
self.p90.as_secs_f64() * 1000.0,
|
self.p90.as_secs_f64() * 1000.0,
|
||||||
self.p99.as_secs_f64() * 1000.0,
|
self.p99.as_secs_f64() * 1000.0,
|
||||||
self.worst.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 {
|
pub fn new() -> Self {
|
||||||
Self {
|
Self {
|
||||||
ring: Box::new([Duration::ZERO; RING_CAPACITY]),
|
ring: Box::new([Duration::ZERO; RING_CAPACITY]),
|
||||||
|
submit_ring: Box::new([Duration::ZERO; RING_CAPACITY]),
|
||||||
len: 0,
|
len: 0,
|
||||||
pos: 0,
|
pos: 0,
|
||||||
total_frames: 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) {
|
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.pos = (self.pos + 1) % RING_CAPACITY;
|
||||||
self.len = (self.len + 1).min(RING_CAPACITY);
|
self.len = (self.len + 1).min(RING_CAPACITY);
|
||||||
self.total_frames += 1;
|
self.total_frames += 1;
|
||||||
if elapsed > JANK_THRESHOLD {
|
if total > JANK_THRESHOLD {
|
||||||
self.janky_frames += 1;
|
self.janky_frames += 1;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@@ -118,6 +160,21 @@ impl FrameReport {
|
|||||||
let mut samples: Vec<Duration> = self.ring[..self.len].to_vec();
|
let mut samples: Vec<Duration> = self.ring[..self.len].to_vec();
|
||||||
samples.sort_unstable();
|
samples.sort_unstable();
|
||||||
let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)];
|
let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)];
|
||||||
|
|
||||||
|
// 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<Duration> = self.submit_ring[..self.len].to_vec();
|
||||||
|
let cpu_samples: Vec<Duration> = 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<Duration>| {
|
||||||
|
v.sort_unstable();
|
||||||
|
v[v.len() / 2]
|
||||||
|
};
|
||||||
|
|
||||||
Some(FrameStats {
|
Some(FrameStats {
|
||||||
total_frames: self.total_frames,
|
total_frames: self.total_frames,
|
||||||
janky_percent: 100.0 * self.janky_frames as f64 / self.total_frames as f64,
|
janky_percent: 100.0 * self.janky_frames as f64 / self.total_frames as f64,
|
||||||
@@ -125,6 +182,8 @@ impl FrameReport {
|
|||||||
p90: pct(90),
|
p90: pct(90),
|
||||||
p99: pct(99),
|
p99: pct(99),
|
||||||
worst: *samples.last().expect("len > 0 checked above"),
|
worst: *samples.last().expect("len > 0 checked above"),
|
||||||
|
cpu_p50: median(cpu_samples),
|
||||||
|
gpu_wait_p50: median(submit_samples),
|
||||||
})
|
})
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@@ -196,6 +255,33 @@ mod tests {
|
|||||||
assert_eq!(r.report().unwrap().janky_percent, 0.0);
|
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]
|
#[test]
|
||||||
fn ring_wraps_without_growing_past_capacity() {
|
fn ring_wraps_without_growing_past_capacity() {
|
||||||
let mut r = FrameReport::new();
|
let mut r = FrameReport::new();
|
||||||
|
|||||||
@@ -6,6 +6,7 @@ use android_view::{
|
|||||||
};
|
};
|
||||||
use iris_core::{UiData, UiRenderNode, UiRenderState};
|
use iris_core::{UiData, UiRenderNode, UiRenderState};
|
||||||
use pollster::FutureExt;
|
use pollster::FutureExt;
|
||||||
|
use std::time::{Duration, Instant};
|
||||||
use wgpu::{
|
use wgpu::{
|
||||||
rwh::{DisplayHandle, HandleError, HasDisplayHandle, HasWindowHandle, WindowHandle},
|
rwh::{DisplayHandle, HandleError, HasDisplayHandle, HasWindowHandle, WindowHandle},
|
||||||
*,
|
*,
|
||||||
@@ -51,8 +52,19 @@ pub struct AndroidRenderer {
|
|||||||
|
|
||||||
impl AndroidRenderer {
|
impl AndroidRenderer {
|
||||||
pub fn new(window: NativeWindow, width: u32, height: u32) -> Self {
|
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 {
|
let instance = Instance::new(&InstanceDescriptor {
|
||||||
backends: Backends::PRIMARY,
|
backends,
|
||||||
..Default::default()
|
..Default::default()
|
||||||
});
|
});
|
||||||
|
|
||||||
@@ -128,7 +140,18 @@ impl AndroidRenderer {
|
|||||||
self.ui.update(&self.device, &self.queue, ui, render);
|
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 output = self.surface.get_current_texture().unwrap();
|
||||||
let view = output
|
let view = output
|
||||||
.texture
|
.texture
|
||||||
@@ -151,8 +174,10 @@ impl AndroidRenderer {
|
|||||||
self.ui.draw(render_pass);
|
self.ui.draw(render_pass);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
let submit_start = Instant::now();
|
||||||
self.queue.submit(std::iter::once(encoder.finish()));
|
self.queue.submit(std::iter::once(encoder.finish()));
|
||||||
output.present();
|
output.present();
|
||||||
|
submit_start.elapsed()
|
||||||
}
|
}
|
||||||
|
|
||||||
pub fn size(&self) -> iris_core::util::Vec2 {
|
pub fn size(&self) -> iris_core::util::Vec2 {
|
||||||
|
|||||||
@@ -282,11 +282,11 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
|
|||||||
return;
|
return;
|
||||||
};
|
};
|
||||||
renderer.update(&mut self.rsc.ui, &mut self.render);
|
renderer.update(&mut self.rsc.ui, &mut self.render);
|
||||||
renderer.draw();
|
let submit_to_present = renderer.draw();
|
||||||
self.state
|
self.state
|
||||||
.android_state_mut()
|
.android_state_mut()
|
||||||
.frame_report
|
.frame_report
|
||||||
.record(frame_start.elapsed());
|
.record_split(frame_start.elapsed(), submit_to_present);
|
||||||
let ui_state = self.state.android_state();
|
let ui_state = self.state.android_state();
|
||||||
log::debug!(
|
log::debug!(
|
||||||
"render(): after update active={} root_px={:?}",
|
"render(): after update active={} root_px={:?}",
|
||||||
|
|||||||
Reference in new issue
Block a user