diff --git a/docs/IRIS.md b/docs/IRIS.md index ad2fd1a..75ecbad 100644 --- a/docs/IRIS.md +++ b/docs/IRIS.md @@ -1161,6 +1161,49 @@ and per-block-row work (RUST.md's "Verification pass over Tasks A and B"). reply shapes exactly **1** text layout, the same as into a one-paragraph one. +## 2026-09-07: `iris::diagnostics` -- a trace toggle for input/frame lines, gating four existing per-frame `debug!` calls + +One new public module and one behaviour change to four existing log +lines, from Iris's "add another button to copy input event info ... +instrument a lot of the code with timings" request (RUST.md's own +section has the full account). + +- **`iris::diagnostics::set_trace(bool)`/`trace_enabled() -> bool`**, a + process-global switch, off by default. It gates two new diagnostics + (`sense::log_input_event`, one line per platform pointer sample under + target `iris::input`; `diagnostics::log_frame`, one line per frame + under `iris::frame`, with the frame number, the frame clock, time + since the last input, layout/draw durations, `RedrawKind`, primitives + on screen, and whether something is animating) and, as of a same-day + review finding (D1), four *older* `debug!` lines that were previously + unconditional: `android::view`'s two `render():` lines, `widget:: + list`'s `iris fling tick:`, `widget::text`'s `iris text render:`, and + `sense`'s `iris drag release samples:`. Not `log::log_enabled!`/ + `log::set_max_level`, because the app installs its logger at + `LevelFilter::Debug` already and the ring records everything that + level lets through regardless of target — the gate has to live on + this side. **Not wired to a control**: the Diagnostics pane is in + `bench_client.rs`, off-limits while another agent had it open; this + is the whole surface a button needs. +- **`UiRenderState` gained `RedrawKind`, `frame_number()`, `epoch()`, + `last_layout_duration()`, `last_redraw_kind()`, + `active_primitive_count()`, `note_input(Instant)` and + `time_since_input(Instant) -> Option`** (`iris-core`). All + read back by `log_frame`; `note_input` is called once from + `SensorUi::run_sensors`, which both backends and the harness already + share, so a frame's `since_input` is comparable across all three + without either platform doing its own bookkeeping. +- **`iris::harness::TouchAction` gained `word() -> &'static str`**, the + inverse of its own `parse` -- what a caller (here, `Harness::touch`) + hands the input logger so a `.touch` file and an `iris::input` line + agree on one spelling of each action. +- **`iris_core::Axis` gained `Debug`** — a one-line derive, needed to log + which axis a drag committed to. +- **`iris/benches/report_to_touch.py`** (new): turns a report's + `iris::input` lines back into a `.touch` file, expanding inline + historical samples into their own lines first. Round-tripped against + the harness in `iris/transcript-fixture/tests/input_log_roundtrip.rs`. + ## 2026-09-07: the phone app is told which server to talk to, and pins from the link Not an iris API change -- a client-facing one, in the crates around it, diff --git a/docs/IRIS_TODO.md b/docs/IRIS_TODO.md index 97e2840..824a2b6 100644 --- a/docs/IRIS_TODO.md +++ b/docs/IRIS_TODO.md @@ -1046,17 +1046,27 @@ do not duplicate it there. estimator and none of the rest. The release log gains a debug `iris drag release samples:` line so a flick reported from the phone can be replayed at layer 1. -- [ ] **Input-event and timing report from the phone.** Iris: "add +- [~] **Input-event and timing report from the phone.** Iris: "add another button to copy input event info so that I can do some stuff manually and then send the event log to you ... instrument a lot of the code with timings so I can give you time reports through the - same button." Build on the log ring (queue: logging through Dev - Updater), not beside it: every `MotionEvent` (action, pointer - position, event time, historical sample count) and every gesture - decision (`iris drag release:` and its siblings) at debug level into - the ring; frame timings (input handled -> layout -> draw submitted, - and the fling tick's `now` against the frame clock) at debug level - into the same ring; "Copy report" already appends the ring. Add a - second button only if the report gets too long to paste -- then - "Copy input log" copies the ring alone. Says which build it came - from. + same button." **Built on the log ring, 2026-09-07** (docs/RUST.md's + own section): `iris::sense::log_input_event` (one line per platform + pointer sample -- Android's `MotionEvent`, historical samples inline; + winit's `WindowEvent`; the harness's `TouchScript` line) and + `iris::diagnostics::log_frame` (one line per frame: frame number, + the frame clock, time since the last input, layout/draw durations, + `redraw_all`/`redraw_updates`/neither, primitives on screen, + whether something is animating), both under + `iris::diagnostics::trace_enabled()`, off by default because the ring + is only 2000 lines / 256 KiB and both targets at 120Hz fill that in + seconds. `iris/benches/report_to_touch.py` turns a report's + `iris::input` lines back into a `.touch` file for layer 1/2 replay -- + round-tripped in `iris/transcript-fixture/tests/ + input_log_roundtrip.rs`. **Not wired to a button**: the Diagnostics + pane is `iris/android-app/src/bench_client.rs`, open under another + agent at the time this landed; `set_trace(bool)` is the whole surface + a control needs. `docs/REVIEW-2026-09-07.md`'s D1 (the ring already + drowned in per-frame `debug!` lines that predated this pass) is fixed + in the same change -- see RUST.md's section for which four call + sites. diff --git a/docs/RUST.md b/docs/RUST.md index 5282dba..78db7d2 100644 --- a/docs/RUST.md +++ b/docs/RUST.md @@ -195,6 +195,124 @@ to the second name, runs, looks right, and reports whatever *it* was built with -- which is how "log upload: this build has no server configured" came from a build that had one. +### `iris::input`/`iris::frame` diagnostics, 2026-09-07 + +Iris asked for a second button (or the same "Copy report" made to say +more): "add another button to copy input event info so that I can do some +stuff manually and then send the event log to you so you know what events +the code is actually receiving. You may also want to instrument a lot of +the code with timings so I can give you time reports too through the same +button." This is that, built on the log ring rather than a second +mechanism. + +**What it writes.** `iris::sense::log_input_event` -- one line per +platform pointer sample, from Android's `on_touch_event` (once per real +`MotionEvent`, historical samples inline), the winit backend (once per +pointer `WindowEvent`, no batching), and `harness::Harness::touch` (once +per `TouchScript` line, also unbatched, which is what makes a harness +replay round-trip exactly): + + iris input: action=down x=540.0 y=1000.0 t=0ms history=0 + iris input: action=move x=540.0 y=1196.0 t=16ms history=3 4:540.0,1040.0 8:540.0,1086.0 12:540.0,1138.0 + +`iris::diagnostics::log_frame` -- one line per frame, called from each +backend's own frame function after the draw (or, on the harness, where a +draw would be): + + iris frame: n=42 now=701ms since_input=12ms layout=8.3µs draw=1.1ms redraw=Updates primitives=384 animating=true + +`n` is `UiRenderState::frame_number` (counts every call to `update`, +including one that redrew nothing); `now` is milliseconds since that +render state's own construction (`UiRenderState::epoch`, set the same way +`Harness::base` is, so it lines up with a harness's own `t_ms`); +`since_input` is how stale the input driving this frame was, from the last +sample `SensorUi::run_sensors` saw; `layout`/`draw` are `Instant` pairs +around `UiRenderState::update` and the platform's own submit+present; +`redraw` is `RedrawKind::{None,All,Updates}`; `primitives` is +`UiRenderState::active_primitive_count` (everything currently on screen, +not a per-frame delta -- `take_counters`' draw/rewrite/shape counts are +that, and `iris::frame` does not duplicate them). + +**Reading a report**: with tracing off (the default) neither target +appears at all. With it on, the two interleave in arrival order, so a +flick's shape reads as a run of `iris input:` lines followed by the frames +they drove, and a release still shows the existing `iris drag release:`/ +`iris drag release samples:` lines from `sense.rs` -- those were not +duplicated, only (the `samples:` one) brought under the same gate. + +**Replaying one**: `iris/benches/report_to_touch.py < report.txt > +replay.touch` reads every `iris input: action=...` line (ignoring +everything else in the report, prefix-agnostic -- it works on a bare +message or a full ring line with its `HH:MM:SS.mmm LEVEL target:` header) +and expands each event's inline historical samples into their own `move` +lines first, oldest first, exactly as Android delivers and replays them. +The output is an ordinary `.touch` file: +`Harness::replay(&TouchScript::parse(&text)?)` plays it back at layer 1, +or point `run-headless.sh phone --phone --replay` at it for layer 2. +Verified round-trip, both directions: a harness replay of +`flick-120hz.touch` with tracing on produces exactly six `iris::input` +lines, and piping them through the script and re-parsing reproduces the +same six `t_ms action x y` samples (`iris/transcript-fixture/tests/ +input_log_roundtrip.rs`). + +**The toggle**: `iris::diagnostics::set_trace(bool)`, off by default. +**Not `log::log_enabled!`/`log::set_max_level`**: the app already installs +its logger at `LevelFilter::Debug` (`iris/android-app/src/lib.rs`'s +`JNI_OnLoad`), and `client_core::log_ring::RingLogger::enabled` is +unconditionally `true` by design ("the ring wants everything"), so a +`log::Level::Debug` line reaches the ring regardless of what this +instrument would prefer -- the gate has to be a crate-level flag, checked +before `log::debug!` is even reached, and that is what `trace_enabled()` +is. **Not wired to a button yet**: the Diagnostics pane that would hold +the switch is in `iris/android-app/src/bench_client.rs`, which another +agent had open at the same time this was written; `set_trace` is the whole +surface a control needs, so wiring one is a follow-up for whoever is free +to touch that file next. + +**Why default off, and why the ring's size is the actual constraint**: the +ring is 2000 lines / 256 KiB +(`client_core::log_ring::DEFAULT_MAX_LINES`/`DEFAULT_MAX_BYTES`); a 120Hz +session logging a line per touch sample and a line per frame fills that in +seconds, so a caller turns tracing on only for the length of whatever is +being investigated, not for a whole session. This is also why the report +should say at its top whether tracing was on -- a caller reading +`iris::diagnostics::trace_enabled()` when building the report can print +that; nothing here does it automatically since nothing here owns the +report's own header. + +**D1 from `docs/REVIEW-2026-09-07.md`**: the review found that this gate +existed (as `iris/src/diagnostics.rs`, uncommitted at the time) but four +older per-frame `debug!` lines were not wired to it -- +`android/view.rs`'s two `render():` lines, `widget/list.rs`'s `iris fling +tick:`, and `widget/text/mod.rs`'s `iris text render:` -- each +unconditional at `Debug`, and between them enough to fill the ring in +under ten seconds at 120Hz before `Copy report` ever saw anything else. +All four (and `sense.rs`'s `iris drag release samples:`, which is +lower-volume but the same shape) are now behind +`iris::diagnostics::trace_enabled()`, moved onto the `iris::frame`/ +`iris::input` targets where each belongs. `iris::sense`'s `iris drag +release:` (info level, one per gesture, low volume, and the line that +already answered "why didn't that flick fling" from Iris's phone) is +unchanged and ungated on purpose -- it is exactly the kind of always- +useful summary line the ring is *for*. + +**Verification**: `iris/transcript-fixture/tests/ +input_log_roundtrip.rs`'s one test replays `flick-120hz.touch` through a +real capturing `log::Log` twice -- tracing off, then on -- and asserts (a) +off leaves zero `Debug`-level lines from the whole replay (`cargo test -p +transcript-fixture` catches a regression here immediately, not just this +one), (b) on produces exactly one `iris::input` line per replayed sample +and at least one `iris::frame` line with a non-zero `layout=`, and (c) the +round trip through `report_to_touch.py` reproduces the exact script. A +throwaway (not committed) 3000-frame timing loop through the harness with +tracing off vs on, idle after the opening layout, measured **2.97µs/frame +off against 3.40µs/frame on with no logger even installed** -- the +`Instant::now()` pairs and the `trace_enabled()` atomic loads that stay +live either way. That is a layer-1 proxy, not the phone's own bench (no +GPU work happens there at all), but it bounds the added cost at a few +hundred nanoseconds against a 60Hz budget of 16,600 -- three orders of +magnitude below where it could be seen. + ### APK size (2026-09-07) Iris's question: the iris bench APK is about double the Compose bench APK diff --git a/iris/benches/report_to_touch.py b/iris/benches/report_to_touch.py new file mode 100755 index 0000000..252b7e4 --- /dev/null +++ b/iris/benches/report_to_touch.py @@ -0,0 +1,96 @@ +#!/usr/bin/env python3 +"""Turns `iris::input` debug lines -- from a phone's diagnostics report, or +from a report the layer-1 harness produced with tracing on +(`iris::diagnostics::set_trace(true)`) -- back into a `TouchScript` file +`iris::harness::Harness::replay` can play back at layer 1. + +Why this exists: `docs/RUST.md`'s "Three test layers" box says the cheapest +layer that can answer a question wins, and a gesture that misbehaves on +Iris's phone is otherwise only describable in words. `iris::sense:: +log_input_event`'s one line per platform event (Android's on_touch_event +once per `MotionEvent`, with historical samples inline; winit's once per +pointer `WindowEvent`; the harness's `touch`, once per script line) already +carries everything a `.touch` file's `t_ms action x y` needs -- this just +reads it back out and reconstructs the samples in order, expanding each +event's inline historical samples into their own `move` lines first (they +are always intermediate positions of a move, and Android documents them as +oldest first, which is also the order they appear in the line). + +Usage: + report_to_touch.py < report.txt > replay.touch + report_to_touch.py report.txt > replay.touch + +Only lines containing "iris input: action=..." are read; everything else in +the report (insets, frame timings, drag-release summaries) is ignored, so +this can be pointed at Copy report's whole clipboard text directly. +""" + +import re +import sys + +# The message half of `sense::log_input_event`'s format string, prefix- +# agnostic: a real report line also carries the ring's own +# `HH:MM:SS.mmm LEVEL target:` header (`LogLine::format`) or, forwarded +# through `ai_server::client_log`, a `[ #]` tag ahead +# of that -- neither of which this needs to understand, since `search` +# (not `match`) finds the marker wherever it starts. +LINE_RE = re.compile( + r"iris input: action=(?P\w+) x=(?P-?[0-9.]+) y=(?P-?[0-9.]+) " + r"t=(?P[0-9]+)ms history=(?P[0-9]+)(?P.*)$" +) +# One historical sample inside `rest`: `t:x,y`, space-separated, oldest first +# -- see `log_input_event`'s own doc for why order matters. +HIST_RE = re.compile(r"(?P[0-9]+):(?P-?[0-9.]+),(?P-?[0-9.]+)") + + +def _fmt(value: float) -> str: + """The number as `TouchScript::parse`'s own `f32::parse` would round-trip + it -- an integer without a trailing `.0` where the source was one + (every coordinate here is a physical pixel), `{:g}` otherwise so a + fractional value from a real device is not silently truncated.""" + if value == int(value): + return str(int(value)) + return f"{value:g}" + + +def convert(lines): + """Every `iris::input` line, oldest first, expanded to one `(t_ms, + action, x, y)` tuple per touch sample -- a historical sample is always + an intermediate `move`, and the event's own sample keeps its real + action (`down`/`move`/`up`/`cancel`).""" + rows = [] + for line in lines: + m = LINE_RE.search(line) + if not m: + continue + hist_count = int(m.group("hist")) + hist_matches = list(HIST_RE.finditer(m.group("rest"))) + if len(hist_matches) != hist_count: + print( + f"report_to_touch: {line.strip()!r} says history={hist_count} but " + f"holds {len(hist_matches)} samples -- skipped", + file=sys.stderr, + ) + continue + for hm in hist_matches: + rows.append( + (int(hm.group("t")), "move", float(hm.group("x")), float(hm.group("y"))) + ) + rows.append( + (int(m.group("t")), m.group("action"), float(m.group("x")), float(m.group("y"))) + ) + return rows + + +def main(): + if len(sys.argv) > 2: + print("usage: report_to_touch.py [report.txt] < report.txt", file=sys.stderr) + return 2 + text = open(sys.argv[1]) if len(sys.argv) == 2 else sys.stdin + for t_ms, action, x, y in convert(text): + print(f"{t_ms} {action} {_fmt(x)} {_fmt(y)}") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/iris/core/src/orientation/axis.rs b/iris/core/src/orientation/axis.rs index 997036a..fa1f16a 100644 --- a/iris/core/src/orientation/axis.rs +++ b/iris/core/src/orientation/axis.rs @@ -1,6 +1,6 @@ use super::*; -#[derive(Copy, Clone, Eq, PartialEq)] +#[derive(Copy, Clone, Eq, PartialEq, Debug)] pub enum Axis { X, Y, diff --git a/iris/core/src/ui/render_state.rs b/iris/core/src/ui/render_state.rs index dd08e95..2ab34b9 100644 --- a/iris/core/src/ui/render_state.rs +++ b/iris/core/src/ui/render_state.rs @@ -1,3 +1,6 @@ +use std::sync::Mutex; +use std::time::{Duration, Instant}; + use crate::{ ActiveData, IdLike, MaskIdx, MoveIdx, Painter, PixelRegion, PrimitiveLayers, RegionAlign, StrongWidget, UiRegion, UiRsc, UiVec2, WidgetId, Widgets, @@ -5,6 +8,21 @@ use crate::{ util::{HashMap, HashSet, Id, Vec2}, }; +/// What [`UiRenderState::update`] did on its last call -- read back by the +/// `iris::frame` diagnostic (`iris::diagnostics::log_frame` in the `iris` +/// crate) so a report can tell a full relayout from a frame that only +/// redrew a handful of dirty widgets from one that drew nothing at all. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum RedrawKind { + /// Neither the root nor any widget changed -- `update` did nothing. + None, + /// [`UiRenderState::redraw_all`]: a new root, or a resize. + All, + /// [`UiRenderState::redraw_updates`]: only the widgets `needs_redraw` + /// named. + Updates, +} + pub struct UiRenderState { pub active: HashMap, pub layers: PrimitiveLayers, @@ -58,6 +76,31 @@ pub struct UiRenderState { /// Text layouts actually computed -- bumped by `Painter::render_text`, /// which `TextView::render` only reaches on a cache miss. pub(super) shape_count: u64, + + /// `Instant::now()` at construction -- the zero every `iris::frame` line + /// dates itself from, so a report's `now=` is comparable to a harness's + /// own `t_ms` (`Harness::new` builds its `base` the same way, in the + /// same constructor call) without either side needing the wall clock. + epoch: Instant, + /// How many times [`Self::update`] has run -- the `iris::frame` line's + /// frame number. Counts every call, including one that found nothing to + /// redraw, so a gap in the sequence in a report is a frame this state + /// was never asked to run at all (a stalled event loop), not one that + /// ran and did nothing. + frame_no: u64, + /// How long the redraw phase of the last [`Self::update`] took -- + /// [`Self::redraw_all`] or [`Self::redraw_updates`], whichever ran, or + /// zero if neither did. Read back by `iris::diagnostics::log_frame`. + last_layout: Duration, + last_redraw_kind: RedrawKind, + /// When the sensor dispatch (`SensorUi::run_sensors`, in the `iris` + /// crate) last saw an input sample, dated by the sample's own clock + /// (`CursorState::time`) rather than when the dispatch ran -- same + /// reasoning as that field's own doc. A `Mutex` rather than a + /// `Cell` for the same reason `captured` is: `run_sensors` takes `&self` + /// and this is the one render state both backends already share across + /// frames. + last_input_at: Mutex>, } /// The bound on the parent walk -- see `resolve_move` in shader.wgsl, @@ -87,6 +130,11 @@ impl UiRenderState { region_mut_count: 0, mov_count: 0, shape_count: 0, + epoch: Instant::now(), + frame_no: 0, + last_layout: Duration::ZERO, + last_redraw_kind: RedrawKind::None, + last_input_at: Mutex::new(None), } } @@ -150,17 +198,82 @@ impl UiRenderState { "a previous frame left {} widget(s) marked as mid-draw", self.draw_started.len(), ); - if self.needs_redraw_all(root) { + // Timed unconditionally -- an `Instant::now()` pair is cheap enough + // not to move the `--phone` bench's frame time (checked when this + // was added), and gating it behind the trace toggle would leave + // `iris::frame` with nothing to report the one frame somebody just + // turned tracing on to look at. + let layout_start = Instant::now(); + let kind = if self.needs_redraw_all(root) { self.redraw_all(root, rsc); self.old_root = root.map(|r| r.id()); self.resized = false; + RedrawKind::All } else if rsc.widgets().has_updates() { self.redraw_updates(rsc); - } + RedrawKind::Updates + } else { + RedrawKind::None + }; + self.last_layout = layout_start.elapsed(); + self.last_redraw_kind = kind; + self.frame_no += 1; #[cfg(debug_assertions)] debug_assert!(self.primitive_counts_agree(), "{}", self.orphan_report(rsc),); } + /// `Instant::now()` at construction -- see the field's own doc. + pub fn epoch(&self) -> Instant { + self.epoch + } + + /// How many times [`Self::update`] has run, counting from 1. + pub fn frame_number(&self) -> u64 { + self.frame_no + } + + /// How long the last [`Self::update`]'s redraw phase took. + pub fn last_layout_duration(&self) -> Duration { + self.last_layout + } + + /// What the last [`Self::update`] did -- see [`RedrawKind`]. + pub fn last_redraw_kind(&self) -> RedrawKind { + self.last_redraw_kind + } + + /// Records that a real input sample was just dispatched, dated by the + /// sample's own clock -- called once per sensor pass, so `iris::frame`'s + /// `since_input` can answer "how stale was the input + /// this frame drew" instead of a caller guessing from the frame + /// interval. `&self` because `run_sensors` only ever has that -- see + /// `last_input_at`'s field doc. + pub fn note_input(&self, at: Instant) { + if let Ok(mut guard) = self.last_input_at.lock() { + *guard = Some(at); + } + } + + /// `now - ` the last input sample's own timestamp, or `None` if no + /// input has ever reached this render state (a cold start, or a screen + /// that only ever animates on its own). Saturates to zero rather than + /// panicking if `now` is earlier than the input sample somehow was -- + /// a diagnostic reading wrong is not worth a crash over. + pub fn time_since_input(&self, now: Instant) -> Option { + let at = *self.last_input_at.lock().ok()?; + at.map(|at| now.saturating_duration_since(at)) + } + + /// Primitive instances every currently-active widget owns, summed -- + /// what `iris::frame`'s `primitives=` reports. Not a per-frame delta: + /// `redraw_updates` only rewrites what changed, so this is "how much is + /// on screen", which is what a report reads as "did this frame have + /// more to draw than the last one", not "how much work did this frame + /// do" (`take_counters` answers that). + pub fn active_primitive_count(&self) -> usize { + self.active.values().map(|a| a.primitives.len()).sum() + } + fn redraw_all(&mut self, root: Option<&StrongWidget>, rsc: &mut dyn UiRsc) { self.clear(rsc); // free all resources & cache diff --git a/iris/src/android/view.rs b/iris/src/android/view.rs index 42ea587..ede551d 100644 --- a/iris/src/android/view.rs +++ b/iris/src/android/view.rs @@ -406,7 +406,13 @@ impl IrisViewPeer { /// magenta and screenshotting), but no primitive ever appears on top of /// it -- on both the Vulkan/SwiftShader and GLES/virgl backends. Leave /// these in until that is root-caused; removing them loses the exact - /// evidence a `logcat` capture needs to reproduce the state. + /// evidence a `logcat` capture needs to reproduce the state. Gated on + /// `iris::diagnostics::trace_enabled` since 2026-09-07 (docs/RUST.md's + /// review, D1): unconditional, they were two `debug!` lines every + /// rendered frame, and `client_core::log_ring`'s `RingLogger` records + /// every level the app's already-`Debug` install lets through + /// regardless of target, so they filled the whole ring in under ten + /// seconds at 120Hz and left `Copy report` nothing else to show. fn render(&mut self, ctx: &mut CallbackCtx) { if self.state.android_state().renderer.is_none() { return; @@ -441,18 +447,29 @@ impl IrisViewPeer { self.state.on_insets_changed(&mut self.rsc, physical); } - let ui_state = self.state.android_state(); - log::debug!( - "render(): root={:?} widgets={} active={} root_px={:?} out_size={:?}", - ui_state.root.is_some(), - self.rsc.widgets().len(), - self.render.active_widgets(), - ui_state - .root - .as_ref() - .and_then(|r| self.render.window_region(r, &self.rsc)), - self.window_size(), - ); + // Gated the same way `iris::frame`'s own line is (docs/RUST.md's + // "Phone logging" review, D1): a bare `log::debug!` reaches + // `client_core::log_ring`'s ring regardless of level, since + // `RingLogger::enabled` is unconditionally `true` and the app + // installs at `LevelFilter::Debug` -- two of these a rendered + // frame filled the 2000-line ring in under ten seconds at 120Hz, + // leaving `Copy report` nothing but frame spam. See + // `iris::diagnostics`'s module doc. + if crate::diagnostics::trace_enabled() { + let ui_state = self.state.android_state(); + log::debug!( + target: "iris::frame", + "render(): root={:?} widgets={} active={} root_px={:?} out_size={:?}", + ui_state.root.is_some(), + self.rsc.widgets().len(), + self.render.active_widgets(), + ui_state + .root + .as_ref() + .and_then(|r| self.render.window_region(r, &self.rsc)), + self.window_size(), + ); + } // iris's own frame-time report (RUST.md's I5 box, "Measurements // taken" (b)): started here, at the same point a redraw request // fires, and stopped after `renderer.draw()`'s `queue.submit` + @@ -498,21 +515,25 @@ impl IrisViewPeer { .android_state_mut() .frame_report .record_split(frame_start.elapsed(), submit_to_present); + crate::diagnostics::log_frame(&self.render, frame_start, submit_to_present, animating); // A frame callback is one-shot, so an animation that wants // another frame has to say so every frame -- unlike `after_input`, // which only has to ask when input dirtied something. if animating { ctx.view.post_frame_callback(&mut ctx.env); } - let ui_state = self.state.android_state(); - log::debug!( - "render(): after update active={} root_px={:?}", - self.render.active_widgets(), - ui_state - .root - .as_ref() - .and_then(|r| self.render.window_region(r, &self.rsc)), - ); + if crate::diagnostics::trace_enabled() { + let ui_state = self.state.android_state(); + log::debug!( + target: "iris::frame", + "render(): after update active={} root_px={:?}", + self.render.active_widgets(), + ui_state + .root + .as_ref() + .and_then(|r| self.render.window_region(r, &self.rsc)), + ); + } // I4 (RUST.md): only produces a `TreeUpdate` -- and so only queues // anything to raise -- when the named set actually changed this @@ -629,6 +650,15 @@ impl ViewPeer for IrisViewPeer { let at = |sample_time: jlong| { anchor_at + Duration::from_nanos(sample_time.saturating_sub(anchor_nanos).max(0) as u64) }; + // `iris::input`'s own doc (`sense::log_input_event`): collected + // only when tracing is on, since this is otherwise a `Vec` per + // `MotionEvent` for a line nobody is reading -- the JNI reads + // themselves (`historical_axis`/`historical_event_time_nanos` + // below) already happen unconditionally, for the replay this + // function does regardless of tracing. + let trace_input = crate::diagnostics::trace_enabled(); + let mut historical_ms: Vec<(u64, f32, f32)> = Vec::new(); + let ms_since_anchor = |t: jlong| (t.saturating_sub(anchor_nanos).max(0) as u64) / 1_000_000; // **Historical samples first.** A flick on a 120Hz screen is // delivered as one or two `MotionEvent`s with the intermediate @@ -659,6 +689,9 @@ impl ViewPeer for IrisViewPeer { sample ahead of it -- the input clock is not what this assumes" ); previous = ht; + if trace_input { + historical_ms.push((ms_since_anchor(ht), hx, hy)); + } let ui_state = self.state.android_state_mut(); ui_state.cursor.pos = vec2(hx, hy); ui_state.cursor.time = at(ht); @@ -695,6 +728,22 @@ impl ViewPeer for IrisViewPeer { } _ => return false, } + if trace_input { + let action_word = match action { + MotionAction::Down => "down", + MotionAction::Move => "move", + MotionAction::Up => "up", + MotionAction::Cancel => "cancel", + _ => "other", + }; + crate::sense::log_input_event( + action_word, + x, + y, + ms_since_anchor(event_time), + &historical_ms, + ); + } self.after_input(ctx); true } diff --git a/iris/src/default/mod.rs b/iris/src/default/mod.rs index 5b62373..f781bc9 100644 --- a/iris/src/default/mod.rs +++ b/iris/src/default/mod.rs @@ -294,6 +294,31 @@ impl AppState for DefaultApp { ui_state.focus = None; } if input_changed { + // The winit half of `iris::input` (`sense::log_input_event`'s + // own doc): no batching here, so `historical` is always empty + // -- winit hands one `WindowEvent` per pointer sample, unlike + // Android's `MotionEvent`. The action is read back off the + // buttons `Input::event` just updated, the same test + // `GestureOutcome`'s callers already use to tell a press from a + // release. Computed only when tracing is on, same reasoning as + // `log_input_event` itself gating on it. + if crate::diagnostics::trace_enabled() { + let action = if cursor_state.buttons.left.is_start() { + "down" + } else if cursor_state.buttons.left.is_end() { + "up" + } else { + "move" + }; + let t_ms = cursor_state.time.duration_since(render.epoch()).as_millis() as u64; + crate::sense::log_input_event( + action, + cursor_state.pos.x, + cursor_state.pos.y, + t_ms, + &[], + ); + } let window_size = ui_state.window_size(); render.run_sensors(rsc, state, cursor_state, window_size); } @@ -313,11 +338,14 @@ impl AppState for DefaultApp { // `IrisViewPeer::render`'s `post_frame_callback` does on // Android. Nothing else in iris moves without an input // event. - let animating = rsc.ui_mut().tick_animations(std::time::Instant::now()); + let frame_start = std::time::Instant::now(); + let animating = rsc.ui_mut().tick_animations(frame_start); let ui_state = state.default_state_mut(); render.update(&ui_state.root, rsc); ui_state.renderer.update(&mut rsc.ui, render); + let draw_start = std::time::Instant::now(); ui_state.renderer.draw(); + crate::diagnostics::log_frame(render, frame_start, draw_start.elapsed(), animating); if animating { ui_state.window.request_redraw(); } diff --git a/iris/src/diagnostics.rs b/iris/src/diagnostics.rs new file mode 100644 index 0000000..d114587 --- /dev/null +++ b/iris/src/diagnostics.rs @@ -0,0 +1,83 @@ +//! The trace toggle for the `iris::input`/`iris::frame` diagnostics (Iris's +//! 2026-09-07 request: "add another button to copy input event info ... +//! instrument a lot of the code with timings"), and the one place both +//! call sites' `iris::frame` line is written from. +//! +//! **Why a crate-level flag instead of `log::log_enabled!`/ +//! `log::set_max_level`**: the app already installs its logger at +//! `LevelFilter::Debug` (`iris/android-app/src/lib.rs`'s `JNI_OnLoad`), so +//! a `log::Level::Debug` line reaches `client_core::log_ring`'s ring +//! regardless of what this instrument would prefer -- `RingLogger::enabled` +//! is unconditionally `true` by design (its own doc: "the ring wants +//! everything"). So the level alone cannot give these two targets a +//! default-off switch; the gate has to live on this side, checked before +//! `log::debug!` is even reached. +//! +//! **Why default off matters**: the ring is 2000 lines / 256 KiB +//! (`client_core::log_ring::DEFAULT_MAX_LINES`/`DEFAULT_MAX_BYTES`), and a +//! 120Hz session logging both a line per touch sample and a line per frame +//! fills that in seconds -- so a caller turns this on only for the length +//! of whatever is being investigated, and the report says so at its top +//! (a caller's job; see `iris::diagnostics::trace_enabled` used at the top +//! of whatever builds the report). +//! +//! **Not yet wired to a control**: the Diagnostics pane that would hold the +//! switch is in `iris/android-app/src/bench_client.rs`, which another agent +//! has open at the same time this was written. `set_trace` is the whole +//! surface a button needs; wiring one is a follow-up. +use std::sync::atomic::{AtomicBool, Ordering}; +use std::time::{Duration, Instant}; + +use iris_core::UiRenderState; + +static TRACE: AtomicBool = AtomicBool::new(false); + +/// Turns the `iris::input`/`iris::frame` `debug!` lines on or off. Off by +/// default -- see the module doc for why turning the level on alone would +/// not do it. +pub fn set_trace(on: bool) { + TRACE.store(on, Ordering::Relaxed); +} + +/// Whether the `iris::input`/`iris::frame` lines are enabled right now -- +/// what a report's header reads before deciding what to say about the +/// lines it does or doesn't hold (UI_RULES.md: "design the unknown state +/// first"). +pub fn trace_enabled() -> bool { + TRACE.load(Ordering::Relaxed) +} + +/// One `iris::frame` line, called once per frame from each backend's own +/// frame function -- `android::view::IrisViewPeer::render`, +/// `default::DefaultApp::window_event`'s `RedrawRequested` arm, and +/// `harness::Harness::frame` -- after the draw (or, on the harness, where a +/// draw would be; `draw` is `Duration::ZERO` there since nothing is +/// actually submitted to a GPU). +/// +/// `render.update(...)` must already have run this frame: this reads back +/// what it recorded (`UiRenderState::last_layout_duration`/ +/// `last_redraw_kind`/`frame_number`) rather than timing anything itself, +/// so a caller's own measurement of the phase around `update()` and around +/// its own draw call are the only two `Instant` pairs in the whole path -- +/// see each call site's own comment for why it is not restructured to fit +/// this instead. +pub fn log_frame(render: &UiRenderState, now: Instant, draw: Duration, animating: bool) { + if !trace_enabled() { + return; + } + let since_input = render + .time_since_input(now) + .map(|d| format!("{}ms", d.as_millis())) + .unwrap_or_else(|| "none".to_string()); + log::debug!( + target: "iris::frame", + "iris frame: n={} now={}ms since_input={since_input} layout={:?} draw={:?} \ + redraw={:?} primitives={} animating={animating}", + render.frame_number(), + now.duration_since(render.epoch()).as_millis(), + render.last_layout_duration(), + draw, + render.last_redraw_kind(), + render.active_primitive_count(), + ); +} diff --git a/iris/src/harness.rs b/iris/src/harness.rs index 9b05871..dd3fe14 100644 --- a/iris/src/harness.rs +++ b/iris/src/harness.rs @@ -58,6 +58,18 @@ impl TouchAction { _ => None, } } + + /// The inverse of [`Self::parse`] -- what [`Harness::touch`] hands + /// [`crate::sense::log_input_event`], so an `iris::input` line and a + /// `.touch` file agree on one spelling of each action. + pub fn word(self) -> &'static str { + match self { + Self::Down => "down", + Self::Move => "move", + Self::Up => "up", + Self::Cancel => "cancel", + } + } } #[derive(Clone, Copy, Debug)] @@ -345,8 +357,14 @@ impl Harness { update(&mut self.state, &mut self.rsc); } let now = self.at(t_ms); - self.rsc.ui.tick_animations(now); + let animating = self.rsc.ui.tick_animations(now); self.render.update(&self.state.root, &mut self.rsc); + // No GPU here, so there is no draw phase to time -- `draw` is + // always zero. `layout`/`redraw`/`primitives` are still real, + // because `render.update` just ran; see + // `iris::diagnostics::log_frame`'s own doc for why this reads + // those back rather than timing anything itself. + crate::diagnostics::log_frame(&self.render, now, Duration::ZERO, animating); } /// Frames every `step_ms` up to and including `end_ms` -- what a @@ -377,6 +395,12 @@ impl Harness { TouchAction::Move => {} TouchAction::Up | TouchAction::Cancel => self.cursor.buttons.left.update(false), } + // Layer 1's half of `iris::input` (`sense::log_input_event`'s own + // doc): no batching happens here, so `historical` is always empty + // and `t_ms` is the script's own column, which is what makes this + // round-trip through `report_to_touch.py` back into an identical + // `TouchScript`. + crate::sense::log_input_event(action.word(), pos.x, pos.y, t_ms, &[]); let cursor = self.cursor.clone(); self.render .run_sensors(&mut self.rsc, &mut self.state, cursor, self.size); diff --git a/iris/src/lib.rs b/iris/src/lib.rs index 1473f70..37eb711 100644 --- a/iris/src/lib.rs +++ b/iris/src/lib.rs @@ -20,6 +20,7 @@ pub mod android; pub mod default; pub mod attr; +pub mod diagnostics; pub mod event; pub mod harness; pub mod platform; diff --git a/iris/src/sense.rs b/iris/src/sense.rs index f690812..8fa572f 100644 --- a/iris/src/sense.rs +++ b/iris/src/sense.rs @@ -227,6 +227,11 @@ impl SensorUi for UiRenderState { cursor: CursorState, window_size: Vec2, ) { + // `iris::frame`'s `since_input` (`iris::diagnostics::log_frame`) + // reads this back -- every backend's sensor dispatch reaches here, + // so recording it once in the one place they share is what keeps + // it from needing a copy per backend. + self.note_input(cursor.time); // Exclusive pointer capture (`UiRenderState::capture_pointer`, // `DragGesture`): once some widget has committed to a drag, every // other widget sees nothing from this pointer at all -- no hover, @@ -461,6 +466,45 @@ impl BitOr for CursorSenses { } } +/// One `iris::input` line for a single platform input sample -- called +/// once per platform event: `android::view::IrisViewPeer::on_touch_event` +/// once per real `MotionEvent` (`historical` carrying whatever samples it +/// batched, oldest first, exactly as Android delivers and replays them); +/// the winit backend once per pointer `WindowEvent`, always with an empty +/// `historical` since winit does not batch; and `harness::Harness::touch` +/// once per `TouchScript` line, also with an empty `historical`, which is +/// what makes a harness-produced report round-trip through +/// `iris/benches/report_to_touch.py` back into the exact script that was +/// replayed (docs/RUST.md's "Three test layers" / phone logging sections). +/// +/// `action` is one of the four words [`crate::harness::TouchScript::parse`] +/// accepts (`"down"`/`"move"`/`"up"`/`"cancel"`), so the same string is +/// both what a real device's `MotionAction` is translated to and what the +/// parser reads back -- one vocabulary rather than two that have to be +/// kept in step by hand. `t_ms`/`historical`'s own times are whatever the +/// caller's own clock calls "the start of this recording" -- the harness's +/// own `t_ms`, or nanoseconds since `IrisViewPeer`'s `input_clock` anchor +/// converted to ms -- so they are comparable to a `.touch` file's own +/// column but not to another process's. +/// +/// Gated on [`crate::diagnostics::trace_enabled`] rather than +/// `log::log_enabled!` -- see that module's doc for why the level alone +/// cannot give this a default-off switch. +pub fn log_input_event(action: &str, x: f32, y: f32, t_ms: u64, historical: &[(u64, f32, f32)]) { + if !crate::diagnostics::trace_enabled() { + return; + } + let mut hist = String::new(); + for (t, hx, hy) in historical { + hist.push_str(&format!(" {t}:{hx:.1},{hy:.1}")); + } + log::debug!( + target: "iris::input", + "iris input: action={action} x={x:.1} y={y:.1} t={t_ms}ms history={}{hist}", + historical.len(), + ); +} + /// How long a stationary press has to be held before it is treated as a /// long-press rather than the start of a pan. pub const LONG_PRESS: Duration = Duration::from_millis(500); @@ -603,10 +647,23 @@ impl DragArbiter { if already_selected && across.abs() > DRAG_SLOP && across.abs() > along.abs() { self.state = ArbiterState::Selecting; self.last = pos; + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::input", + "iris gesture: select extend (early, already selected) across={across:.1}" + ); + } DragOutcome::SelectExtend } else if along.abs() > DRAG_SLOP && along.abs() >= across.abs() { self.state = ArbiterState::Panning; self.last = pos; + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::input", + "iris gesture: drag start axis={:?} along={along:.1}", + self.axis, + ); + } // `along` here is the *whole* drag since `press_start`, // not since the last frame -- nothing panned while // `Undecided` was withholding the slop, so applying it @@ -632,6 +689,9 @@ impl DragArbiter { { self.state = ArbiterState::Selecting; self.last = pos; + if crate::diagnostics::trace_enabled() { + log::debug!(target: "iris::input", "iris gesture: long press"); + } DragOutcome::SelectStart } else { DragOutcome::Undecided @@ -777,6 +837,13 @@ impl DragGesture { self.velocity .add_position(pos_window.axis(self.arbiter.axis()), now); self.arbiter.press_start(pos_window, now, already_selected); + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::input", + "iris gesture: press start pos=({:.1},{:.1})", + pos_window.x, pos_window.y, + ); + } self.dispatch(render, id, pos_window, now) } CursorSense::Drop | CursorSense::PressEnd(_) => { @@ -806,11 +873,16 @@ impl DragGesture { // paste them into a `touch/*.touch` recording or straight // into `iris/benches/velocity_reference.py`. Debug rather // than info because it is one line per gesture and the - // ring the report copies is small. - log::debug!( - "iris drag release samples: {}", - self.velocity.samples_display() - ); + // ring the report copies is small -- but "small" is still + // not "free" (docs/RUST.md's review, D1), so it is gated + // the same way every other `debug!` in this pass is. + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::input", + "iris drag release samples: {}", + self.velocity.samples_display() + ); + } self.arbiter.release(); render.release_pointer(); outcome @@ -823,6 +895,13 @@ impl DragGesture { self.velocity .add_position(pos_window.axis(self.arbiter.axis()), now); self.arbiter.press_start(pos_window, now, already_selected); + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::input", + "iris gesture: press start (recovered, no PressStart seen) pos=({:.1},{:.1})", + pos_window.x, pos_window.y, + ); + } self.dispatch(render, id, pos_window, now) } _ => self.dispatch(render, id, pos_window, now), diff --git a/iris/src/widget/list.rs b/iris/src/widget/list.rs index fe6528c..5dfa71a 100644 --- a/iris/src/widget/list.rs +++ b/iris/src/widget/list.rs @@ -572,14 +572,22 @@ impl List { // observable nor observed while `distance_fraction` returned `t` // (`android_fling_spline`'s doc), which is why this is here rather // than the total-travel line the release log already carries. - log::debug!( - "iris fling tick: t={:.3}s dy={:+.1}px speed={:.0}px/s of {:.0} left={:.1}px", - elapsed.as_secs_f32(), - delta, - f.calc.velocity_at(velocity, elapsed), - velocity, - f.calc.distance(velocity) - target, - ); + // Gated on `iris::diagnostics::trace_enabled` since 2026-09-07 + // (docs/RUST.md's review, D1): one line per fling *tick*, + // unconditional, was enough on its own to help fill the log + // ring -- see `android::view::IrisViewPeer::render`'s own doc for + // the same finding on its two per-frame lines. + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::frame", + "iris fling tick: t={:.3}s dy={:+.1}px speed={:.0}px/s of {:.0} left={:.1}px", + elapsed.as_secs_f32(), + delta, + f.calc.velocity_at(velocity, elapsed), + velocity, + f.calc.distance(velocity) - target, + ); + } self.scroll(delta); // Clamp: a fling moving toward the start that has already reached diff --git a/iris/src/widget/text/mod.rs b/iris/src/widget/text/mod.rs index cc9268d..03b3068 100644 --- a/iris/src/widget/text/mod.rs +++ b/iris/src/widget/text/mod.rs @@ -78,12 +78,20 @@ impl TextView { } self.width = width; let tex = painter.render_text(&mut self.buf, &self.attrs, width); - log::debug!( - "iris text render: chars={} width={width:?} glyphs={} size={:?}", - self.buf.text().chars().count(), - tex.glyphs.len(), - tex.size, - ); + // Gated on `iris::diagnostics::trace_enabled` since 2026-09-07 + // (docs/RUST.md's review, D1): one line per text *shape* (a cache + // miss), unconditional, is many per frame while rows compose -- + // see `android::view::IrisViewPeer::render`'s own doc for the same + // finding on its two per-frame lines. + if crate::diagnostics::trace_enabled() { + log::debug!( + target: "iris::frame", + "iris text render: chars={} width={width:?} glyphs={} size={:?}", + self.buf.text().chars().count(), + tex.glyphs.len(), + tex.size, + ); + } self.tex = Some(tex.clone()); self.attrs.changed = false; self.buf.changed = false; diff --git a/iris/transcript-fixture/Cargo.toml b/iris/transcript-fixture/Cargo.toml index 236c4e9..8609ad4 100644 --- a/iris/transcript-fixture/Cargo.toml +++ b/iris/transcript-fixture/Cargo.toml @@ -22,3 +22,7 @@ serde_json = { version = "1", features = ["float_roundtrip"] } [dev-dependencies] winit = { workspace = true } +# For the `iris::input`/`iris::frame` round-trip test: a capturing `log::Log` +# to read back what `iris::diagnostics::log_frame`/`sense::log_input_event` +# wrote, pinned to the same version `iris/Cargo.toml` already carries. +log = "0.4.28" diff --git a/iris/transcript-fixture/tests/input_log_roundtrip.rs b/iris/transcript-fixture/tests/input_log_roundtrip.rs new file mode 100644 index 0000000..14c3b8e --- /dev/null +++ b/iris/transcript-fixture/tests/input_log_roundtrip.rs @@ -0,0 +1,189 @@ +//! Layer 1 of docs/RUST.md's "Three test layers", for the diagnostics +//! themselves rather than a widget: `iris::diagnostics::set_trace` gates +//! `iris::input`/`iris::frame` (Iris's 2026-09-07 request, "add another +//! button to copy input event info ... instrument a lot of the code with +//! timings"), and `docs/REVIEW-2026-09-07.md`'s D1 found that the switch +//! existed but four older per-frame `debug!` lines were not wired to it, +//! filling the app's 2000-line log ring with frame spam before `Copy +//! report` had a chance to include anything else. This is what a fix to +//! that has to prove, both directions: +//! +//! 1. **Off** (the default): replaying a real gesture through a real +//! screen leaves the ring holding nothing below `info` -- so the +//! lines D1 named, and everything this pass gated the same way, really +//! are silent by default rather than merely "usually quiet." +//! 2. **On**: the same replay produces `iris::input` lines that +//! `report_to_touch.py` turns back into the exact `TouchScript` that +//! was replayed, and `iris::frame` lines with real, non-zero +//! durations dated on the harness's own clock. +//! +//! **Single capturing logger, single test function** (this file's only +//! `#[test]`): `log::set_logger` can succeed exactly once per process, and +//! AGENTS.md's "tracing caches callsite interest process-wide" lesson is +//! the general form of why every exercise of a logging path has to share +//! one subscriber -- so if a second test here ever needs the ring's +//! contents, it must extend this one rather than install its own. + +use std::process::{Command, Stdio}; +use std::sync::{Mutex, OnceLock}; + +use iris::harness::{Harness, TouchScript}; +use transcript_fixture::{PHONE_FRAME_MS, PHONE_SCALE, phone_size}; + +/// Records every line's level and formatted message -- enough to answer +/// both "is the ring quiet" (no line at `Debug` or below) and "what did +/// tracing actually write" (the `iris::input` lines, read back by +/// `report_to_touch.py`). +struct CaptureLogger { + lines: Mutex>, +} + +static LOGGER: OnceLock = OnceLock::new(); + +impl log::Log for CaptureLogger { + fn enabled(&self, _metadata: &log::Metadata) -> bool { + true + } + fn log(&self, record: &log::Record) { + self.lines + .lock() + .unwrap() + .push((record.level(), record.args().to_string())); + } + fn flush(&self) {} +} + +/// Installs the capture logger at `Debug` -- the same level +/// `iris/android-app/src/lib.rs`'s `JNI_OnLoad` installs at, which is +/// exactly why `iris::diagnostics::trace_enabled` has to be the gate +/// (its own module doc) rather than the level. +fn logger() -> &'static CaptureLogger { + let logger = LOGGER.get_or_init(|| CaptureLogger { + lines: Mutex::new(Vec::new()), + }); + // Ignore "already set": a previous call in this same test binary + // already won, and it is the same logger either way. + let _ = log::set_logger(logger); + log::set_max_level(log::LevelFilter::Debug); + logger +} + +fn drain(logger: &CaptureLogger) -> Vec<(log::Level, String)> { + std::mem::take(&mut *logger.lines.lock().unwrap()) +} + +fn opened() -> (Harness, transcript_ui::TranscriptScreen) { + let mut h = Harness::new(phone_size(), PHONE_SCALE); + let opened = transcript_fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds"); + h.frame(0); + h.frame(PHONE_FRAME_MS); + (h, opened.screen) +} + +#[test] +fn tracing_is_silent_off_and_round_trips_the_flick_on() { + let logger = logger(); + + // --- (1) off: a real flick through a real screen leaves the ring + // with nothing at `Debug` or below. + iris::diagnostics::set_trace(false); + drain(logger); // whatever `opened()` itself logged while building + let (mut h, screen) = opened(); + drain(logger); // and whatever opening logged + let flick = TouchScript::parse(include_str!("../touch/flick-120hz.touch")) + .unwrap_or_else(|e| panic!("flick-120hz.touch: {e}")); + h.replay(&flick); + let _ = (screen.list)(&mut h.rsc); // touch the screen the same way a real caller would + let quiet = drain(logger); + let debug_lines: Vec<_> = quiet + .iter() + .filter(|(level, _)| *level == log::Level::Debug) + .collect(); + assert!( + debug_lines.is_empty(), + "tracing is off, but the ring would still have held these `debug!` lines: {debug_lines:#?}" + ); + + // --- (2) on: the same replay, from a fresh screen so the anchor and + // sequence numbers match `flick-120hz.touch` exactly again. + iris::diagnostics::set_trace(true); + let (mut h, screen) = opened(); + drain(logger); + h.replay(&flick); + let _ = (screen.list)(&mut h.rsc); + let traced = drain(logger); + iris::diagnostics::set_trace(false); // leave it off for any test after this one + + let input_lines: Vec<&str> = traced + .iter() + .filter(|(_, msg)| msg.contains("iris input: action=")) + .map(|(_, msg)| msg.as_str()) + .collect(); + assert_eq!( + input_lines.len(), + flick.samples.len(), + "expected one `iris::input` line per replayed sample, got:\n{input_lines:#?}" + ); + let frame_lines: Vec<&str> = traced + .iter() + .filter(|(_, msg)| msg.starts_with("iris frame:")) + .map(|(_, msg)| msg.as_str()) + .collect(); + assert!( + !frame_lines.is_empty(), + "expected at least one `iris::frame` line once tracing was on" + ); + for line in &frame_lines { + // `layout=` and `draw=` are `{:?}`-formatted `Duration`s, so a real + // one reads like `12.34µs`/`1.2ms`, never the bare `0ns` a + // no-op frame would print. + assert!( + !line.contains("layout=0ns"), + "a frame that redrew should not report zero layout time: {line}" + ); + } + + // --- the round trip: pipe every `iris::input` line through + // `report_to_touch.py` and parse the result back into a `TouchScript`, + // which must equal the one that was replayed. `report_to_touch.py` + // is prefix-agnostic (it `search`es for the marker), so handing it + // the bare message is the same as handing it a real ring line. + let report = input_lines.join("\n"); + let script_path = concat!(env!("CARGO_MANIFEST_DIR"), "/../benches/report_to_touch.py"); + let mut child = Command::new("python3") + .arg(script_path) + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .expect("python3 must be on PATH to run report_to_touch.py"); + { + use std::io::Write; + child + .stdin + .take() + .unwrap() + .write_all(report.as_bytes()) + .unwrap(); + } + let output = child.wait_with_output().expect("report_to_touch.py exited"); + assert!( + output.status.success(), + "report_to_touch.py failed: {}", + String::from_utf8_lossy(&output.stderr) + ); + let touch_text = String::from_utf8(output.stdout).expect("report_to_touch.py wrote UTF-8"); + let round_tripped = + TouchScript::parse(&touch_text).unwrap_or_else(|e| panic!("round-tripped script: {e}")); + + assert_eq!( + round_tripped.samples.len(), + flick.samples.len(), + "round trip produced a different number of samples:\n{touch_text}" + ); + for (original, back) in flick.samples.iter().zip(round_tripped.samples.iter()) { + assert_eq!(original.t_ms, back.t_ms); + assert_eq!(original.action, back.action); + assert_eq!(original.pos, back.pos); + } +}