iris: FrameReport, a per-frame wall-time report of iris's own render path

dumpsys gfxinfo cannot see a SurfaceView's own GPU-drawn frames at all
(RUST.md's I5 box), so iris needs its own equivalent of Compose's
render-report button before item 3 of the recommendation can be decided
by a number. FrameReport (iris/core/src/render/frame_report.rs) records
each frame's wall time -- from render()'s redraw start to after
queue.submit + present() -- into a fixed 4096-entry ring, and reports
total frames, janky % (>16.7ms, gfxinfo's own budget), P50/P90/P99 and
the worst. Wired into AndroidUiState and android/view.rs's render(), and
exposed as two named controls ("Frame report", "Reset frame report") on
iris-android-app's transcript screen, logged under the crate's fixed tag
so a script can grep "iris frame report" the way transcript-bench.sh
greps "ai-app render report".

6 new unit tests for the ring/percentile math. cargo fmt/clippy/test
--workspace clean; cargo ndk (iris, transcript-ui, and
iris-android-app --features transcript-screen) all clean.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
irisandClaude Fable 5.1 committed 2026-09-05 14:23:51 -04:00
1 parent d17040b601
commit 7ae53ad797
5 files changed
+335 -3

No files matched your search

+72 -3
View File
@@ -44,6 +44,12 @@ mod pinned {
pub struct TranscriptClient {
ui_state: AndroidUiState,
/// The screen's own content -- everything under the fixed
/// [`frame_report_controls`] bar, which is built once (`new`, below)
/// and never touched by `show_message`/`rebuild_transcript`'s own
/// `set` calls the way `desktop-app`'s `transcript_ptr` isn't touched
/// by rebuilding the session list beside it.
content: WeakWidget<WidgetPtr>,
screen: Option<transcript_ui::TranscriptScreen>,
/// The folded transcript as of the last rebuild -- kept here (not
/// re-derived) for the same reason `desktop-app`'s `Client::items`
@@ -94,13 +100,76 @@ fn placeholder<Rsc: HasEvents>(rsc: &mut Rsc, message: &str) -> StrongWidget {
.any()
}
/// The two named controls RUST.md's I5 box ("Measurements taken" (b))
/// drives by name over `ui-trace`, e.g. `ui-trace record --do "tap 'Frame
/// report'"`. `dumpsys gfxinfo` cannot see this screen's own GPU-drawn
/// frames at all -- this is the screen's own equivalent of the Compose
/// app's "Copy render timings" control, logged rather than clipboarded
/// (no clipboard wiring exists here) under this crate's own fixed
/// `android_logger` tag (`iris-android-app`, `lib.rs`'s `JNI_OnLoad`),
/// grep-able on the fixed string `"iris frame report"` the way
/// `transcript-bench.sh` greps `"ai-app render report"`.
fn frame_report_controls(rsc: &mut AndroidRsc<TranscriptClient>) -> WeakWidget {
type Rsc = AndroidRsc<TranscriptClient>;
let report_rect = rect(Color::rgb(50, 50, 60))
.on(
CursorSense::click(),
|ctx: EventIdCtx<'_, Rsc, _, _>, _rsc: &mut Rsc| match ctx
.state
.android_state()
.frame_report
.report()
{
Some(stats) => log::info!("iris frame report: {stats}"),
None => log::info!(
"iris frame report: no frames recorded -- scroll first, then press this"
),
},
)
.label("Frame report");
let report = (
report_rect,
wtext("Frame report").size(18).text_align(Align::CENTER),
)
.stack()
.pad(8)
.add(rsc);
let reset_rect = rect(Color::rgb(70, 40, 40))
.on(
CursorSense::click(),
|ctx: EventIdCtx<'_, Rsc, _, _>, _rsc: &mut Rsc| {
ctx.state.android_state_mut().frame_report.reset();
log::info!("iris frame report: reset");
},
)
.label("Reset frame report");
let reset = (
reset_rect,
wtext("Reset").size(18).text_align(Align::CENTER),
)
.stack()
.pad(8)
.add(rsc);
(report, reset).span(Dir::RIGHT).height(56).add(rsc)
}
impl AndroidAppState for TranscriptClient {
fn new(mut ui_state: AndroidUiState, rsc: &mut AndroidRsc<Self>) -> Self {
let content = WidgetPtr::new().add(rsc);
let loading = placeholder(rsc, "Loading sessions...");
ui_state.set_root(loading);
content(rsc).set(loading);
let tree = (frame_report_controls(rsc), content.height(rest(1)))
.span(Dir::DOWN)
.add_strong(rsc)
.any();
ui_state.set_root(tree);
let mut client = Self {
ui_state,
content,
screen: None,
items: Vec::new(),
session_id: None,
@@ -120,7 +189,7 @@ impl AndroidAppState for TranscriptClient {
impl TranscriptClient {
fn show_message(&mut self, rsc: &mut AndroidRsc<Self>, message: &str) {
let widget = placeholder(rsc, message);
self.android_state_mut().set_root(widget);
(self.content)(rsc).set(widget);
self.screen = None;
}
@@ -286,7 +355,7 @@ impl TranscriptClient {
});
}
self.android_state_mut().set_root(tree);
(self.content)(rsc).set(tree);
self.screen = Some(screen);
}
+213
View File
@@ -0,0 +1,213 @@
use std::time::Duration;
/// The frame budget `dumpsys gfxinfo` also uses to call a frame "janky": the
/// 60Hz vsync period. Kept as the same threshold so a percentage from this
/// report and a percentage from `gfxinfo` mean the same thing.
pub const JANK_THRESHOLD: Duration = Duration::from_nanos(16_666_667);
/// Enough frames for several minutes of scrolling before the oldest ones
/// start being overwritten -- the same "diagnostic, not a log" sizing
/// `FrameStats.kt`'s `CAP` uses on the Compose side, chosen independently
/// here since a `Duration` is smaller than the six `Long` arrays it keeps.
const RING_CAPACITY: usize = 4096;
/// 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
/// ordinary Skia/HWUI View-drawing pipeline, which a `wgpu`-rendered
/// `SurfaceView` bypasses entirely. `record` is meant to be called once per
/// frame, wrapping the same span Compose's own render report and `gfxinfo`
/// count -- from the frame's redraw/update start to after the frame is
/// handed to the platform to present.
///
/// **What this does not measure**: wgpu's `present()` call queues the frame
/// with the compositor and returns; it is not fenced against the GPU
/// actually finishing the frame or the compositor actually showing it, the
/// way `gfxinfo`'s own `GPU_DURATION`/vsync accounting is. So a sample here
/// is "how long the CPU took to build and submit this frame", not
/// "how long the frame took to reach the screen" -- named in
/// [`FrameStats`]'s own `Display` line rather than presented as the latter,
/// per the standing rule against showing an inferred number as a measured
/// one where the two differ.
///
/// Fixed-size ring, no allocation on the hot path -- `report()` is the only
/// place that allocates (a sort over the current ring), and it is only
/// ever called from a button tap, not once per frame.
pub struct FrameReport {
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,
pos: usize,
/// All frames recorded since the last `reset`, even past `RING_CAPACITY`
/// -- what `janky_percent` divides by, so a long run's percentage stays
/// correct even once the ring itself only holds the most recent frames.
total_frames: u64,
janky_frames: u64,
}
/// One resolved reading. `Display` is the log line both the "Frame report"
/// button and `transcript-bench.sh`-style scripts read, grep-able on
/// `"iris frame report"`.
pub struct FrameStats {
pub total_frames: u64,
pub janky_percent: f64,
pub p50: Duration,
pub p90: Duration,
pub p99: Duration,
pub worst: Duration,
}
impl std::fmt::Display for FrameStats {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(
f,
"frames={} janky%={:.2} p50={:.1}ms p90={:.1}ms p99={:.1}ms worst={:.1}ms \
(measures redraw-start to after present() is called, not GPU/compositor \
completion)",
self.total_frames,
self.janky_percent,
self.p50.as_secs_f64() * 1000.0,
self.p90.as_secs_f64() * 1000.0,
self.p99.as_secs_f64() * 1000.0,
self.worst.as_secs_f64() * 1000.0,
)
}
}
impl FrameReport {
pub fn new() -> Self {
Self {
ring: Box::new([Duration::ZERO; RING_CAPACITY]),
len: 0,
pos: 0,
total_frames: 0,
janky_frames: 0,
}
}
/// Record one frame's elapsed wall time. O(1), no allocation.
pub fn record(&mut self, elapsed: Duration) {
self.ring[self.pos] = elapsed;
self.pos = (self.pos + 1) % RING_CAPACITY;
self.len = (self.len + 1).min(RING_CAPACITY);
self.total_frames += 1;
if elapsed > JANK_THRESHOLD {
self.janky_frames += 1;
}
}
/// Clears every counter and every sample -- what the "Reset frame
/// report" control calls, so a report covers only what was scrolled
/// after the button was pressed (the same reason `FrameStats.kt`'s
/// `reset()` exists on the Compose side).
pub fn reset(&mut self) {
self.len = 0;
self.pos = 0;
self.total_frames = 0;
self.janky_frames = 0;
}
/// `None` if nothing has been recorded since the last reset -- the
/// "no frames recorded, scroll first" case, not a zeroed report that
/// would read as a real (perfect) measurement.
pub fn report(&self) -> Option<FrameStats> {
if self.len == 0 {
return None;
}
let mut samples: Vec<Duration> = self.ring[..self.len].to_vec();
samples.sort_unstable();
let pct = |p: usize| samples[(samples.len() * p / 100).min(samples.len() - 1)];
Some(FrameStats {
total_frames: self.total_frames,
janky_percent: 100.0 * self.janky_frames as f64 / self.total_frames as f64,
p50: pct(50),
p90: pct(90),
p99: pct(99),
worst: *samples.last().expect("len > 0 checked above"),
})
}
}
impl Default for FrameReport {
fn default() -> Self {
Self::new()
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn no_frames_reports_none() {
assert!(FrameReport::new().report().is_none());
}
#[test]
fn one_frame_is_every_percentile_and_the_worst() {
let mut r = FrameReport::new();
r.record(Duration::from_millis(10));
let stats = r.report().unwrap();
assert_eq!(stats.total_frames, 1);
assert_eq!(stats.p50, Duration::from_millis(10));
assert_eq!(stats.p99, Duration::from_millis(10));
assert_eq!(stats.worst, Duration::from_millis(10));
assert_eq!(stats.janky_percent, 0.0);
}
#[test]
fn percentiles_and_worst_over_a_known_set() {
let mut r = FrameReport::new();
// 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));
}
let stats = r.report().unwrap();
assert_eq!(stats.total_frames, 100);
assert_eq!(stats.p50, Duration::from_millis(51));
assert_eq!(stats.p90, Duration::from_millis(91));
assert_eq!(stats.p99, Duration::from_millis(100));
assert_eq!(stats.worst, Duration::from_millis(100));
}
#[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
let stats = r.report().unwrap();
assert_eq!(stats.janky_percent, 50.0);
}
#[test]
fn janky_percent_is_over_all_time_frames_not_just_the_ring() {
// Fewer than RING_CAPACITY frames, all janky, then a fresh reset --
// 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));
}
assert_eq!(r.report().unwrap().janky_percent, 100.0);
r.reset();
assert!(r.report().is_none());
r.record(Duration::from_millis(1));
assert_eq!(r.report().unwrap().janky_percent, 0.0);
}
#[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));
}
let stats = r.report().unwrap();
// total_frames keeps the full count even once the ring has wrapped.
assert_eq!(stats.total_frames, (RING_CAPACITY * 2) as u64);
// but every sample the ring can report on is still one of the five
// values fed in, since a wrap can only overwrite with more of the
// same pattern here.
assert!(stats.worst <= Duration::from_millis(5));
}
}
+2
View File
@@ -11,12 +11,14 @@ use wgpu::{
mod atlas;
mod data;
mod frame_report;
mod primitive;
mod texture;
mod util;
pub use atlas::*;
pub use data::{Mask, MaskIdx, MoveIdx, MoveOffset};
pub use frame_report::{FrameReport, FrameStats, JANK_THRESHOLD};
pub use primitive::*;
const SHAPE_SHADER: &str = include_str!("./shader.wgsl");
+17
View File
@@ -57,6 +57,11 @@ pub struct AndroidUiState {
/// The AccessKit tree itself -- see `iris_core::AccessTree`'s doc
/// comment.
pub access: AccessTree,
/// iris's own frame-time report (RUST.md's I5 box, "Measurements
/// taken" (b)) -- `render()` below records into it once per frame,
/// because `dumpsys gfxinfo` cannot see a `SurfaceView`'s own
/// GPU-drawn frames at all. See `iris_core::FrameReport`'s own doc.
pub frame_report: FrameReport,
}
impl AndroidUiState {
@@ -72,6 +77,7 @@ impl AndroidUiState {
shared,
access_adapter: Default::default(),
access: AccessTree::new(),
frame_report: FrameReport::new(),
}
}
@@ -262,6 +268,13 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
.and_then(|r| self.render.window_region(r, &self.rsc)),
self.window_size(),
);
// iris's own frame-time report (RUST.md's I5 box, "Measurements
// taken" (b)): started here, at the same point a redraw request
// fires, and stopped after `renderer.draw()`'s `queue.submit` +
// `present()` -- the span Compose's render report and `gfxinfo`
// both count. See `iris_core::FrameReport`'s own doc for exactly
// what this does and does not measure.
let frame_start = Instant::now();
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();
@@ -270,6 +283,10 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
};
renderer.update(&mut self.rsc.ui, &mut self.render);
renderer.draw();
self.state
.android_state_mut()
.frame_report
.record(frame_start.elapsed());
let ui_state = self.state.android_state();
log::debug!(
"render(): after update active={} root_px={:?}",