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")); + } }