diff --git a/client-core/src/log_ring.rs b/client-core/src/log_ring.rs index acdd662..9d6a83d 100644 --- a/client-core/src/log_ring.rs +++ b/client-core/src/log_ring.rs @@ -9,14 +9,18 @@ //! of whichever platform logger was already installed (`android_logger`, //! `env_logger`) rather than instead of it -- see [`RingLogger`]. //! -//! Two consumers, both reading the same ring rather than each keeping -//! their own: the bench app's `Copy report`/`Diagnostics` (which reads -//! [`LogRing::tail_text`] and [`LogRing::summary`]) and whatever hands the -//! log out of the process -- on Android, the `DevLogProvider` Dev Updater -//! queries, which reads [`LogRing::since`] and [`LogRing::newest_seq`]. -//! That is why reading does not consume: a line already handed over must -//! still be in the report, and a report taken twice must say the same -//! thing. +//! Three consumers, all reading the same ring rather than each keeping +//! their own: whatever hands the log out of the process -- on Android, the +//! `DevLogProvider` Dev Updater queries, which reads [`LogRing::since`] +//! and [`LogRing::newest_seq`] -- the bench app's diagnostics pane, which +//! only counts it ([`LogRing::summary`]), and the panic hook +//! ([`LogRing::try_tail_text`]). That is why reading does not consume: a +//! line already handed over must still be readable, and a report taken +//! twice must say the same thing. +//! +//! Nothing inlines the log into a copied report any more (2026-09-08): +//! Dev Updater reads it directly, so a second copy on the clipboard was +//! the same lines twice. use std::collections::VecDeque; use std::sync::{Arc, Mutex, OnceLock}; @@ -32,15 +36,6 @@ use std::time::{SystemTime, UNIX_EPOCH}; pub const DEFAULT_MAX_LINES: usize = 2000; pub const DEFAULT_MAX_BYTES: usize = 256 * 1024; -/// How many of the ring's newest lines [`LogRing::tail_text`] includes. -/// Sized for a phone's share sheet rather than for the ring itself: 150 -/// lines of `HH:MM:SS.mmm LEVEL target: message` is a few KiB, comfortably -/// short of whatever made pasting the full (up to 2000-line) ring into a -/// chat's message box laggy on Iris's phone. The full ring is still -/// reachable through `devlog`'s provider, so this only bounds what a -/// report inlines. -pub const COPY_REPORT_TAIL_LINES: usize = 150; - /// One recorded line. `seq` is assigned by the ring and only ever /// increases, so a reader that remembers where it got to can ask for what /// came after -- and a gap in the sequence is exactly the lines the bound @@ -249,35 +244,6 @@ impl LogRing { .join("\n") } - /// The newest `max_lines` lines, formatted, with a first line naming - /// how many older ones were left out of *this* text when the ring held - /// more than that -- what `Copy report` appends instead of - /// [`Self::to_text`]. - /// - /// Iris's own report: pasting the full ring (over a thousand lines on - /// a session that ran with tracing on) into a phone's message box was - /// what "causes a lot of lag" meant (docs/IRIS_TODO.md, 2026-09-07 - /// night) -- nothing is actually lost, since `devlog`'s provider still - /// hands Dev Updater's Runtime tab the whole ring; this only caps what - /// gets inlined into a share. - pub fn tail_text(&self, max_lines: usize) -> String { - let lines = self.snapshot(); - if lines.len() <= max_lines { - return lines - .iter() - .map(LogLine::format) - .collect::>() - .join("\n"); - } - let omitted = lines.len() - max_lines; - let tail = lines[lines.len() - max_lines..] - .iter() - .map(LogLine::format) - .collect::>() - .join("\n"); - format!("{omitted} earlier lines omitted; full log in Dev Updater's Runtime tab\n{tail}") - } - /// The newest `max_lines` lines, formatted, or `None` if the ring is /// locked at this instant. /// @@ -591,33 +557,6 @@ mod tests { assert_eq!(ring.to_text().lines().count(), 2); } - #[test] - fn tail_text_is_the_whole_ring_untouched_when_under_the_cap() { - let ring = LogRing::new(100, 1 << 20); - fill(&ring, 5); - assert_eq!(ring.tail_text(150), ring.to_text()); - } - - #[test] - fn tail_text_trims_to_the_newest_lines_and_says_how_many_were_left_out() { - let ring = LogRing::new(1000, 1 << 20); - fill(&ring, 200); - let tail = ring.tail_text(150); - let mut lines = tail.lines(); - assert_eq!( - lines.next().unwrap(), - "50 earlier lines omitted; full log in Dev Updater's Runtime tab" - ); - let rest: Vec<&str> = lines.collect(); - assert_eq!(rest.len(), 150, "exactly the cap, after the header line"); - assert!( - rest[0].ends_with("line 50"), - "the oldest line kept is the 50th, not line 0: {}", - rest[0] - ); - assert!(rest.last().unwrap().ends_with("line 199")); - } - #[test] fn try_tail_text_gives_the_newest_lines_with_no_header() { let ring = LogRing::new(1000, 1 << 20); diff --git a/docs/IRIS.md b/docs/IRIS.md index 221aa9d..3c3d031 100644 --- a/docs/IRIS.md +++ b/docs/IRIS.md @@ -12,7 +12,50 @@ things still stay out. 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-08 (newest): one `ScrollController`, a `Scrollable` trait, and `Pin` +## 2026-09-08 (newest): redrawing one widget cost O(its own primitives squared) + +Your report -- expanding a tool card with a long horizontally-scrolling +edit in it lags -- is a framework defect, not a text-layout one, and the +size of it is not close: **a 51,200-glyph block took 1.37 seconds to +redraw, of which shaping and rasterising the text was 20ms.** It is 29ms +now, and the cost is linear in the glyph count rather than quadratic. + +What happened. A widget redrawn in place frees every primitive it owned +and writes fresh ones. Freeing compacts each layer's draw order with +`swap_remove`, and every primitive that gets swapped into a hole has to be +told its new position -- so a widget with N primitives generates ~N +renumberings. Finding the handle to renumber was a **linear scan of +everything that widget drew**, which made the pass N^2. For a paragraph +that is nothing. For one text widget holding a whole `old_string` and +`new_string`, N is every glyph in the card. + +The fix is a back-pointer: the primitive arena now records, per slot, +where that slot's handle sits in its owner's `ActiveData::primitives` +(`Primitives::handle_index`), written at the one place a handle is taken +(`Painter::own`). `apply_free` indexes straight to it. + + 50,000 glyphs, redrawn: before 636ms/redraw after 2.4ms/redraw + per glyph: before 12.7us after 0.043us (flat in N) + +`benches/message_list.rs` grew scenario **(g)** for it, and the number to +read is per-glyph: flat as N grows is the pass condition, and a total +hides it. Two things about that file: it also caught the quadratic in +`--phone`-sized text, and it had stopped running at all -- scenarios (a) +and (e) built a `LazySpan` with no mask around it, which the span now +asserts against, so the whole benchmark panicked on its second line. +Fixed in the same change. + +**What this does not fix, and what I would do next.** An open card still +shapes, rasterises and submits *every* glyph of its input and output, not +the screenful you can see -- iris does not cull within a widget, and a +tool card is the one place that bites, because an `Edit`'s `old_string` +and `new_string` go onto the card whole. The output half is already capped +(`OUTPUT_LINES`/`OUTPUT_BYTES` in `tool.rs`, 80 lines or 4 KiB behind a +"Show all"); the *input* half has no cap at all, and that is the +asymmetry to close. Wrapping the block, which you asked for, changes the +shape but not this cost: the same glyphs are laid out either way. + +## 2026-09-08: one `ScrollController`, a `Scrollable` trait, and `Pin` Your three points on `docs/SCROLL.md`, in one change. The shape is the one you proposed: **a controller both scrolling widgets contain**, rather than diff --git a/docs/IRIS_TODO.md b/docs/IRIS_TODO.md index 75998cb..43ea59b 100644 --- a/docs/IRIS_TODO.md +++ b/docs/IRIS_TODO.md @@ -944,6 +944,21 @@ diagnosis and what building it actually costs. the shaped-mask work (`.masked_by`, 38bf630) is the likeliest, since the old chain was `.masked()` *inside* the padding. Left ticked with the original symptom recorded rather than deleted, in case it comes back. +- [ ] **An open tool card lays out every glyph of its input, however + long.** iris does not cull within a widget -- a `Text` shapes, + rasterises and submits the whole string whether or not the box it sits + in can show it -- and a tool card is where that bites, because an + `Edit`'s `old_string` and `new_string` go onto the card whole. The + *output* half is already capped at 80 lines or 4 KiB behind a "Show + all" (`tool.rs`'s `OUTPUT_LINES`/`OUTPUT_BYTES`); the input half has no + cap at all, which is the asymmetry to close, and the cheaper fix of the + two. Culling inside a `Text` is the other, and is a real design + question: the shaped layout knows where each glyph is, so a viewport + test is possible, but nothing else in iris cares where the screen is. + Found 2026-09-08 chasing Iris's "expanding the edit card lags" report, + whose actual cause was the quadratic `apply_free` (fixed; docs/IRIS.md). + Wrapping the block does not change this cost -- the same glyphs are laid + out either way. - [ ] **No overflow ellipsis.** `TextAttrs` can wrap or not wrap; there is no "one line, ellipsised" the way `maxLines = 1` + `TextOverflow. Ellipsis` gives Compose. A tool card's summary is clipped instead, so diff --git a/iris/android-app/src/bench_client.rs b/iris/android-app/src/bench_client.rs index f5cc9b8..d21c573 100644 --- a/iris/android-app/src/bench_client.rs +++ b/iris/android-app/src/bench_client.rs @@ -699,6 +699,13 @@ impl BenchClient { /// it copies the diagnostics pane's own text instead, with a first /// line saying so -- `diagnostics_text` needs no prior button press /// either, so this is never actually empty-handed. + /// The report carries **no copy of the app log** (removed 2026-09-08, + /// Iris: "please remove the app log from the diagnostics. Those can be + /// obtained through dev updater now"). Dev Updater's Runtime tab reads + /// the same ring through `devlog`'s provider, and the diagnostics + /// pane's own `devlog provider:` line names the authority to read it + /// from -- so what is left here is the measurement, not a second copy + /// of something already reachable. fn copy_report(&mut self, rsc: &mut Rsc) { let Some(platform) = &self.platform else { log::info!("iris bench report: no platform handle, can't reach the clipboard"); @@ -711,18 +718,6 @@ impl BenchClient { self.diagnostics_text(rsc) ), }; - // The ring's tail goes on the clipboard, not the full ring, and - // not into the on-screen pane either: the full ring can be over a - // thousand lines with tracing on, and pasting that into a phone's - // message box was Iris's own "causes a lot of lag" report. The - // full ring is still reachable through Dev Updater's Runtime tab - // (`devlog`'s provider reads the same ring) -- this only bounds - // what gets inlined here. - let report = format!( - "{report}\n\n=== app log ({}) ===\n{}", - crate::app_log::ring().summary(), - crate::app_log::ring().tail_text(client_core::log_ring::COPY_REPORT_TAIL_LINES) - ); if platform.copy_to_clipboard("iris bench report", &report) { log::info!("iris bench report: copied to clipboard"); } else { diff --git a/iris/benches/message_list.rs b/iris/benches/message_list.rs index a9c9b9d..33ae3c8 100644 --- a/iris/benches/message_list.rs +++ b/iris/benches/message_list.rs @@ -49,6 +49,13 @@ //! only the rows on the far side of it, never redraw the ones already //! correctly placed. //! +//! - (g) redraw-one-big-text: a single text widget of N glyphs redrawn in +//! place, which is what a tool card rebuilt on a tap costs. Every one of +//! its primitives is freed and rewritten, and so renumbered in the +//! layer's draw order -- the pass that used to be O(N^2) there +//! (`UiRenderState::apply_free`, fixed 2026-09-08). The number to watch +//! is per-glyph: it must stay flat as N grows, not grow with it. +//! //! (f), many images with zero steady-state bind-group creation, needs a //! real `wgpu` device and lives in `iris/examples/bench_images.rs` instead, //! driven through `run-headless.sh` -- see that file's header. @@ -120,10 +127,19 @@ fn build_message_list( list.push_back(LazyItem::new(i as u64, row)); } let list = rsc.ui.widgets.add_strong(list); + let weak = list.weak(); + // Masked because a `LazySpan` requires it -- it draws a row straddling + // an edge in full and relies on the clip to cut it off, and asserts as + // much rather than letting the overhang reach the screen. The app's + // own transcript screen puts the same mask around the same widget. + let root = rsc.ui.widgets.add_strong(Masked { + shape: None, + inner: list.any(), + }); // Driven through the span's own `ScrollController`, like every other // scroll area in iris: what this measures has to be the path the app // actually takes. - (list.weak(), list.any()) + (weak, root.any()) } fn report(label: &str, elapsed: std::time::Duration, draws: u64, rewrites: u64, moves: u64) { @@ -360,7 +376,15 @@ fn bench_expand_holds_edge(n: usize, growths: usize) { } let list = rsc.ui.widgets.add_strong(list); let list_weak = list.weak(); - let root = list.any(); + // Masked for `build_message_list`'s reason -- a `LazySpan` requires it. + let root = rsc + .ui + .widgets + .add_strong(Masked { + shape: None, + inner: list.any(), + }) + .any(); let growable = growable.unwrap(); let mut render = UiRenderState::new(); @@ -408,6 +432,61 @@ fn bench_expand_holds_edge(n: usize, growths: usize) { ); } +/// (g) One text widget of `chars` characters, redrawn in place `redraws` +/// times -- an open tool card whose content is rebuilt, or any widget +/// holding a lot of text that a tap changes. +/// +/// A redraw frees every primitive the widget owned and writes fresh ones, +/// so every glyph is renumbered in its layer's draw order. Finding the +/// handle to renumber used to be a scan of everything the same widget +/// drew, which made one redraw quadratic in its own glyph count: 1.37s for +/// 51,200 glyphs on this machine, against 20ms to shape and rasterise the +/// same text. Print per-glyph rather than per-redraw, since flat is the +/// pass condition and a total says nothing without dividing it. +fn bench_redraw_big_text(chars: usize, redraws: usize) { + let mut rsc = BenchRsc { + ui: UiData::default(), + }; + // One character per glyph, and varied so nothing can collapse the + // string into a repeat. + let content: String = (0..chars) + .map(|i| char::from(b'a' + (i % 26) as u8)) + .collect(); + let mut text = Text::new(content); + text.wrap = true; + let text = rsc.ui.widgets.add_strong(text); + let handle = text.weak(); + let root = text.any(); + + let mut render = UiRenderState::new(); + render.resize((1080.0, 2000.0)); + render.update(&root, &mut rsc); + render.take_counters(); + + let mut total = std::time::Duration::ZERO; + for _ in 0..redraws { + // Asking for the widget mutably is what marks it for redraw -- + // the same path a caller changing its content takes. + rsc.ui.widgets.get_mut(&handle).unwrap(); + let start = Instant::now(); + render.update(&root, &mut rsc); + total += start.elapsed(); + } + let (draws, rewrites, moves, _shapes) = render.take_counters(); + report( + &format!("(g) redraw one {chars}-glyph text, {redraws}x (totals)"), + total, + draws, + rewrites, + moves, + ); + println!( + " per redraw: {:.3}ms, per glyph: {:.4}us", + total.as_secs_f64() * 1000.0 / redraws as f64, + total.as_secs_f64() * 1_000_000.0 / (redraws * chars) as f64, + ); +} + fn main() { println!("iris message-list benchmark -- release build, this machine's CPU"); for &n in &[100usize, 1_000, 10_000] { @@ -425,4 +504,7 @@ fn main() { for &n in &[100usize, 1_000, 10_000] { bench_expand_holds_edge(n, 40); } + for &chars in &[1_000usize, 10_000, 50_000] { + bench_redraw_big_text(chars, 10); + } } diff --git a/iris/core/src/render/primitive.rs b/iris/core/src/render/primitive.rs index 8230517..e184090 100644 --- a/iris/core/src/render/primitive.rs +++ b/iris/core/src/render/primitive.rs @@ -124,6 +124,20 @@ macro_rules! primitives { pub struct Primitives { instances: Vec, assoc: Vec, + /// Where each slot's [`PrimitiveHandle`] sits in its owner's + /// `ActiveData::primitives` -- the index that makes + /// `UiRenderState::apply_free` O(1) per renumbered primitive instead + /// of a scan of everything the owner drew. Written by + /// [`Self::set_handle_index`] from the one place a handle is taken + /// into that vec (`Painter::own`), and dead alongside its `assoc` + /// entry, which is what keeps the two in step. + /// + /// Without it a text widget that is freed and redrawn in one frame + /// costs O(glyphs^2): every one of its glyphs is renumbered, and each + /// renumbering scanned all of them. Measured 2026-09-08 at 1.37s for a + /// 51,200-glyph block on this machine, against 20ms for the shaping + /// and rasterising of the same text. + handle_idx: Vec, /// Slots freed since the last [`Self::apply_free`]. Deliberately not /// reusable yet: the layer that drew one still names it in its draw /// order until that call compacts the order, so handing it out again @@ -145,6 +159,7 @@ impl Default for Primitives { Self { instances: Default::default(), assoc: Default::default(), + handle_idx: Default::default(), freed: Vec::new(), reusable: Vec::new(), data: Default::default(), @@ -154,6 +169,11 @@ impl Default for Primitives { } impl Primitives { + /// A slot whose handle has not been recorded yet -- see + /// [`Self::handle_idx`]. No owner draws four billion primitives, so + /// the sentinel cannot collide with a real index. + const NO_HANDLE: u32 = u32::MAX; + /// Writes a primitive into the arena and hands back its slot and its /// entry in the per-primitive data. The caller (`UiRenderState`) puts /// the slot into a layer's draw order -- an instance that no layer @@ -212,10 +232,12 @@ impl Primitives { let slot = if let Some(i) = self.reusable.pop() { self.instances[i] = inst; self.assoc[i] = id; + self.handle_idx[i] = Self::NO_HANDLE; i } else { self.instances.push(inst); self.assoc.push(id); + self.handle_idx.push(Self::NO_HANDLE); self.instances.len() - 1 }; slot as u32 @@ -248,10 +270,28 @@ impl Primitives { self.assoc[slot as usize] } + /// Records that `slot`'s handle is `idx` entries into its owner's + /// `ActiveData::primitives`. Called once per primitive, by the one + /// place that puts a handle into that vec. + pub fn set_handle_index(&mut self, slot: u32, idx: u32) { + self.handle_idx[slot as usize] = idx; + } + + /// Where `slot`'s handle sits in its owner's `ActiveData::primitives` + /// -- see [`Self::handle_idx`]. `None` only for a slot whose owner + /// never took the handle, which nothing in this crate does. + pub fn handle_index(&self, slot: u32) -> Option { + match self.handle_idx[slot as usize] { + Self::NO_HANDLE => None, + idx => Some(idx as usize), + } + } + pub fn clear(&mut self) { self.updated = true; self.instances.clear(); self.assoc.clear(); + self.handle_idx.clear(); self.freed.clear(); self.reusable.clear(); self.data.clear(); diff --git a/iris/core/src/ui/painter.rs b/iris/core/src/ui/painter.rs index 3aba7d3..66f015d 100644 --- a/iris/core/src/ui/painter.rs +++ b/iris/core/src/ui/painter.rs @@ -56,10 +56,25 @@ impl<'a> Painter<'a> { self.rsc.ui_mut().masks.push_ref(self.mask); } let slot = h.slot; - self.primitives.push(h); + self.own(h); slot } + /// Take ownership of a handle this widget just wrote. + /// + /// The one place a `PrimitiveHandle` enters `self.primitives`, and so + /// the one place that can keep `Primitives::handle_index` in step with + /// where it lands -- which is what `UiRenderState::apply_free` reads + /// instead of scanning this vec. Anything that writes a primitive + /// without coming through here leaves that index unset, and its + /// position in a layer's draw order stops being renumbered. + fn own(&mut self, h: PrimitiveHandle) { + self.state + .primitives + .set_handle_index(h.slot, self.primitives.len() as u32); + self.primitives.push(h); + } + /// Writes a primitive to be rendered pub fn primitive(&mut self, primitive: P) { self.primitive_at(primitive, self.region) @@ -276,7 +291,7 @@ impl<'a> Painter<'a> { if self.mask != MaskIdx::NONE { self.rsc.ui_mut().masks.push_ref(self.mask); } - self.primitives.push(h); + self.own(h); } pub fn render_text( diff --git a/iris/core/src/ui/render_state.rs b/iris/core/src/ui/render_state.rs index c5cd0f7..0ad3eb8 100644 --- a/iris/core/src/ui/render_state.rs +++ b/iris/core/src/ui/render_state.rs @@ -207,14 +207,29 @@ impl UiRenderState { fn apply_free(&mut self) { for (layer, order) in self.layers.iter_mut() { for change in order.apply_free() { + // Straight to the handle, never a scan of everything the + // owner drew: a widget freed and redrawn in one frame has + // *every* one of its primitives renumbered here, so a scan + // makes this pass quadratic in that widget's primitive + // count -- 1.37s for one 51,200-glyph text block, against + // 20ms to shape and rasterise the same text (measured + // 2026-09-08). `Primitives::handle_index` is written where + // the handle is taken, in `Painter::own`. let owner = self.primitives.owner(change.slot); - if let Some(active) = self.active.get_mut(&owner) { - for h in &mut active.primitives { - if h.layer == layer && h.slot == change.slot { - h.pos = change.pos; - break; - } - } + let Some(idx) = self.primitives.handle_index(change.slot) else { + continue; + }; + if let Some(active) = self.active.get_mut(&owner) + && let Some(h) = active.primitives.get_mut(idx) + { + debug_assert!( + h.layer == layer && h.slot == change.slot, + "slot {} says it is handle {idx} of {owner:?}, which is slot {} in layer {}", + change.slot, + h.slot, + h.layer, + ); + h.pos = change.pos; } } }