iris/ai-app
1
0 Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

iris: iris::input/iris::frame diagnostics, and gating the four debug! lines that already drowned the ring

Browse Source 
Iris asked for a button to copy raw input events and per-frame timings
through the same report Copy report already produces. sense::log_input_event
(one line per platform pointer sample, historical samples inline on
Android) and diagnostics::log_frame (one line per frame: frame number,
frame clock, time since last input, layout/draw durations, redraw kind,
primitives on screen, animating) both land under iris::diagnostics's
trace_enabled() gate, off by default since the ring is 2000 lines/256KiB
and either target at 120Hz fills it in seconds. report_to_touch.py turns
a report's iris::input lines back into a .touch file for harness/desktop
replay, round-tripped in transcript-fixture's input_log_roundtrip test.

Folds in docs/REVIEW-2026-09-07.md's D1: four older per-frame debug!
lines (android::view's two render() lines, list.rs's fling tick,
text/mod.rs's text render) were unconditional at Debug and, with the
ring's RingLogger recording everything the app's Debug install lets
through regardless of target, filled it before Copy report ever saw
anything else. All four (and sense.rs's drag-release-samples line) are
now behind the same gate. The same test proves both directions: tracing
off leaves zero Debug lines from a replayed flick, tracing on produces
the expected iris::input/iris::frame lines with real durations.

Not wired to a Diagnostics-pane button: bench_client.rs is open under
another agent. set_trace(bool) is the whole surface a control needs.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
irisandClaude Fable 5.1 committed 2026-09-07 16:48:48 -04:00
1 parent 729098756d
commit 992c472975
16 files changed
+871 -18
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

docs/IRIS.md
+43
View File
@@ -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<Duration>`** (`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,
docs/IRIS_TODO.md
+21 -11
View File
@@ -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.
docs/RUST.md
+118
View File
@@ -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
iris/benches/report_to_touch.py
Executable
+96
View File
@@ -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 `[<source> <clock> #<seq>]` 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<action>\w+) x=(?P<x>-?[0-9.]+) y=(?P<y>-?[0-9.]+) "
r"t=(?P<t>[0-9]+)ms history=(?P<hist>[0-9]+)(?P<rest>.*)$"
)
# 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<t>[0-9]+):(?P<x>-?[0-9.]+),(?P<y>-?[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())
iris/core/src/orientation/axis.rs
+1 -1
View File
@@ -1,6 +1,6 @@
use super::*;
#[derive(Copy, Clone, Eq, PartialEq)]
#[derive(Copy, Clone, Eq, PartialEq, Debug)]
pub enum Axis {
X,
Y,
iris/core/src/ui/render_state.rs
+115 -2
View File
@@ -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<WidgetId, ActiveData>,
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<Option<Instant>>,
}
/// 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<Duration> {
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
iris/src/android/view.rs
+50 -1
View File
@@ -406,7 +406,13 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
/// 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,8 +447,18 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
self.state.on_insets_changed(&mut self.rsc, physical);
}
// 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(),
@@ -453,6 +469,7 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
.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,14 +515,17 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
.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);
}
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
@@ -513,6 +533,7 @@ impl<State: AndroidAppState> IrisViewPeer<State> {
.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<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
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<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
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<State: AndroidAppState> ViewPeer for IrisViewPeer<State> {
}
_ => 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
}
iris/src/default/mod.rs
+29 -1
View File
@@ -294,6 +294,31 @@ impl<State: DefaultAppState> AppState for DefaultApp<State> {
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<State: DefaultAppState> AppState for DefaultApp<State> {
// `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();
}
iris/src/diagnostics.rs
+83
View File
@@ -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(),
);
}
iris/src/harness.rs
+25 -1
View File
@@ -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);
iris/src/lib.rs
+1
View File
@@ -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;
iris/src/sense.rs
+80 -1
View File
@@ -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<CursorSense> 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.
// 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),
iris/src/widget/list.rs
+8
View File
@@ -572,7 +572,14 @@ 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.
// 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,
@@ -580,6 +587,7 @@ impl List {
velocity,
f.calc.distance(velocity) - target,
);
}
self.scroll(delta);
// Clamp: a fling moving toward the start that has already reached
iris/src/widget/text/mod.rs
+8
View File
@@ -78,12 +78,20 @@ impl TextView {
}
self.width = width;
let tex = painter.render_text(&mut self.buf, &self.attrs, width);
// 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;
iris/transcript-fixture/Cargo.toml
+4
View File
@@ -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"
iris/transcript-fixture/tests/input_log_roundtrip.rs
+189
View File
@@ -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<Vec<(log::Level, String)>>,
}
static LOGGER: OnceLock<CaptureLogger> = 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);
}
}