From 1aab61bf262650feef5d2e44be5343574631da42 Mon Sep 17 00:00:00 2001 From: iris <2+iris@noreply.localhost> Date: Sun, 6 Sep 2026 01:02:04 -0400 Subject: [PATCH 1/2] iris android-app: Benchmark v2 -- fling, type and keyboard phases Implements RUST.md's "Benchmark v2" spec in bench_client.rs: fling (8 out + 8 back at 12,000px/s through List::fling, waits for !is_scrolling() capped 3s, reports travel as row index + offset via List's new anchor_position_display), stream (unchanged), type (the 600-char P0 constant, one char per 50ms into the composer's real TextEdit via .set(), then deleted), and keyboard (5 show/hide cycles via bench_jni.rs's new InputMethodManager calls, confirmed from on_insets_changed's real ime_bottom transitions rather than assumed from the JNI call returning). FrameReport gained mark_phase/phase_stats/late_at_hz (iris/core) so the report can show a per-phase block (frames, late%, p50/p90/p99, worst) against the display's real refresh rate (bench_jni's new refresh_rate_hz), matching the shape docs/bench/compose-phone-v2 uses. RING_CAPACITY bumped 4096->16384 since a full v2 run is ~3,000+ frames. Found and fixed a real deadlock while wiring this up: read_from_state (a new helper that gets a value back out of a spawned task's ctx.update, which has no return channel of its own) only worked for its first call in a chain, because nothing called redraw.request_redraw() after enqueueing later ones -- nothing then drains the task channel to run them. Every call now triggers its own redraw. Verified end to end on this checkout's x86_64 emulator (force-gles, cold boot): fling/stream/type all report populated phase blocks; keyboard's show never got a real on_insets_changed confirmation this run (see follow-up work). Full report and travel numbers go in RUST.md's P0 box next. Co-Authored-By: Claude Fable 5.1 --- iris/android-app/run-bench.sh | 15 +- iris/android-app/src/bench_client.rs | 535 ++++++++++++++++++++++----- iris/android-app/src/bench_jni.rs | 101 ++++- iris/core/src/render/frame_report.rs | 257 ++++++++++++- iris/src/widget/list.rs | 36 ++ 5 files changed, 839 insertions(+), 105 deletions(-) diff --git a/iris/android-app/run-bench.sh b/iris/android-app/run-bench.sh index b0ec16c..44b9b43 100755 --- a/iris/android-app/run-bench.sh +++ b/iris/android-app/run-bench.sh @@ -46,10 +46,13 @@ adb -s "$SERIAL" shell am start -n "$PKG/dev.iris.android.demo.MainActivity" >/d ui-trace record -s "$SERIAL" -d 3000 --do "tap 'Run benchmark'" -o /tmp/run-bench-tap.txt >/dev/null -# Poll for the report line rather than a fixed sleep -- the run itself is a -# fixed script (24 swipes + a 20s streaming phase) but device speed varies. +# Poll for the report line rather than a fixed sleep -- the run itself is +# a fixed script (RUST.md's "Benchmark v2": 16 flings, a 20s streaming +# phase, ~61s of typing, 10s of keyboard toggles, roughly 2.5 minutes end +# to end) but device speed varies. 260s cap rather than v1's 90s -- v2 is +# a longer script than v1's swipe-loop-only run. i=0 -while [ "$i" -lt 90 ]; do +while [ "$i" -lt 260 ]; do LINE=$(adb -s "$SERIAL" logcat -d -s iris-android-app:I 2>/dev/null | grep "iris bench report:" || true) if [ -n "$LINE" ]; then break @@ -58,7 +61,9 @@ while [ "$i" -lt 90 ]; do sleep 1 done if [ -z "$LINE" ]; then - echo "run-bench.sh: no report after 90s -- check logcat by hand" >&2 + echo "run-bench.sh: no report after 260s -- check logcat by hand" >&2 exit 1 fi -adb -s "$SERIAL" logcat -d -s iris-android-app:I | grep -A 6 "iris bench report:" +# -A 60 rather than v1's -A 6 -- v2's report has a per-phase block (four +# phases, four lines each) on top of the frames/bench sections v1 had. +adb -s "$SERIAL" logcat -d -s iris-android-app:I | grep -A 60 "iris bench report:" diff --git a/iris/android-app/src/bench_client.rs b/iris/android-app/src/bench_client.rs index 2e98beb..c8a1679 100644 --- a/iris/android-app/src/bench_client.rs +++ b/iris/android-app/src/bench_client.rs @@ -26,9 +26,9 @@ use client_core::transcript_fold::{TranscriptItem, fold_event, fold_page, group_ use event_model::SeqEvent; use iris::android::{AndroidAppState, AndroidRsc, AndroidUiState, HasAndroidUiState}; use iris::prelude::*; -use std::sync::Arc; use std::sync::atomic::{AtomicBool, Ordering}; -use std::time::Duration; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; /// bench-fixture/README.md: the first `BACKLOG_COUNT` non-blank lines are /// the opening window; the rest are the streaming tail. Kept in sync with @@ -37,19 +37,57 @@ use std::time::Duration; /// builds open a different split of it, not a wrong-vs-right answer. const BACKLOG_COUNT: usize = 3200; -/// `BenchRun.kt`'s own constants -- kept identical so the two apps' bench -/// runs are the same gesture and the same load, which is the entire point -/// of a shared fixture and a shared scripted loop (P0's pass condition). -const CYCLES: usize = 6; -const SWIPE_PX: f32 = 900.0; -const SWIPE_MS: u64 = 200; -const SWIPE_PAUSE_MS: u64 = 500; +/// RUST.md's "Benchmark v2" spec, written once so both apps' bench clients +/// implement the identical four phases -- see that box before changing any +/// constant here, since a mismatch would make the two reports stop +/// measuring the same thing while still looking like they do. const STREAM_EVENTS_PER_SEC: u64 = 20; const STREAM_SECONDS: u64 = 20; + +/// Kept only so this phase's own label text still reads "scroll: 6 cycles +/// (24 swipes, legacy tween)" the way `BenchRun.kt`'s v2 report does -- +/// `docs/bench/compose-phone-v2-2026-09-06.md`'s own report shows this +/// exact line even though the swipe loop it names no longer runs there +/// either (the fling phase replaced it); nothing here drives an actual +/// swipe with these any more. +const LEGACY_CYCLES: usize = 6; + +/// Fling phase (v2): a real fling through `List::fling`, not a tween -- +/// Iris's ask was that it "travel way faster" than the v1 swipe, and a +/// tween can never exceed the distance/time it is given while a real +/// fling decays from an initial velocity the way a finger flick does. +/// 12,000 px/s matches `BenchRun.kt`'s own constant exactly. +const FLING_VELOCITY_PX_S: f32 = 12_000.0; +const FLING_COUNT: usize = 8; +const FLING_SETTLE_CAP_MS: u64 = 3_000; +const FLING_PAUSE_MS: u64 = 300; + +/// Type phase (v2): long, multisyllabic words so the composer actually +/// wraps and the transcript above it is pushed upward, typed and deleted +/// one character per `TYPE_CHAR_MS`. Exactly `BenchRun.TYPE_TEXT` -- +/// verified 600 characters by `type_text_is_exactly_600_characters` below. +const TYPE_TEXT: &str = "Benchmarking this transcript screen requires unusually long, \ +multisyllabic words so wrapping and reflow are properly exercised: internationalization, \ +counterproductiveness, disproportionately, incomprehensibility, deinstitutionalization, \ +uncharacteristically, overenthusiastically, misunderstanding, straightforwardness, \ +telecommunications, and interdisciplinary collaboration all push a narrow composer field to \ +wrap across several lines while the transcript above is pushed upward by the growing \ +keyboard-adjacent box, which is exactly what a real reader typing a long message sees \ +happening now!!!"; +const TYPE_CHAR_MS: u64 = 50; + +/// Keyboard phase (v2): five show/hide cycles, a second apart, matching +/// `BenchRun.kt`'s `KEYBOARD_CYCLES`/`KEYBOARD_SHOW_WAIT_MS`/ +/// `KEYBOARD_HIDE_WAIT_MS`. +const KEYBOARD_CYCLES: usize = 5; +const KEYBOARD_WAIT_MS: u64 = 1_000; + /// One animation step's target cadence -- close enough to 60Hz that a -/// `List::scroll` swipe is many small moves rather than one jump, so -/// frames are actually rendered along the way (the point of animating it -/// at all rather than calling `scroll` once per swipe). +/// fling/scroll is many small moves rather than one jump, so frames are +/// actually rendered along the way, and close enough that a `ctx.update` +/// closure's effect (only applied once the next frame callback drains the +/// task channel -- `IrisViewPeer::drain_tasks`) is visible again quickly +/// when a later step in the same phase needs to read state back. const ANIM_STEP_MS: u64 = 16; const FIXTURE_JSONL: &str = include_str!("../../../app/bench-fixture/assets/transcript.jsonl"); @@ -74,6 +112,25 @@ pub struct BenchClient { platform: Option>, last_report: Option, running: bool, + /// The keyboard phase's own confirmation channel -- updated from + /// `on_insets_changed` (the platform's own answer for whether the IME + /// is actually visible, per `LogicalInsets::ime_bottom`), read from the + /// benchmark's spawned task via the shared `Arc>` rather than + /// `ctx.update`, since neither side needs the widget tree for this. + ime_state: Arc>, +} + +/// See `BenchClient::ime_state`'s doc. `shown_events`/`hidden_events` +/// count real 0->visible / visible->0 transitions `on_insets_changed` +/// observed, not merely "a show/hide was requested" -- UI_RULES.md: never +/// present an inferred value as a measured one. `run_keyboard_phase` reads +/// the counters before and after asking for a toggle and calls it +/// confirmed only if the count moved. +#[derive(Default)] +struct ImeState { + visible: bool, + shown_events: u32, + hidden_events: u32, } impl HasAndroidUiState for BenchClient { @@ -219,6 +276,7 @@ impl AndroidAppState for BenchClient { platform: None, last_report: None, running: false, + ime_state: Arc::new(Mutex::new(ImeState::default())), }; let (backlog, stream_tail) = parse_fixture(); @@ -246,9 +304,29 @@ impl AndroidAppState for BenchClient { /// Pads the top button row by the status-bar inset -- see `top_bar`'s /// field comment. Rebuilds the row rather than mutating a stored /// `Padding` in place, since nothing here holds a handle to one. - fn on_insets_changed(&mut self, rsc: &mut AndroidRsc, insets: iris::android::LogicalInsets) { + /// + /// Also the keyboard phase's own confirmation signal: `ime_bottom` + /// crossing 0<->positive is the platform's own answer for whether the + /// IME actually opened or closed, fired from the real insets + /// callback rather than assumed from having called `show_ime`/ + /// `hide_ime` -- see `ime_state`'s doc. + fn on_insets_changed( + &mut self, + rsc: &mut AndroidRsc, + insets: iris::android::LogicalInsets, + ) { let controls = bench_controls(rsc, insets.top); (self.top_bar)(rsc).set(controls); + + let mut ime = self.ime_state.lock().unwrap(); + let now_visible = insets.ime_bottom > 0.0; + if now_visible && !ime.visible { + ime.shown_events += 1; + } + if !now_visible && ime.visible { + ime.hidden_events += 1; + } + ime.visible = now_visible; } } @@ -366,10 +444,10 @@ impl BenchClient { } } - /// P0's scripted run: `BenchRun.kt`'s scroll loop, then its streaming - /// phase, then the report -- run in-process for the same reason that - /// file's own doc gives (no usable system tracing on a real phone, no - /// agent that can drive one). + /// RUST.md's "Benchmark v2": fling, then stream (unchanged from v1), + /// then type, then keyboard, then the report -- run in-process for the + /// same reason `BenchRun.kt`'s own doc gives (no usable system tracing + /// on a real phone, no agent that can drive one). fn start_benchmark(&mut self, rsc: &mut Rsc) { if self.running { log::info!("iris bench report: already running"); @@ -382,35 +460,21 @@ impl BenchClient { let redraw = rsc.tasks.redraw_handle(); let platform = self.platform.clone(); let stream_tail = self.stream_tail.clone(); + let ime_state = self.ime_state.clone(); + let refresh_hz = platform + .as_ref() + .and_then(|p| p.refresh_rate_hz()) + .unwrap_or(60.0); let cpu_start = process_cpu_ms(); + let run_started_at = Instant::now(); rsc.spawn_task(async move |mut ctx| { - // The swipe loop: two drags toward newer content, two back -- - // a cycle returns to where it started, so the whole loop - // measures steady-state scrolling. `BenchRun.kt`'s own - // comment on this shape. - for _ in 0..CYCLES { - for delta in [SWIPE_PX, SWIPE_PX, -SWIPE_PX, -SWIPE_PX] { - animate_scroll(&mut ctx, &redraw, delta, SWIPE_MS).await; - tokio::time::sleep(Duration::from_millis(SWIPE_PAUSE_MS)).await; - } - } - - // Pinned to the newest end before streaming starts, matching - // `stream-bench.sh`'s "Jump to latest" tap. - ctx.update(|state: &mut BenchClient, rsc| { - if let Some(screen) = &state.screen { - (screen.list)(rsc).jump_to_end(); - } - }); - redraw.request_redraw(); - - // The battery sampler runs concurrently with the streaming - // phase, once a second, the same cadence `BatterySampler` uses - // on the Compose side -- via its own JNI-attached thread, not - // `ctx.update`, since a sample needs no widget-tree access. + // The battery sampler runs for the whole run, once a second, + // the same cadence `BatterySampler` uses on the Compose side + // -- via its own JNI-attached thread, not `ctx.update`, since + // a sample needs no widget-tree access. let sampler_done = Arc::new(AtomicBool::new(false)); - let samples = Arc::new(std::sync::Mutex::new(Vec::::new())); + let samples = Arc::new(Mutex::new(Vec::::new())); let sampler = platform.clone().map(|platform| { let done = sampler_done.clone(); let samples = samples.clone(); @@ -424,27 +488,10 @@ impl BenchClient { }) }); - let total = (STREAM_EVENTS_PER_SEC * STREAM_SECONDS) as usize; - let mut sent = 0usize; - for event in stream_tail.into_iter().take(total) { - ctx.update(move |state: &mut BenchClient, rsc| { - let old_items = state.items.clone(); - state.items = fold_event(&state.items, &event); - match &state.screen { - // The path P0 asked to measure: update only the - // row(s) that changed instead of rebuilding all - // ~3,200 of them per event. - Some(screen) => screen.apply(rsc, &old_items, &state.items), - None => state.rebuild_transcript(rsc), - } - }); - redraw.request_redraw(); - sent += 1; - tokio::time::sleep(Duration::from_millis(1000 / STREAM_EVENTS_PER_SEC)).await; - } - // Lets the last few deltas land and draw before the report is - // read -- `BenchRun.kt`'s own closing delay. - tokio::time::sleep(Duration::from_millis(300)).await; + let travel = run_fling_phase(&mut ctx, &redraw).await; + let (sent, total) = run_stream_phase(&mut ctx, &redraw, stream_tail).await; + run_type_phase(&mut ctx, &redraw, &platform).await; + let keyboard = run_keyboard_phase(&mut ctx, &platform, &ime_state).await; sampler_done.store(true, Ordering::Relaxed); if let Some(sampler) = sampler { @@ -453,7 +500,10 @@ impl BenchClient { let battery = battery_line(&samples.lock().unwrap()); let cpu_line = match (cpu_start, process_cpu_ms()) { (Some(start), Some(end)) => { - format!(" process CPU time over this run: {}ms", end.saturating_sub(start)) + format!( + " process CPU time over this run: {}ms", + end.saturating_sub(start) + ) } _ => " process CPU time over this run: unavailable".to_string(), }; @@ -461,19 +511,61 @@ impl BenchClient { Some(kb) => format!(" peak RSS: {kb}kB"), None => " peak RSS: unavailable (/proc/self/status unreadable)".to_string(), }; + let total_seconds = run_started_at.elapsed().as_secs_f64(); ctx.update(move |state: &mut BenchClient, rsc| { state.running = false; - let scroll_line = format!( - " scroll: {CYCLES} cycles ({} swipes), streamed {sent}/{total} fixture events", - CYCLES * 4 - ); - let frames_line = match state.android_state().frame_report.report() { - Some(stats) => format!("{stats}"), - None => "no frames recorded".to_string(), + let now = Instant::now(); + let phase_lines: String = state + .android_state() + .frame_report + .phase_stats(now, refresh_hz) + .iter() + .map(|p| format!("{p}\n")) + .collect(); + let per_phase = if phase_lines.is_empty() { + String::new() + } else { + format!("per phase:\n{phase_lines}\n") }; + let frames_block = match state.android_state().frame_report.report() { + Some(stats) => { + let (late, late_pct) = + state.android_state().frame_report.late_at_hz(refresh_hz); + 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", + stats.total_frames, + total_seconds, + refresh_hz, + 1000.0 / refresh_hz as f64, + stats.p50.as_secs_f64() * 1000.0, + stats.p90.as_secs_f64() * 1000.0, + stats.p99.as_secs_f64() * 1000.0, + stats.worst.as_secs_f64() * 1000.0, + stats.cpu_p50.as_secs_f64() * 1000.0, + stats.gpu_wait_p50.as_secs_f64() * 1000.0, + ) + } + None => "frames:\n no frames recorded".to_string(), + }; + let scroll_line = format!( + " scroll: {LEGACY_CYCLES} cycles ({} swipes, legacy tween), streamed \ + {sent}/{total} fixture events", + LEGACY_CYCLES * 4 + ); + let fling_line = format!( + " fling: {FLING_COUNT} flings out + {FLING_COUNT} back at \ + {FLING_VELOCITY_PX_S}px/s, travel {travel}" + ); + let type_line = format!( + " type: {} characters inserted then deleted, one per {TYPE_CHAR_MS}ms", + TYPE_TEXT.chars().count() + ); let report = format!( - "iris bench report\n{frames_line}\n{scroll_line}\n{cpu_line}\n{rss_line}\n{battery}" + "iris bench report\n{per_phase}{frames_block}\n\nbench:\n{fling_line}\n\ + {scroll_line}\n{type_line}\n{keyboard}\n{cpu_line}\n{rss_line}\n{battery}" ); log::info!("iris bench report: {report}"); state.report_display.edit(rsc).set(&report); @@ -484,26 +576,287 @@ impl BenchClient { } } -/// Moves `List::scroll` by `total_px` over `duration_ms`, in ~60Hz steps, -/// so the swipe is many rendered frames rather than one jump -- the same -/// shape `animateScrollBy(SWIPE_PX, tween(SWIPE_MS))` gives on the Compose -/// side, in the one place the two backends have to differ (iris's `List` -/// has no built-in tween, so this drives it by hand). -async fn animate_scroll( +/// Runs `f` against the real `BenchClient`/`Rsc` on the main thread (the +/// same `ctx.update` every other mutation here goes through) and returns +/// its result to the caller's async task -- `ctx.update` alone has no way +/// to hand a value back, since the closure only actually runs once the +/// next frame callback drains `IrisViewPeer`'s task channel +/// (`drain_tasks`). **Must call `redraw.request_redraw()` itself, right +/// after enqueueing** -- `ctx.update` only ever pushes onto a channel; +/// nothing drains it until something schedules the frame callback that +/// calls `drain_tasks`, and a caller relying on some *earlier*, +/// already-in-flight `request_redraw()` to cover a *later* `ctx.update` +/// deadlocks the moment that earlier callback has already fired and +/// drained everything queued before this call existed. Cost a real hang +/// in this file's first version of the fling phase: every loop iteration +/// after the first sat forever with nothing scheduled to drain it. +/// Polls rather than assuming one `ANIM_STEP_MS` sleep is enough, since a +/// slow device's frame callback can lag further than that. +async fn read_from_state( ctx: &mut iris::task::TaskCtx, - redraw: &Arc, - total_px: f32, - duration_ms: u64, -) { - let steps = (duration_ms / ANIM_STEP_MS).max(1); - let step_px = total_px / steps as f32; - for _ in 0..steps { - ctx.update(move |state: &mut BenchClient, rsc| { - if let Some(screen) = &state.screen { - (screen.list)(rsc).scroll(step_px); - } - }); - redraw.request_redraw(); + redraw: &Arc, + f: F, +) -> T +where + T: Send + 'static, + F: FnOnce(&mut BenchClient, &mut Rsc) -> T + Send + 'static, +{ + let (tx, rx) = std::sync::mpsc::channel(); + ctx.update(move |state: &mut BenchClient, rsc| { + let _ = tx.send(f(state, rsc)); + }); + redraw.request_redraw(); + loop { + if let Ok(value) = rx.try_recv() { + return value; + } tokio::time::sleep(Duration::from_millis(ANIM_STEP_MS)).await; } } + +/// Phase 1: starting pinned at the newest end, `FLING_COUNT` flings away +/// from it (toward older messages) through `List::fling`, then +/// `FLING_COUNT` back. Outward is *negative* in this list's `scroll` +/// convention (`List::scroll`'s own doc: positive moves *later* content +/// into view) -- the opposite sign `BenchRun.kt`'s `runFlingPhase` uses, +/// since `TranscriptList`'s `LazyColumn` and this list define "positive" +/// the other way around; the two apps' *travel* is still directly +/// comparable because both report it as a row index + pixel offset, not a +/// signed distance. +async fn run_fling_phase( + ctx: &mut iris::task::TaskCtx, + redraw: &Arc, +) -> String { + ctx.update(|state: &mut BenchClient, _rsc| { + state.android_state_mut().frame_report.mark_phase("fling"); + }); + ctx.update(|state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + (screen.list)(rsc).jump_to_end(); + } + }); + redraw.request_redraw(); + // Lets the next frame's `repair_anchor` resolve `jump_to_end`'s + // `anchor = None` into a real slot before `start` is read. + tokio::time::sleep(Duration::from_millis(ANIM_STEP_MS * 2)).await; + let start = read_anchor_position(ctx, redraw).await; + + for _ in 0..FLING_COUNT { + ctx.update(|state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + (screen.list)(rsc).fling(-FLING_VELOCITY_PX_S); + } + }); + redraw.request_redraw(); + wait_for_fling_settle(ctx, redraw).await; + tokio::time::sleep(Duration::from_millis(FLING_PAUSE_MS)).await; + } + let outward = read_anchor_position(ctx, redraw).await; + + for _ in 0..FLING_COUNT { + ctx.update(|state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + (screen.list)(rsc).fling(FLING_VELOCITY_PX_S); + } + }); + redraw.request_redraw(); + wait_for_fling_settle(ctx, redraw).await; + tokio::time::sleep(Duration::from_millis(FLING_PAUSE_MS)).await; + } + let end = read_anchor_position(ctx, redraw).await; + + format!("start={start} outward={outward} end={end}") +} + +async fn read_anchor_position( + ctx: &mut iris::task::TaskCtx, + redraw: &Arc, +) -> String { + read_from_state(ctx, redraw, |state, rsc| match &state.screen { + Some(screen) => (screen.list)(rsc).anchor_position_display(), + None => "idx=none".to_string(), + }) + .await +} + +/// Ticks the fling forward in ~60Hz steps (the same shape +/// `run_stream_phase`'s per-event loop and the old `animate_scroll` used) +/// until it settles or `FLING_SETTLE_CAP_MS` passes -- belt-and-suspenders +/// the same way `BenchRun.kt`'s own `waitForSettle` is, since a fling's +/// own spline-decided `duration()` already caps how long it can run. +async fn wait_for_fling_settle( + ctx: &mut iris::task::TaskCtx, + redraw: &Arc, +) { + let cap = Duration::from_millis(FLING_SETTLE_CAP_MS); + let started = Instant::now(); + while started.elapsed() < cap { + let still_scrolling = read_from_state(ctx, redraw, |state, rsc| match &state.screen { + Some(screen) => (screen.list)(rsc).tick_fling(Instant::now()), + None => false, + }) + .await; + if !still_scrolling { + return; + } + tokio::time::sleep(Duration::from_millis(ANIM_STEP_MS)).await; + } +} + +/// Phase 2, unchanged from v1: pinned to the newest end before streaming +/// starts (matching `stream-bench.sh`'s "Jump to latest" tap), then +/// `STREAM_EVENTS_PER_SEC * STREAM_SECONDS` fixture events replayed +/// through the real `fold_event`/`TranscriptScreen::apply` path. Returns +/// `(sent, total)`. +async fn run_stream_phase( + ctx: &mut iris::task::TaskCtx, + redraw: &Arc, + stream_tail: Vec, +) -> (usize, usize) { + ctx.update(|state: &mut BenchClient, _rsc| { + state.android_state_mut().frame_report.mark_phase("stream"); + }); + ctx.update(|state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + (screen.list)(rsc).jump_to_end(); + } + }); + redraw.request_redraw(); + + let total = (STREAM_EVENTS_PER_SEC * STREAM_SECONDS) as usize; + let mut sent = 0usize; + for event in stream_tail.into_iter().take(total) { + ctx.update(move |state: &mut BenchClient, rsc| { + let old_items = state.items.clone(); + state.items = fold_event(&state.items, &event); + match &state.screen { + Some(screen) => screen.apply(rsc, &old_items, &state.items), + None => state.rebuild_transcript(rsc), + } + }); + redraw.request_redraw(); + sent += 1; + tokio::time::sleep(Duration::from_millis(1000 / STREAM_EVENTS_PER_SEC)).await; + } + // Lets the last few deltas land and draw before the next phase starts + // -- `BenchRun.kt`'s own closing delay. + tokio::time::sleep(Duration::from_millis(300)).await; + (sent, total) +} + +/// Phase 3: focuses the real composer, shows the keyboard, then types +/// `TYPE_TEXT` one character at a time through the composer `TextEdit`'s +/// real edit path (`set`, the same call a real keystroke's `onValueChange` +/// makes -- `Composer::build_composer`'s `field`), and deletes it the same +/// way. +async fn run_type_phase( + ctx: &mut iris::task::TaskCtx, + redraw: &Arc, + platform: &Option>, +) { + ctx.update(|state: &mut BenchClient, _rsc| { + state.android_state_mut().frame_report.mark_phase("type"); + }); + ctx.update(|state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + (screen.list)(rsc).jump_to_end(); + state.set_focus(Some(screen.composer.field)); + } + }); + redraw.request_redraw(); + if let Some(p) = platform { + p.show_ime(); + } + // Lets focus and the keyboard's opening animation land before typing + // starts, so the frames this phase records are the wrap/reflow it is + // measuring, not the keyboard opening -- `BenchRun.kt`'s own delay. + tokio::time::sleep(Duration::from_millis(300)).await; + + let mut typed = String::new(); + for ch in TYPE_TEXT.chars() { + typed.push(ch); + let text = typed.clone(); + ctx.update(move |state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + screen.composer.field.edit(rsc).set(&text); + } + }); + redraw.request_redraw(); + tokio::time::sleep(Duration::from_millis(TYPE_CHAR_MS)).await; + } + tokio::time::sleep(Duration::from_millis(200)).await; + while !typed.is_empty() { + typed.pop(); + let text = typed.clone(); + ctx.update(move |state: &mut BenchClient, rsc| { + if let Some(screen) = &state.screen { + screen.composer.field.edit(rsc).set(&text); + } + }); + redraw.request_redraw(); + tokio::time::sleep(Duration::from_millis(TYPE_CHAR_MS)).await; + } +} + +/// Phase 4: `KEYBOARD_CYCLES` show/hide cycles through the shell's own +/// `InputMethodManager` (`bench_jni.rs`'s `show_ime`/`hide_ime`), each +/// confirmed by `on_insets_changed`'s real `ime_bottom` transition rather +/// than assumed from the JNI call having returned -- `ImeState`'s doc. +/// "keyboard: could not be shown" if the platform never confirms it even +/// once, per UI_RULES.md ("design the unknown/failed state before the +/// answer's"). +async fn run_keyboard_phase( + ctx: &mut iris::task::TaskCtx, + platform: &Option>, + ime_state: &Arc>, +) -> String { + ctx.update(|state: &mut BenchClient, _rsc| { + state + .android_state_mut() + .frame_report + .mark_phase("keyboard"); + }); + let mut shown = 0; + let mut hidden = 0; + for _ in 0..KEYBOARD_CYCLES { + let before_shown = ime_state.lock().unwrap().shown_events; + if let Some(p) = platform { + p.show_ime(); + } + tokio::time::sleep(Duration::from_millis(KEYBOARD_WAIT_MS)).await; + if ime_state.lock().unwrap().shown_events > before_shown { + shown += 1; + } + + let before_hidden = ime_state.lock().unwrap().hidden_events; + if let Some(p) = platform { + p.hide_ime(); + } + tokio::time::sleep(Duration::from_millis(KEYBOARD_WAIT_MS)).await; + if ime_state.lock().unwrap().hidden_events > before_hidden { + hidden += 1; + } + } + if shown == 0 { + format!(" keyboard: could not be shown ({KEYBOARD_CYCLES} attempts, 0 confirmed visible)") + } else { + format!( + " keyboard: shown {shown}/{KEYBOARD_CYCLES}, hidden {hidden}/{KEYBOARD_CYCLES} \ + (confirmed via on_insets_changed)" + ) + } +} + +#[cfg(test)] +mod tests { + use super::TYPE_TEXT; + + /// `BenchRun.kt`'s own `TYPE_TEXT` is verified `.length == 600`; this + /// is the same string, so it has to match exactly or the two apps' + /// type phases stop typing the same content -- RUST.md's "Benchmark + /// v2" spec is one shared string for both. + #[test] + fn type_text_is_exactly_600_characters() { + assert_eq!(TYPE_TEXT.chars().count(), 600); + } +} diff --git a/iris/android-app/src/bench_jni.rs b/iris/android-app/src/bench_jni.rs index 0a5ae4b..6fac495 100644 --- a/iris/android-app/src/bench_jni.rs +++ b/iris/android-app/src/bench_jni.rs @@ -1,11 +1,14 @@ //! JNI calls the `bench` feature needs that go through the shell's own //! Java side rather than anything `iris`/`android-view` already wraps: //! `BatteryManager.getIntProperty(BATTERY_PROPERTY_CURRENT_NOW)` for the -//! per-second battery sample, and `ClipboardManager.setPrimaryClip` for -//! the "Copy report" control (P0's iris half, docs/RUST.md). Neither is -//! part of `android_view::context`'s own `Context`/`Resources` wrappers -//! (that file's own `// TODO: more methods?`), so this calls them -//! directly rather than growing that crate's wrapper for two one-off +//! per-second battery sample, `ClipboardManager.setPrimaryClip` for the +//! "Copy report" control (P0's iris half, docs/RUST.md), and -- added for +//! RUST.md's "Benchmark v2" -- `Display.getRefreshRate()` for the phase +//! report's real late-frame budget and `InputMethodManager. +//! showSoftInput`/`hideSoftInputFromWindow` for the keyboard phase. None +//! of these are part of `android_view::context`'s own `Context`/ +//! `Resources` wrappers (that file's own `// TODO: more methods?`), so +//! this calls them directly rather than growing that crate's wrapper for //! calls this crate alone needs. //! //! Holds its own `JavaVM` + `GlobalRef` to the view (handed in through @@ -131,4 +134,92 @@ impl PlatformHandle { .ok()?; Some(()) } + + /// The display's own refresh rate in Hz (`View::getDisplay()` -> + /// `Display::getRefreshRate()`), for RUST.md's "Benchmark v2": late + /// frames are judged against *this* device's real budget, not an + /// assumed 60Hz -- a 90Hz or 120Hz phone would otherwise call frames + /// "late" that met their own faster deadline. `None` if the view is + /// not yet attached to a window (`getDisplay` returns `null`) or the + /// platform reports a non-positive rate, which is not a real answer + /// either. + pub fn refresh_rate_hz(&self) -> Option { + let mut guard = self.vm.attach_current_thread().ok()?; + let env: &mut JNIEnv = &mut guard; + let display = env + .call_method( + self.view.as_obj(), + "getDisplay", + "()Landroid/view/Display;", + &[], + ) + .ok()? + .l() + .ok()?; + if display.is_null() { + return None; + } + let rate = env + .call_method(&display, "getRefreshRate", "()F", &[]) + .ok()? + .f() + .ok()?; + if rate > 0.0 { Some(rate) } else { None } + } + + /// `InputMethodManager.showSoftInput(view, 0)` -- the keyboard phase's + /// own show, called directly rather than through the focus-driven + /// `pending_show_keyboard` path `android/view.rs` uses for a real tap, + /// since RUST.md's "Benchmark v2" spec asks for this "through the + /// shell's InputMethodManager" independent of focus state. `true` only + /// if the platform itself reports the request succeeded -- whether the + /// IME actually became visible is confirmed separately, from + /// `on_insets_changed`, per UI_RULES.md ("never present an inferred + /// value as a measured one"). + pub fn show_ime(&self) -> bool { + self.try_toggle_ime(true).unwrap_or(false) + } + + /// `InputMethodManager.hideSoftInputFromWindow(windowToken, 0)`. + pub fn hide_ime(&self) -> bool { + self.try_toggle_ime(false).unwrap_or(false) + } + + fn try_toggle_ime(&self, show: bool) -> Option { + let mut guard = self.vm.attach_current_thread().ok()?; + let env: &mut JNIEnv = &mut guard; + let context = self.context(env)?; + let imm = self.system_service(env, &context, "input_method")?; + if show { + env.call_method( + &imm, + "showSoftInput", + "(Landroid/view/View;I)Z", + &[JValue::Object(self.view.as_obj()), JValue::Int(0)], + ) + .ok()? + .z() + .ok() + } else { + let token = env + .call_method( + self.view.as_obj(), + "getWindowToken", + "()Landroid/os/IBinder;", + &[], + ) + .ok()? + .l() + .ok()?; + env.call_method( + &imm, + "hideSoftInputFromWindow", + "(Landroid/os/IBinder;I)Z", + &[JValue::Object(&token), JValue::Int(0)], + ) + .ok()? + .z() + .ok() + } + } } diff --git a/iris/core/src/render/frame_report.rs b/iris/core/src/render/frame_report.rs index e944d90..c125bbb 100644 --- a/iris/core/src/render/frame_report.rs +++ b/iris/core/src/render/frame_report.rs @@ -1,15 +1,87 @@ -use std::time::Duration; +use std::time::{Duration, Instant}; /// 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. +/// report and a percentage from `gfxinfo` mean the same thing. Only a +/// fallback now that a caller can read the display's real refresh rate +/// (`report_at_hz`/`mark_phase`'s callers) -- most devices are 60Hz, but a +/// 90Hz or 120Hz phone judged against this constant would call every frame +/// "late" that merely met its own, faster budget. 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; +/// Bumped from 4096 for RUST.md's "Benchmark v2": a fling+stream+type+ +/// keyboard run is ~6,500+ frames on the Compose side, comfortably under +/// this so `phase_stats` never has to report a phase as partially evicted. +const RING_CAPACITY: usize = 16384; + +/// One `mark_phase` call: the wall-clock instant and the (0-based, +/// never-reset-by-`reset`-except-at-`reset`-time) absolute frame index at +/// which a phase began -- `phase_stats` slices `index_ring` against this to +/// find which recorded samples belong to which phase, since the ring +/// itself only keeps the most recent `RING_CAPACITY` samples' *values*, +/// not which phase they were in. +struct PhaseMark { + name: String, + start_index: u64, + start_at: Instant, +} + +/// One phase's own slice of a report -- RUST.md's "Benchmark v2" spec's +/// "per-phase blocks in `FrameReport`... frames, late count/percent... +/// p50/p90/p99, worst, duration". `Display` matches the shape +/// `docs/bench/compose-phone-v2-2026-09-06.md`'s report already uses, so +/// the two apps' reports read the same way side by side. +pub struct PhaseStats { + pub name: String, + /// How many frames were recorded during this phase in total -- may + /// exceed `late + (samples counted)` if some of this phase's frames + /// have since been evicted from the ring by a very long run; that + /// case is named in the `Display` rather than silently under-counted. + pub frames: u64, + pub duration: Duration, + pub late: u64, + pub late_percent: f64, + pub p50: Duration, + pub p90: Duration, + pub p99: Duration, + pub worst: 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 + /// the "we don't fully know" state, named rather than folded silently + /// into a number that looks exact. + pub complete: bool, +} + +impl std::fmt::Display for PhaseStats { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + writeln!( + f, + " {}: {} frames over {:.1}s{}", + self.name, + self.frames, + self.duration.as_secs_f64(), + if self.complete { + "" + } else { + " (ring evicted some of this phase)" + }, + )?; + writeln!(f, " late: {} ({:.1}%)", self.late, self.late_percent)?; + writeln!( + f, + " total p50 {:.1}ms p90 {:.1}ms p99 {:.1}ms", + self.p50.as_secs_f64() * 1000.0, + self.p90.as_secs_f64() * 1000.0, + self.p99.as_secs_f64() * 1000.0, + )?; + write!(f, " worst {:.1}ms", self.worst.as_secs_f64() * 1000.0) + } +} /// A per-frame wall-time report iris keeps of itself, because `dumpsys /// gfxinfo` cannot see a `SurfaceView`'s own GPU-drawn frames at all @@ -41,6 +113,11 @@ pub struct FrameReport { /// "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]>, + /// 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 + /// frames fall in which phase. + index_ring: Box<[u64; 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, @@ -50,6 +127,12 @@ pub struct FrameReport { /// correct even once the ring itself only holds the most recent frames. total_frames: u64, janky_frames: u64, + /// `mark_phase` calls since the last `reset`, oldest first -- see + /// `phase_stats`. Empty on an ordinary run that never calls + /// `mark_phase`, so `phase_stats` returns an empty `Vec` and a caller + /// prints no "per phase:" section at all, matching RUST.md's "empty/ + /// absent on an ordinary 'Copy' press, which never marks a phase." + phases: Vec, } /// One resolved reading. `Display` is the log line both the "Frame report" @@ -107,10 +190,12 @@ impl FrameReport { Self { ring: Box::new([Duration::ZERO; RING_CAPACITY]), submit_ring: Box::new([Duration::ZERO; RING_CAPACITY]), + index_ring: Box::new([0; RING_CAPACITY]), len: 0, pos: 0, total_frames: 0, janky_frames: 0, + phases: Vec::new(), } } @@ -131,6 +216,7 @@ impl FrameReport { 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.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; @@ -142,12 +228,89 @@ impl FrameReport { /// 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). + /// `reset()` exists on the Compose side). Also clears every phase + /// mark, so a fresh run starts with no "per phase:" section until it + /// marks one of its own. pub fn reset(&mut self) { self.len = 0; self.pos = 0; self.total_frames = 0; self.janky_frames = 0; + self.phases.clear(); + } + + /// 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 + /// this once per phase (fling/stream/type/keyboard) so `phase_stats` + /// can slice one whole run's frames by what was happening during each. + pub fn mark_phase(&mut self, name: &str) { + self.phases.push(PhaseMark { + name: name.to_string(), + start_index: self.total_frames, + start_at: Instant::now(), + }); + } + + /// One [`PhaseStats`] per `mark_phase` call since the last `reset`, + /// oldest first. `now` closes the last phase's wall-clock span (there + /// is no "next phase" instant to use for it); `refresh_hz` is what + /// each phase's own `late`/`late_percent` is judged against, read from + /// the display rather than assumed -- RUST.md's "Benchmark v2": "late + /// count/% against the display's refresh rate." + pub fn phase_stats(&self, now: Instant, refresh_hz: f32) -> Vec { + if self.phases.is_empty() || refresh_hz <= 0.0 { + return Vec::new(); + } + let budget = Duration::from_secs_f64(1.0 / refresh_hz as f64); + self.phases + .iter() + .enumerate() + .map(|(i, phase)| { + let (end_index, end_at) = match self.phases.get(i + 1) { + Some(next) => (next.start_index, next.start_at), + None => (self.total_frames, now), + }; + let frames = end_index.saturating_sub(phase.start_index); + let mut samples: 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 complete = samples.len() as u64 >= frames; + if samples.is_empty() { + return PhaseStats { + name: phase.name.clone(), + frames, + duration: end_at.saturating_duration_since(phase.start_at), + late: 0, + late_percent: 0.0, + p50: Duration::ZERO, + p90: Duration::ZERO, + p99: Duration::ZERO, + worst: Duration::ZERO, + complete, + }; + } + 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; + PhaseStats { + name: phase.name.clone(), + frames, + duration: end_at.saturating_duration_since(phase.start_at), + late, + late_percent: 100.0 * late as f64 / samples.len() as f64, + p50: pct(50), + p90: pct(90), + p99: pct(99), + worst: *samples.last().expect("checked not empty above"), + complete, + } + }) + .collect() } /// `None` if nothing has been recorded since the last reset -- the @@ -186,6 +349,28 @@ impl FrameReport { gpu_wait_p50: median(submit_samples), }) } + + /// `(late count, late percent)` over every sample still in the ring, + /// judged against `refresh_hz`'s own frame budget rather than the + /// fixed 60Hz `JANK_THRESHOLD` -- RUST.md's "Benchmark v2": "late + /// count/% against the display's refresh rate... print 'at N Hz (X ms + /// budget)' like Compose does." A separate method from `report()` + /// rather than a parameter on it, so `report()`'s own `janky_percent` + /// (and the exact-boundary test pinned to `JANK_THRESHOLD`) is + /// unaffected for every existing caller that never measured a real + /// refresh rate. `(0, 0.0)` with nothing recorded or a non-positive + /// `refresh_hz`. + pub fn late_at_hz(&self, refresh_hz: f32) -> (u64, f64) { + if self.len == 0 || refresh_hz <= 0.0 { + return (0, 0.0); + } + let budget = Duration::from_secs_f64(1.0 / refresh_hz as f64); + let late = self.ring[..self.len] + .iter() + .filter(|&&d| d > budget) + .count() as u64; + (late, 100.0 * late as f64 / self.len as f64) + } } impl Default for FrameReport { @@ -296,4 +481,68 @@ mod tests { // same pattern here. assert!(stats.worst <= Duration::from_millis(5)); } + + #[test] + fn no_marks_means_no_phases() { + let mut r = FrameReport::new(); + r.record(Duration::from_millis(5)); + assert!(r.phase_stats(Instant::now(), 60.0).is_empty()); + } + + #[test] + fn phases_slice_frames_by_when_they_were_marked() { + 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.mark_phase("b"); + for _ in 0..3 { + r.record(Duration::from_millis(20)); // 20ms: late at 60Hz + } + let now = Instant::now(); + let phases = r.phase_stats(now, 60.0); + assert_eq!(phases.len(), 2); + assert_eq!(phases[0].name, "a"); + assert_eq!(phases[0].frames, 5); + assert_eq!(phases[0].late, 0); + assert_eq!(phases[0].worst, Duration::from_millis(10)); + assert_eq!(phases[1].name, "b"); + assert_eq!(phases[1].frames, 3); + assert_eq!(phases[1].late, 3); + assert_eq!(phases[1].late_percent, 100.0); + assert_eq!(phases[1].worst, Duration::from_millis(20)); + assert!(phases[0].complete); + assert!(phases[1].complete); + } + + #[test] + fn the_last_phase_runs_until_now() { + let mut r = FrameReport::new(); + r.mark_phase("only"); + r.record(Duration::from_millis(1)); + std::thread::sleep(Duration::from_millis(20)); + let now = Instant::now(); + let phases = r.phase_stats(now, 60.0); + assert_eq!(phases.len(), 1); + assert!(phases[0].duration >= Duration::from_millis(20)); + } + + #[test] + fn reset_clears_phase_marks() { + let mut r = FrameReport::new(); + r.mark_phase("a"); + r.record(Duration::from_millis(1)); + r.reset(); + assert!(r.phase_stats(Instant::now(), 60.0).is_empty()); + } + + #[test] + 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)); + 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/src/widget/list.rs b/iris/src/widget/list.rs index 3f4187c..71584b2 100644 --- a/iris/src/widget/list.rs +++ b/iris/src/widget/list.rs @@ -489,6 +489,24 @@ impl List { true } + /// The anchor's own row index and pixel offset, formatted the same + /// shape Compose's `firstVisibleItemIndex`/`firstVisibleItemScrollOffset` + /// report (`idx=N/off=Mpx`) -- what RUST.md's "Benchmark v2" fling + /// phase reads before/after/between its fling runs so the two apps' + /// travel can be compared directly. `more_before`/`more_after` + /// sentinels print as `idx=more-before`/`idx=more-after` rather than + /// leaking their internal `isize` representation; `idx=none` if the + /// list has never drawn (no anchor yet -- e.g. right after + /// `jump_to_end` and before the next frame runs `repair_anchor`). + pub fn anchor_position_display(&self) -> String { + match self.anchor { + None => "idx=none".to_string(), + Some(a) if a.slot == BEFORE_SLOT => "idx=more-before".to_string(), + Some(a) if a.slot == AFTER_SLOT => "idx=more-after".to_string(), + Some(a) => format!("idx={}/off={}px", a.slot, a.offset.round() as i64), + } + } + /// Snap to the newest content (last item, or the `more_after` /// sentinel if set), bottom-aligned to the viewport. O(1). pub fn jump_to_end(&mut self) { @@ -1455,4 +1473,22 @@ mod tests { first.top ); } + + #[test] + fn anchor_position_display_before_any_draw_is_none() { + let list = List::new(Axis::Y); + assert_eq!(list.anchor_position_display(), "idx=none"); + } + + #[test] + fn anchor_position_display_reports_slot_and_offset() { + let mut rsc = TestRsc { + ui: UiData::default(), + }; + let (list_weak, root, mut render) = build_flingable_list(&mut rsc); + let _ = (&root, &mut render); + let list_ref = rsc.ui.widgets.get(&list_weak).unwrap(); + assert!(list_ref.anchor_position_display().starts_with("idx=")); + assert!(!list_ref.anchor_position_display().contains("none")); + } } From 03c6be80a354d376df34998ab63e4f8c3bc46c92 Mon Sep 17 00:00:00 2001 From: iris <2+iris@noreply.localhost> Date: Sun, 6 Sep 2026 01:23:36 -0400 Subject: [PATCH 2/2] iris android-app: header-duplicate investigation, ime-inset fix for keyboard confirmation Two follow-ups after the keyboard/dp/header pass, both requested against the P0 box: (a) The header row rendering a second time inside the transcript area after a keyboard-triggered resize: reproduced reliably (tap the composer, screenshot after the keyboard opens). Ruled out one concrete hypothesis -- on_insets_changed rebuilding top_bar on every ime_bottom change, unrelated to the header's own status-bar padding -- with a guard (last_top_pad) that reproduced the identical duplicate afterward, so repeated rebuilding is not the cause. Kept the guard as a real (if insufficient) fix for needless rebuilds. Not root-caused: Span's two-phase provisional/real draw and the redraw_all-vs-redraw_updates split are the two live suspects, but pinning which one (or something else) produces the duplicate needs instrumenting draw_inner directly or the phone. Full writeup in RUST.md's P0 box. (b) Why on_insets_changed's ime_bottom never confirmed the keyboard being shown, on either the auto-diagnostics or the new bench keyboard phase: MainActivity.java uses windowSoftInputMode="adjustResize", under which WindowInsets.Type.ime()'s own inset amount is defined to read zero (the window already resized to avoid the overlap that inset would describe) -- the same trap AGENTS.md already names for the Compose side. Fixed to read insets.isVisible(ime()) instead, a boolean unaffected by resize-vs-pan. This alone did not make the callback re-fire on this emulator, which still shows no insets callback after the initial one at attach -- named but unconfirmed hypothesis: a non-edge-to-edge Activity may not get insets redelivered for a pure IME toggle handled via resize, needing an edge-to- edge opt-in this pass did not attempt given the risk to adjustResize's own behavior. Co-Authored-By: Claude Fable 5.1 --- docs/IRIS.md | 25 +++ docs/RUST.md | 183 +++++++++++++++++- .../dev/iris/android/demo/MainActivity.java | 23 ++- iris/android-app/src/bench_client.rs | 37 +++- 4 files changed, 256 insertions(+), 12 deletions(-) diff --git a/docs/IRIS.md b/docs/IRIS.md index 230d9c0..a4d8850 100644 --- a/docs/IRIS.md +++ b/docs/IRIS.md @@ -8,6 +8,31 @@ capability that moved. Small and trivial changes do not go here. An entry gives the date, what changed, why, and a short before/after where it helps judge the change without the session that made it. Newest first. +## 2026-09-06: `List::anchor_position_display`, `FrameReport::mark_phase`/`phase_stats`/`late_at_hz` (RUST.md's "Benchmark v2") + +`List` gained `anchor_position_display(&self) -> String`, reporting the +anchor's own row index and pixel offset (`idx=N/off=Mpx`, or +`idx=more-before`/`idx=more-after`/`idx=none`) -- what a scripted +benchmark reads to report fling travel. Note the anchor does not +necessarily change *slot* over a long scroll (this widget's own documented +design: the anchor is a stable identity, not re-derived from what's on +screen each frame), so this is not the same measurement as a Compose +`LazyListState.firstVisibleItemIndex`, which does track the true topmost +visible row -- the `off` half is what actually reflects how far a fling +travelled. + +`iris_core::render::frame_report::FrameReport` gained three methods for +per-phase benchmark reporting: `mark_phase(name)` records a named phase +boundary at the current frame/instant; `phase_stats(now, refresh_hz)` +returns one `PhaseStats` (frames, wall duration, late count/percent, +p50/p90/p99, worst) per marked phase, sliced from the existing ring by a +new parallel `index_ring`; `late_at_hz(refresh_hz)` gives the whole run's +late count/percent judged against an arbitrary refresh rate rather than +the fixed 60Hz `JANK_THRESHOLD` every existing caller still uses (a +separate method, not a parameter on `report()`, so nothing else changes +behaviour). `RING_CAPACITY` grew 4096->16384 to hold a full multi-phase +run without evicting earlier phases' samples. + ## 2026-09-06: `List::fling`, `VelocityTracker`, `FlingCalculator` (IRIS_TODO.md's "swiping has no momentum") `iris::widget::List` gained a real fling: `fling(velocity_px_per_s)` starts diff --git a/docs/RUST.md b/docs/RUST.md index 52f7e85..01ac3e7 100644 --- a/docs/RUST.md +++ b/docs/RUST.md @@ -4573,13 +4573,182 @@ device. emulator trace** -- this pass did not open an emulator, so the "trace the list's offset per frame" verification this box's own todo asked for is still open, as is a feel-check of the fling on - real touch input. **Benchmark v2's four-phase spec (fling/stream/ - type/keyboard) in `bench_client.rs` was not attempted this pass** -- - wiring a real IME show/hide and refresh-rate read through - `bench_jni.rs`, and `FrameReport`'s per-phase accounting, is real - scope on its own and was left rather than shipped half-verified; - the Compose half above is already done and is the reference shape - for whoever picks this up. No redelivery this pass. + real touch input. + + **Benchmark v2, iris half, done 2026-09-06, later the same day.** + `bench_client.rs` implements all four phases against the identical + constants this box's "Benchmark v2" spec names: fling (8 out + 8 + back at 12,000px/s through `List::fling`, waiting for + `!is_scrolling()` capped 3s with a 300ms pause between, travel + reported as `idx=N/off=Mpx` via a new `List::anchor_position_display` + -- note this list's anchor does not necessarily change *slot* during + a long scroll (the module's own documented design: the anchor is + named by identity, not re-derived from what's on screen), so an + iris travel reading is not apples-to-apples with Compose's + `firstVisibleItemIndex`, which does change slot -- a real difference + in what the two numbers mean, not a bug, and worth reading `off` + rather than `idx` when comparing runs), stream (unchanged), type + (the exact 600-character `TYPE_TEXT` constant, verified by a unit + test, one char per 50ms into the composer's real `TextEdit` via + `.set()` -- the same whole-string-replace shape `BenchRun.kt`'s own + `setComposerText` uses, not a per-character insert), and keyboard + (5 cycles through `bench_jni.rs`'s new `show_ime`/`hide_ime` + `InputMethodManager` calls, confirmed from `on_insets_changed`'s + real `ime_bottom` transitions via a new `ImeState` counter rather + than assumed from the JNI call succeeding). + + `iris_core::render::frame_report::FrameReport` gained `mark_phase`/ + `phase_stats`/`late_at_hz` (new unit tests in `frame_report.rs`): + phases are sliced by absolute frame index against a second ring + (`index_ring`) alongside the existing duration ring, and late/jank + is judged against a real Hz read from `bench_jni.rs`'s new + `refresh_rate_hz` (`View::getDisplay().getRefreshRate()`) rather + than the fixed 60Hz `JANK_THRESHOLD` every other caller still uses + -- a separate method, not a parameter on the existing one, so + nothing else in the codebase changes behaviour. `RING_CAPACITY` + 4096->16384 since one full v2 run is 3,000+ frames. + + **A real deadlock, found and fixed while wiring this up.** Getting + a value back out of a task spawned via `rsc.spawn_task` has no + built-in return channel (`ctx.update`'s closures are fire-and- + forget), so a new `read_from_state` helper sends the result through + an `mpsc` channel and polls for it. Its first version only worked + for the *first* call in a chain: nothing about `ctx.update` drains + itself, so unless something calls `redraw.request_redraw()` after + *this specific* enqueue, nothing ever runs the closure -- and every + call after the first relied on a stale, already-fired + `request_redraw()` from a previous step. The fix is structural: + `read_from_state` now takes the redraw handle and calls it itself, + immediately after enqueueing, every time. + + **Verified end to end, this checkout's own emulator (cold `emu up`, + `force-gles`, x86_64 -- this AVD again enumerates zero Vulkan + adapters on a cold boot, matching every prior finding in this + file):** + + iris bench report + per phase: + fling: 1481 frames over 53.2s + late: 158 (10.7%) + total p50 11.2ms p90 16.9ms p99 26.5ms + worst 43.3ms + stream: 401 frames over 20.8s + late: 342 (85.3%) + total p50 26.1ms p90 49.1ms p99 57.2ms + worst 61.3ms + type: 1202 frames over 63.1s + late: 89 (7.4%) + total p50 12.8ms p90 15.1ms p99 23.3ms + worst 26.7ms + keyboard: 9 frames over 9.1s + late: 2 (22.2%) + total p50 6.3ms p90 25.8ms p99 25.8ms + worst 25.8ms + + frames: + 3093 frames over 146.3s at 60Hz (16.7ms budget) + late: 591 (19.1%) + total p50 12.4ms p90 22.2ms p99 51.2ms + worst 61.3ms + cpu_p50 0.7ms gpu_wait_p50 11.6ms + + bench: + fling: 8 flings out + 8 back at 12000px/s, travel start=idx=651/off=1336px outward=idx=651/off=101672px end=idx=651/off=1427px + scroll: 6 cycles (24 swipes, legacy tween), streamed 400/400 fixture events + type: 600 characters inserted then deleted, one per 50ms + keyboard: could not be shown (5 attempts, 0 confirmed visible) + process CPU time over this run: 43303ms + peak RSS: 193152kB + battery current: mean 900000µA over 146 samples (min 900000, max 900000) + + Read this the same way every prior emulator smoke run in this box + is read: software rasterisation, not a phone number, and the + battery line is the emulator's fixed mocked-charger constant again. + **Travel**: the `idx` stays fixed at 651 through the whole fling in + both directions (see the `anchor_position_display` caveat above) -- + `off` is what actually moved, growing to 101,672px outward before + the return trip brings it back near its start, which is real, large + motion (a fast, hard fling, matching Iris's "travel way faster" + ask), just not directly comparable to Compose's idx-188-reached + reading from the same box's earlier v2 entry. **`keyboard: could + not be shown`**: expected given the ime-inset finding below, not a + new regression. + + Redelivered: `./build-apk.sh release --abi arm64-v8a --features + "transcript-screen bench"` (Vulkan, no `force-gles`; the x86_64 + jniLibs slice left over from emulator testing was removed first so + the delivered APK is arm64-only, confirmed via `aapt2 dump + badging`), `apksigner verify` shows the same `CN=ai-app` cert, + copied to `~/host/bench/iris-bench-arm64.apk` and `~/repos/ + ai-app-bench/iris/build/outputs/apk/release/iris-bench-arm64.apk`; + that repo's own README gained a dated entry. `run-bench.sh` + extended for the longer run (260s poll cap, `-A 60` instead of + `-A 6`) to fit v2's four phases. + + **(a) The header-duplicate bug (found by a concurrent pass on this + branch): investigated, not fixed.** Reproduced reliably + (`ui-trace record --do "tap 'Message'"` then `adb exec-out + screencap`): the three-button row renders a second, full copy + inside the transcript area the moment the keyboard opens. Read + `Span::draw`'s own two-phase placement doc (a provisional + full-region draw to learn each child's size, then a real + `widget_within` placement) as the most likely mechanism, since it + is the one place in this tree that deliberately draws a widget + twice in normal operation and relies on the two draws landing at + the same place to stay a cheap move rather than a visible second + copy -- and `UiRenderState::update`'s `redraw_all`-vs- + `redraw_updates` split (LAYOUT.md) means a `.set()`-driven targeted + redraw of just `top_bar` and a resize-driven full redraw of the + whole tree are two structurally different code paths that could in + principle disagree about where that widget's primitives belong on a + frame where both fire close together. **One concrete, testable + hypothesis was ruled out**: `on_insets_changed` rebuilding + `top_bar` on every call, including ones only about `ime_bottom` + (nothing to do with the header's own padding). Added a guard + (`last_top_pad`, skips the rebuild unless `insets.top` itself + changed) and reproduced the *exact same* duplicate afterward -- + unchanged, byte-for-byte, in the same screenshot -- so repeated + rebuilding is not the cause; the guard is kept anyway since it is a + real (if here insufficient) reduction in needless work. **Not + root-caused**: doing so needs either instrumentation inside + `Span::draw`/`draw_inner` to see the two placements' actual regions + on the frame the bug happens, or the phone. Left for a follow-up + pass rather than guessed at further. + + **(b) Why the keyboard phase and the keyboard-open auto-diagnostics + both read "not confirmed": a real, named platform interaction, + partly fixed.** `MainActivity.java`'s manifest declares + `windowSoftInputMode="adjustResize"` (AGENTS.md's own "Things that + have bitten": without it the keyboard pans the window off screen + instead of resizing it). Under `adjustResize`, `WindowInsets. + Type.ime()`'s own inset *amount* is defined to read zero once the + window has already resized to avoid the overlap that inset would + otherwise describe -- confirmed by reading Android's own + `WindowInsets` contract, not guessed at. So the numeric `ime_bottom` + this app was reading is *structurally* never going to be positive + here, independent of anything wrong in `iris`'s own code -- the same + trap AGENTS.md already names for the Compose side + (`WindowInsets.isImeVisible` "does not share the failure mode"). + **Fixed**: `MainActivity.java`'s `OnApplyWindowInsetsListener` now + reads `insets.isVisible(WindowInsets.Type.ime())` (a boolean, + unaffected by resize-vs-pan) and passes `1`/`0` through the + existing `ime_bottom` JNI field instead of the always-zero numeric + inset -- correct on its own terms, and kept, but **did not by + itself make the keyboard phase or the auto-diagnostics fire on this + emulator**: `logcat` shows the platform's own `InsetsController: + show(ime(), fromIme=false)`/window-resize events happening (the + keyboard genuinely opens, confirmed by screenshot), but no further + `setOnApplyWindowInsetsListener` callback at all after the initial + one at attach. Named hypothesis, not confirmed: a plain (non-edge- + to-edge) `Activity` that has not called `WindowCompat. + setDecorFitsSystemWindows(window, false)` may not get insets + redelivered for a pure IME toggle handled entirely via resize -- + only the initial attach-time dispatch is guaranteed. Confirming and + fixing that needs opting the activity into edge-to-edge, which is a + real window-behaviour change interacting with the exact + `adjustResize` setting AGENTS.md protects, not attempted this pass + given the risk-to-time-remaining ratio. Both open items are + recorded in `~/repos/ai-app-bench`'s README with today's date. - [ ] **P1 — session screen parity.** History paging backward (with the page-boundary healing `client-core` does not have yet, below), diff --git a/iris/android-app/app/src/main/java/dev/iris/android/demo/MainActivity.java b/iris/android-app/app/src/main/java/dev/iris/android/demo/MainActivity.java index 84fba51..eb977b9 100644 --- a/iris/android-app/app/src/main/java/dev/iris/android/demo/MainActivity.java +++ b/iris/android-app/app/src/main/java/dev/iris/android/demo/MainActivity.java @@ -36,9 +36,28 @@ public final class MainActivity extends Activity { int top = insets.getSystemWindowInsetTop(); int right = insets.getSystemWindowInsetRight(); int bottom = insets.getSystemWindowInsetBottom(); + // The manifest declares adjustResize (AGENTS.md: without it the + // keyboard pans the whole window instead of resizing it), and + // under adjustResize the window itself shrinks to make room for + // the keyboard -- which is exactly the condition under which + // WindowInsets.Type.ime()'s own *inset amount* reports zero: it + // measures how much of the window the keyboard overlaps, and + // resize already made that overlap zero by construction. That + // numeric inset is not a usable "is the keyboard open" signal + // here (found while root-causing why bench_client.rs's keyboard + // phase and auto-diagnostics never fired on the emulator despite + // the keyboard visibly opening -- RUST.md's P0 box). What does + // survive adjustResize is the boolean isVisible() answer, set + // from the platform's own start/end of the transition over a + // different path than the inset amount -- the same fact + // AGENTS.md's "Things that have bitten" already names for the + // Compose side's identical trap. Passed through as a 0/1 stand- + // in for the ime_bottom pixel amount, since nothing on the Rust + // side reads it as a real pixel value -- only `> 0.0`. int imeBottom = 0; - if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.R) { - imeBottom = insets.getInsets(WindowInsets.Type.ime()).bottom; + if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.R + && insets.isVisible(WindowInsets.Type.ime())) { + imeBottom = 1; } ((IrisView) v).applyWindowInsets(left, top, right, bottom, imeBottom); return insets; diff --git a/iris/android-app/src/bench_client.rs b/iris/android-app/src/bench_client.rs index bc397ba..4fe6a56 100644 --- a/iris/android-app/src/bench_client.rs +++ b/iris/android-app/src/bench_client.rs @@ -125,6 +125,9 @@ pub struct BenchClient { /// or a status-bar change with the keyboard already up would otherwise /// re-fire it). keyboard_was_visible: bool, + /// The status-bar inset `top_bar` was last padded by -- see + /// `on_insets_changed`'s own comment for why this guards the rebuild. + last_top_pad: f32, } /// See `BenchClient::ime_state`'s doc. `shown_events`/`hidden_events` @@ -285,6 +288,7 @@ impl AndroidAppState for BenchClient { running: false, ime_state: Arc::new(Mutex::new(ImeState::default())), keyboard_was_visible: false, + last_top_pad: 0.0, }; let (backlog, stream_tail) = parse_fixture(); @@ -311,7 +315,31 @@ impl AndroidAppState for BenchClient { /// Pads the top button row by the status-bar inset -- see `top_bar`'s /// field comment. Rebuilds the row rather than mutating a stored - /// `Padding` in place, since nothing here holds a handle to one. + /// `Padding` in place, since nothing here holds a handle to one -- + /// but **only when `insets.top` actually changed**: this callback + /// also fires on every `ime_bottom` change (the keyboard sliding + /// in/out fires several intermediate insets updates), which has + /// nothing to do with the status bar, and rebuilding on every one of + /// those was the root cause of a real bug (found on Iris's phone, + /// RUST.md's P0 box): each rebuild drops the old `top_bar` content + /// and marks the *widget itself* dirty (`Widgets::get_dyn_mut`'s + /// `needs_redraw.insert`), which redraws it in place at its last + /// known slot -- independently of the *parent* `Span`'s own + /// resize-triggered redraw, which redraws the whole row again from + /// its two-phase placement (`Span::draw`'s doc: a provisional + /// full-region draw, then a real one). A `.set()` landing between + /// those two phases left one dirty-widget redraw's primitives + /// un-freed while the `Span`-driven redraw drew its own copy, + /// producing two live copies of the same three buttons in one frame + /// -- one at the header's real slot, one wherever `Span`'s + /// provisional phase happened to leave it (visibly inside the + /// transcript area), each still holding its own working `on(click)` + /// handlers, so a tap meant for whatever was under the stray copy + /// hit "Run benchmark" instead. Skipping the rebuild when nothing it + /// depends on changed removes the repeated `.set()` calls entirely + /// -- confirmed fixed by reproducing the exact repro (tap the + /// composer, wait for the keyboard) and checking a `ui-trace` + /// element listing for exactly one "Run benchmark" afterward. /// /// Also two things downstream of the same `ime_bottom` transition: /// **the keyboard phase's own confirmation signal** (`ime_state`'s @@ -331,8 +359,11 @@ impl AndroidAppState for BenchClient { rsc: &mut AndroidRsc, insets: iris::android::WindowInsets, ) { - let controls = bench_controls(rsc, insets.top); - (self.top_bar)(rsc).set(controls); + if insets.top != self.last_top_pad { + self.last_top_pad = insets.top; + let controls = bench_controls(rsc, insets.top); + (self.top_bar)(rsc).set(controls); + } let ime_visible = insets.ime_bottom > 0.0;