//! Profiling runs rather than tests: what a frame costs on the CPU, at //! layer 1 (docs/RUST.md's "Three test layers") -- the real //! transcript screen over the real bench fixture, with no window, no //! compositor and no GPU, on a clock this file owns. It exists so "the //! fling stutters" can be attributed rather than guessed at, and it is //! kept between investigations rather than rewritten each time (Iris, //! 2026-09-09: "please keep the profiling rig around for future use"). //! //! cargo test --release --test frame_profile -- --ignored --nocapture //! //! from `scripts/rigs/ui-profile/`. //! //! Two runs today: `what_a_fling_frame_costs` (scrolling over transcript //! that is already folded) and `what_a_streamed_event_costs` (a reply //! arriving into it). //! //! `#[ignore]`d because it asserts nothing -- it prints a distribution, //! so `run-tests.sh` neither runs it nor can fail on it. **Release, or //! the numbers mean nothing**: layout is dominated by text shaping, which //! is an order of magnitude slower unoptimised. //! //! What it cannot answer: anything about the GPU, the present queue, or //! the phone's own clock. It measures the CPU half of a frame, which is //! where `cpu_p50` in a phone bench report comes from. use ai_app::ui::fixture::{PHONE_FRAME_MS, PHONE_SCALE, phone_size}; use iris::harness::{Harness, TouchScript}; use iris::prelude::*; use std::time::{Duration, Instant}; use ui_profile::stats::summarise; /// Passes over the same content, alternating direction. More than two /// because the question the rig was built for is whether a frame's cost /// is first-time work (which the first pass pays and the rest do not) or /// work repeated every time a row comes back on screen. const PASSES: usize = 8; /// The velocity `bench_client.rs`'s fling phase uses, so a number here /// and a number in a phone report describe the same gesture. const VELOCITY: f32 = 12_000.0; /// A fling settles on the spline's own schedule (~2s at this velocity); /// this only stops a pass that somehow never settles from running away. const PASS_CAP_MS: u64 = 4_000; #[test] #[ignore] fn what_a_fling_frame_costs() { let mut h = Harness::new(phone_size(), PHONE_SCALE); let opened = ai_app::ui::fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds"); h.frame(0); h.frame(PHONE_FRAME_MS); // The recorded flick first, so the velocity a real finger produces is // in the log beside the scripted passes below. let flick = TouchScript::parse(include_str!("../../../../app-rust/touch/flick-120hz.touch")).unwrap(); h.replay(&flick); println!( "recorded flick released at {:?}px/s; scripted passes run at {VELOCITY}px/s", (opened.screen.list)(&mut h.rsc).fling_velocity(), ); let mut t = flick.end_ms(); let mut all_frames = Vec::new(); let mut all_layouts = Vec::new(); for pass in 0..PASSES { // Away from the newest end on the even passes and back on the // odd ones, the same out-and-back the bench's fling phase drives. let velocity = if pass % 2 == 0 { VELOCITY } else { -VELOCITY }; let list = (opened.screen.list)(&mut h.rsc); list.fling(velocity); let id = opened.screen.list.id(); h.rsc.ui.animate(id); let mut frames = Vec::new(); let mut layouts = Vec::new(); let end = t + PASS_CAP_MS; while t <= end { let at = Instant::now(); h.frame(t); frames.push(at.elapsed()); layouts.push(h.render.last_layout_duration()); t += PHONE_FRAME_MS; if !(opened.screen.list)(&mut h.rsc).is_scrolling() { break; } } let laid_out = layouts .iter() .filter(|d| **d > Duration::from_micros(20)) .count(); println!( "pass {pass} ({}): {} frames, {laid_out} did layout", if velocity > 0.0 { "out " } else { "back" }, frames.len(), ); summarise("frame", &frames); all_frames.extend(frames); all_layouts.extend(layouts); // A moment at rest between passes, as a finger would leave. t += 200; } println!( "\nall {PASSES} passes, primitives={}", h.render.active_primitive_count() ); summarise("frame", &all_frames); summarise("layout", &all_layouts); } /// The other half of a bench run, and since 2026-09-09 the expensive one: /// what it costs to fold one arriving event into the transcript and show /// it. The bench's stream phase measured `build p50 9.5ms` on Iris's /// phone against a fling's 0.4ms, so this is where the frame time now is. /// /// Reports the fold and the widget-tree apply separately, because they /// are different problems with different fixes -- and reports how the /// cost moves as the transcript grows, which is the shape that says /// whether the work is per-event or per-event-times-transcript. #[test] #[ignore] fn what_a_streamed_event_costs() { let mut h = Harness::new(phone_size(), PHONE_SCALE); let opened = ai_app::ui::fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds"); h.frame(0); h.frame(PHONE_FRAME_MS); let mut items = opened.items; println!( "backlog: {} items, then {} streamed events", items.len(), opened.stream_tail.len() ); let mut fold = Vec::new(); let mut apply = Vec::new(); let mut frame = Vec::new(); // Split by whether the delta started a new markdown block, since that // is the delta that builds a widget rather than re-shaping one. let mut frame_same_block = Vec::new(); let mut frame_new_block = Vec::new(); let mut t = PHONE_FRAME_MS; let block_count = |items: &[ai_app::client::transcript_fold::TranscriptItem]| { use ai_app::client::markdown_blocks::split_blocks; use ai_app::client::transcript_fold::TranscriptItem; match items.last() { Some(TranscriptItem::AssistantMsg { text, .. }) => split_blocks(text).len(), _ => 0, } }; for (n, event) in opened.stream_tail.iter().enumerate() { let blocks_before = block_count(&items); let old = items.clone(); let at = Instant::now(); let folded = ai_app::client::transcript_fold::fold_event(&items, event); fold.push(at.elapsed()); items = folded; let added_block = block_count(&items) > blocks_before; let at = Instant::now(); opened.screen.apply(&mut h.rsc, &old, &items); apply.push(at.elapsed()); t += PHONE_FRAME_MS; let at = Instant::now(); h.frame(t); let took = at.elapsed(); frame.push(took); if added_block { frame_new_block.push(took); } else { frame_same_block.push(took); } // Where the cost sits as the transcript grows -- one line early, // one late, is enough to see a per-event cost from a quadratic. if n == 0 || n == opened.stream_tail.len() - 1 { println!( " event {n:>3} of {}: items={} fold {:?} apply {:?}", opened.stream_tail.len(), items.len(), fold[n], apply[n], ); } } summarise("fold", &fold); summarise("apply", &apply); summarise("frame", &frame); summarise("frame/same-block", &frame_same_block); summarise("frame/new-block", &frame_new_block); // What the GPU side has to carry, which layer 1 builds but never // uploads and so cannot time: every primitive is re-uploaded whenever // the arena changes, and the buffer is recreated when its length does // (`ArrBuf::update`). Splitting the streamed reply into blocks trades // shaping cost for more widgets, so this is the number that says // whether that trade is free on a real GPU path. println!( " primitives on screen at the end: {}", h.render.active_primitive_count() ); } /// What re-shaping a *growing* message costs, isolated from everything /// else a frame does -- the measurement that decides whether an /// incremental-text design would pay for itself (Iris, 2026-09-09: /// "we should definitely investigate incremental text rendering"). /// /// Grows one text buffer a delta at a time, the way a streamed reply /// grows one row, and reports what `TextBuffer::shape` costs at each /// length. Linear per-delta cost means the total over a reply is /// quadratic in its length, which is the thing an incremental shaper /// would remove. #[test] #[ignore] fn what_reshaping_a_growing_message_costs() { use iris::prelude::*; let mut h = Harness::new(phone_size(), PHONE_SCALE); // A reply-sized paragraph built a delta at a time. The deltas are // words rather than characters because that is what a model streams. const DELTA: &str = "the quick brown fox jumps over the lazy dog "; let attrs = TextAttrs::default(); let width = Some(phone_size().x); let mut buffer = iris::prelude::TextBuffer::new_empty(); let mut text = String::new(); let mut per_delta = Vec::new(); let mut total = Duration::ZERO; for n in 1..=400 { text.push_str(DELTA); buffer.set_text(text.clone()); let at = Instant::now(); buffer.shape(&mut h.rsc.ui.text, &attrs, width, PHONE_SCALE); let took = at.elapsed(); per_delta.push(took); total += took; if n % 100 == 0 { println!( " after {n:>3} deltas ({:>6} chars): this reshape {:?}", text.len(), took ); } } println!( " 400 deltas: {:?} of shaping in total, {:?} per delta at the end", total, per_delta.last().unwrap() ); summarise("reshape", &per_delta); // The same measurement at the sizes real replies actually reach. // Measured 2026-09-09 over 7,706 top-level blocks from 3,675 real // assistant messages on this machine: p50 147 chars, p90 449, p99 // 836, largest 1,580, and *nothing* above 4,000. The bench fixture's // streamed message is one 14,888-character block, which is 9x the // largest real one -- so the sizes below are what a live reshape // actually costs and the run above is what the benchmark measures. println!(" at the sizes real replies reach:"); for chars in [147usize, 449, 836, 1580] { let mut sample = String::new(); while sample.len() < chars { sample.push_str(DELTA); } sample.truncate(chars); let mut buffer = iris::prelude::TextBuffer::new(sample); let at = Instant::now(); buffer.shape(&mut h.rsc.ui.text, &attrs, width, PHONE_SCALE); println!(" {chars:>5} chars: {:?}", at.elapsed()); } } /// Where a streamed delta's cost actually is, given that `RowBlocks:: /// apply_delta` already re-shapes only the block the delta landed in. /// Three candidates, all of which scale with the *whole* message rather /// than the delta: re-parsing the markdown to find the blocks, comparing /// them against the ones already drawn, and re-shaping the last block. #[test] #[ignore] fn where_a_streamed_deltas_cost_is() { use ai_app::client::markdown_blocks::{common_prefix, split_blocks}; // A reply with real block structure -- paragraphs separated by blank // lines, the way a model writes -- so the last block is one paragraph // rather than the whole message. const SENTENCE: &str = "The quick brown fox jumps over the lazy dog. "; let mut src = String::new(); let mut blocks = Vec::new(); let mut split = Vec::new(); let mut compare = Vec::new(); for n in 1..=400 { src.push_str(SENTENCE); // A paragraph break every eight deltas, so the trailing block // stays a normal size and only the message grows. if n % 8 == 0 { src.push_str("\n\n"); } let at = Instant::now(); let new_blocks = split_blocks(&src); split.push(at.elapsed()); let at = Instant::now(); let _ = common_prefix(&blocks, &new_blocks); compare.push(at.elapsed()); blocks = new_blocks; if n % 100 == 0 { println!( " after {n:>3} deltas ({:>6} chars, {} blocks): split {:?} compare {:?}", src.len(), blocks.len(), split[n - 1], compare[n - 1], ); } } summarise("split_blocks", &split); summarise("common_prefix", &compare); let total: Duration = split.iter().chain(compare.iter()).sum(); println!(" 400 deltas: {total:?} in block-splitting and comparison alone"); } /// What the bench fixture's streamed tail actually is, since the cost of /// a delta depends entirely on how big the block it lands in gets. #[test] #[ignore] fn what_the_fixture_streams() { use ai_app::client::markdown_blocks::split_blocks; use ai_app::client::transcript_fold::TranscriptItem; let mut h = Harness::new(phone_size(), PHONE_SCALE); let opened = ai_app::ui::fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds"); let backlog = opened.items.clone(); let mut items = opened.items; let before = items.len(); for event in &opened.stream_tail { items = ai_app::client::transcript_fold::fold_event(&items, event); } println!("{} items -> {}", before, items.len()); // The stress message the generator plants in the backlog: one block, // no blank line, just under `text_cap`'s MESSAGE_BYTES. let biggest = backlog .iter() .filter_map(|item| match item { TranscriptItem::AssistantMsg { text, .. } => Some(text), _ => None, }) .map(|text| { let blocks = split_blocks(text); ( text.len(), blocks.len(), blocks.iter().map(|b| b.source.len()).max().unwrap_or(0), ) }) .max_by_key(|(_, _, longest)| *longest); if let Some((chars, blocks, longest)) = biggest { println!( " backlog's largest single block: {longest} chars (in a {chars}-char message of {blocks} blocks)" ); } // The last few items are where the stream landed. Only the message // variants matter -- those are what a delta appends to. for item in items.iter().rev().take(4) { let (kind, text) = match item { TranscriptItem::AssistantMsg { text, .. } => ("AssistantMsg", text.clone()), TranscriptItem::UserMsg { text, .. } => ("UserMsg", text.clone()), TranscriptItem::ToolRun { input, output, .. } => { ("ToolRun", format!("{input}{output}")) } _ => ("other", String::new()), }; let blocks = split_blocks(&text); println!( " tail {kind}: {} chars in {} blocks; longest block {} chars", text.len(), blocks.len(), blocks.iter().map(|b| b.source.len()).max().unwrap_or(0), ); } }