ai-app/app-rust/tests/frame_profile.rs

//! 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
//!
//! 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};

/// 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;

fn pct(sorted: &[Duration], p: f64) -> f64 {
    let i = ((sorted.len() as f64 - 1.0) * p).round() as usize;
    sorted[i].as_secs_f64() * 1000.0
}

fn summarise(name: &str, samples: &[Duration]) {
    let mut v = samples.to_vec();
    v.sort();
    let over_budget = v
        .iter()
        .filter(|d| **d > Duration::from_micros(8_333))
        .count();
    println!(
        "  {name:16} n={:<5} p50 {:.2}ms  p90 {:.2}ms  p99 {:.2}ms  worst {:.2}ms  \
         over-8.3ms {over_budget}",
        v.len(),
        pct(&v, 0.5),
        pct(&v, 0.9),
        pct(&v, 0.99),
        pct(&v, 1.0),
    );
}

#[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!("../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),
        );
    }
}