diff --git a/docs/DECISIONS.md b/docs/DECISIONS.md index 5f4bdfd..55dc231 100644 --- a/docs/DECISIONS.md +++ b/docs/DECISIONS.md @@ -7,6 +7,37 @@ marked **DEFERRED** are ones the agent chose not to decide alone. ## 2026-09-05 +- **iris gets its own measured frame report, rather than waiting on a + `dumpsys`/`gfxinfo` answer that cannot see a `SurfaceView`'s GPU-drawn + frames.** `iris_core::FrameReport` (`iris/core/src/render/frame_report.rs`) + times each frame's wall clock from the same point `render()`'s redraw + starts to just after `queue.submit` + `present()` — the span Compose's + own render report and `gfxinfo` both count — into a fixed 4096-entry + ring (no allocation per frame; `report()` is the only place that + allocates, and only on a button tap). The report gives total frames, + janky % over the same 16.7ms budget `gfxinfo` uses, P50/P90/P99 and the + worst, plus a reset. Exposed the way the Compose app's copy-button + report already is: two named controls ("Frame report", "Reset frame + report") on the transcript screen, tappable by accessibility name via + `ui-trace`, logging under this crate's fixed `android_logger` tag + (`iris-android-app`) so a script can grep `"iris frame report"` the way + `transcript-bench.sh` greps `"ai-app render report"`. The report's own + `Display` line says plainly that it measures up to the `present()` call + returning, not GPU/compositor completion — wgpu's `present()` is not + fenced against either, so presenting that span as "time to reach the + screen" would be a measured-looking number that is actually inferred, + which the standing UI rule forbids. +- **`ui-trace` gains a hold-then-drag gesture, additive, in + `emulator-tools`.** Neither of its two existing actions can produce + "hold stationary for `LONG_PRESS`, then move without lifting" — `tap` + has no hold and `swipe X1 Y1 X2 Y2 MS` interpolates motion across its + whole duration from t=0. A new action presses, waits, then moves to a + second point and releases as one continuous touch (raw + `sendevent`/`MotionEvent` injection, extending whatever mechanism the + existing `swipe` already uses), so `DragArbiter`'s pan-vs-select rule + (`iris/src/sense.rs`, already covered by 8 unit tests against a + synthetic clock) can finally be driven on a real device instead of only + in a test harness. - **Touch drag on a transcript row follows Android's own rule**: a vertical drag pans the list immediately; a stationary press held 500 ms starts a text selection which further dragging extends; a horizontal drag while diff --git a/iris/android-app/src/transcript_client.rs b/iris/android-app/src/transcript_client.rs index ea09982..b664ade 100644 --- a/iris/android-app/src/transcript_client.rs +++ b/iris/android-app/src/transcript_client.rs @@ -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, screen: Option, /// 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: &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) -> WeakWidget { + type Rsc = AndroidRsc; + 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 { + 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, 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); } diff --git a/iris/core/src/render/frame_report.rs b/iris/core/src/render/frame_report.rs new file mode 100644 index 0000000..89a3433 --- /dev/null +++ b/iris/core/src/render/frame_report.rs @@ -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 { + if self.len == 0 { + return None; + } + 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)]; + 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)); + } +} diff --git a/iris/core/src/render/mod.rs b/iris/core/src/render/mod.rs index 5788254..feac4d8 100644 --- a/iris/core/src/render/mod.rs +++ b/iris/core/src/render/mod.rs @@ -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"); diff --git a/iris/src/android/view.rs b/iris/src/android/view.rs index fc393b5..501421b 100644 --- a/iris/src/android/view.rs +++ b/iris/src/android/view.rs @@ -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 IrisViewPeer { .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 IrisViewPeer { }; 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={:?}",