diff --git a/doc/architecture.md b/doc/architecture.md index b45ebc3..8c6c032 100644 --- a/doc/architecture.md +++ b/doc/architecture.md @@ -543,17 +543,42 @@ cannot measure this app because it renders into a `SurfaceView`). `/storage/emulated/0/PadPerf/enable` before launch. `main.go` then creates a `perf.Profiler` that writes `logic_frames.csv` (one row per logic frame: seq, ms-since-start, frame delta, page, scroll Dp, max-scroll Dp, total lines, - visible byte range) and logs a rolling ~1 s `PERF` summary. `DestroyEvent` - stops it (final flush + `PERF stopped` summary with p50/p90/p99/max). + visible byte range, gap flag) and logs a rolling ~1 s `PERF` summary. + `DestroyEvent` stops it (final flush + `PERF stopped` summary with + p50/p90/p99/max). +- **Gap handling**: a row whose previous frame is ≥ 100 ms away is an idle + gap, not a slow frame (the first frame of a burst would otherwise carry the + whole idle period in its delta). Gap rows are flagged in the CSV, kept out + of the summary's latency percentiles, and reported separately + (`gaps=N maxGap=…ms`). A frame that arrives ≥ 2 s after the previous one + also flushes the CSV immediately: the frame that opens a new burst is the + moment the previous burst's rows become final, so an idle tail (or a + force-stopped app) does not lose the last burst. +- **Main-side presents**: `main.go` separately counts `app.FrameEvent`s and + logs a rolling `PERF-PRESENT frames=N fps=F` line; fps ≫ 1 while idle means + something is invalidating the window continuously. - **Hook**: `internal/editor.PerfRecord` is a package-level func, set by `main.go` only when enabled. `Logic.emitFrame` calls it on the owner goroutine with a `ProbeRecord` **before** sending the frame. When disabled it is `nil` and the per-frame cost is a single nil check. -- **Debug scroll jumps** (for testing, off by default): with the profiler on, +- **Debug commands** (for testing, off by default): with the profiler on, `main.go` also polls `/storage/emulated/0/PadPerf/cmd` (a one-shot file - consumed on read). `top`, `bottom`, `frac <0..1>`, and `dp ` jump the - editor's `ScrollOffset` (clamped to `[0, MaxScroll]`) and emit a frame. This - lets a test drive large-offset scrolls deterministically without pixel taps. + consumed on read; `Logic.applyDebugCmd`). `top`, `bottom`, `frac <0..1>`, + and `dp ` jump the editor's `ScrollOffset` (clamped to + `[0, MaxScroll]`) and emit a frame; `open ` opens a file from any + page (same `OpenFile` path as a browser tap) and emits. This lets a test + drive scrolls and file opens deterministically without pixel taps. +- **Frame-regression guard** (pre-release): frame emission is event-driven, so + a healthy app emits small per-action bursts and nothing while idle. Two + layers check that: `TestNoFramesWhileIdle` (internal/test/e2e, in the + regular go-test suite) asserts the logic emits ZERO frames across an idle + window after the browser and the editor (load + scroll + find cycle) + settle; and `scripts/profile_emulator.sh` runs the full sequence on a + device/emulator — 8 s idle, open, 16 s idle, three scrolls — via the debug + commands above, seeds a known 4000-line file for the open, and FAILs if any + idle-split phase of the CSV exceeds its frame budget (a ≥ 1/s spinner + exceeds a 16 s idle budget; a faster one balloons a phase or shows up in + PERF-PRESENT). - The profiler is owned by the goroutine that creates it and is single-goroutine (no locks). It does **not** `Sync()` the CSV per flush (only per row batch) to avoid periodic fsync hitches in the logic path. @@ -561,3 +586,8 @@ cannot measure this app because it renders into a `SurfaceView`). across scroll offsets 0.02→1.0 (no large-offset degradation); the visible byte range stays ≤ ~4.3 KB (0.04% of the file); PSS plateaus ~250 MB (bounded high-water mark, no leak). See `development_plan.md` Phase 6. +- **Measured** (emulator, 4000-line file, 2026-08): the pre-release profile + passes with 5 phases — browser startup 5–6 frames, open 5–6, and 1–2 per + scroll — and ZERO frames across all idle windows (PERF-PRESENT fps < 1 + throughout); an injected 500 ms frame spinner makes the script FAIL + (phase 1 = 69 frames vs budget 10, PERF-PRESENT fps ≈ 2.4). diff --git a/internal/editor/logic.go b/internal/editor/logic.go index ad9b3e3..beb554a 100644 --- a/internal/editor/logic.go +++ b/internal/editor/logic.go @@ -358,7 +358,8 @@ func (l *Logic) emitFrame() { } // EnableDebugCmdPoll starts a background poller (debug-only) that watches -// /cmd for a one-shot scroll command and forwards it to the owner for +// /cmd for a one-shot debug command (see applyDebugCmd) and forwards +// it to the owner for // application. Used to jump the editor to specific scroll offsets for // performance/clamping validation. The poller does the (blocking) file read // off the owner and sends the command via debugCmdC; the owner applies it. @@ -396,18 +397,32 @@ func (l *Logic) EnableDebugCmdPoll(dir string) { } // applyDebugCmd applies a one-shot debug scroll command from the cmd-file -// poller. Commands: "top", "bottom", "frac <0..1>", "dp ". Must be -// called on the logic goroutine. +// poller. Commands: "open " (any page), and, on the editor page, +// "top", "bottom", "frac <0..1>", "dp ". Must be called on the logic +// goroutine. func (l *Logic) applyDebugCmd(cmd string) { s := l.state - if s.page != EditorPage { - log.Printf("DebugCmd: %q ignored (not on editor page)", cmd) - return - } fields := strings.Fields(cmd) if len(fields) == 0 { return } + // "open " works from any page: it opens the file and switches to + // the editor. The pre-release frame profile (scripts/profile_emulator.sh) + // uses it to open a known scrollable file deterministically instead of + // pixel-tapping the browser list. + if fields[0] == "open" { + if len(fields) < 2 { + log.Printf("DebugCmd: open needs a path") + return + } + OpenFile(fields[1]) + l.emitFrame() // OpenFile only mutates state (the tap path emits via its handler) + return + } + if s.page != EditorPage { + log.Printf("DebugCmd: %q ignored (not on editor page)", cmd) + return + } var target ui.Dp switch fields[0] { case "top": diff --git a/internal/perf/perf.go b/internal/perf/perf.go index 875074b..dcc832e 100644 --- a/internal/perf/perf.go +++ b/internal/perf/perf.go @@ -39,8 +39,16 @@ type Row struct { TotalLines int VisStart int VisEnd int + Gap bool // DeltaMs is an idle gap, not frame latency (see gapThreshold) } +// gapThreshold separates "the app was idle" from "a frame was slow": a +// gap of this length or more means no frames were emitted for that whole +// time, so the first frame of the next burst carries the entire idle period +// in DeltaMs. A genuinely slow frame on a real device is at most a few +// tens of ms. +const gapThreshold = 100 * time.Millisecond + // Profiler records logic-frame cadence plus context. All methods must be // called from the owning goroutine only (no locks). type Profiler struct { @@ -110,6 +118,7 @@ func (p *Profiler) Record(ctx Ctx) { TotalLines: ctx.TotalLines, VisStart: ctx.VisStart, VisEnd: ctx.VisEnd, + Gap: delta >= gapThreshold, }) if now.Sub(p.lastLog) >= time.Second { @@ -120,18 +129,40 @@ func (p *Profiler) Record(ctx Ctx) { p.flush() p.lastFlush = now } + // Burst ended: persist immediately. The periodic flush above only runs + // inside Record, so without this an idle tail (or a force-stopped app) + // would lose the last burst's rows; the frame that opens a new burst is + // the moment the previous burst's rows become final. + if delta >= 2*time.Second { + p.flush() + p.lastFlush = now + } } // logSummary prints a rolling percentile summary of the frames buffered since -// the last flush to logcat. +// the last flush to logcat. Idle gaps are kept OUT of the latency +// percentiles (they are pauses between bursts of activity, not slow frames) +// and reported separately. func (p *Profiler) logSummary() { n := len(p.buf) if n == 0 { return } - ds := make([]float64, n) - for i, r := range p.buf { - ds[i] = r.DeltaMs + gaps, maxGap := 0, 0.0 + ds := make([]float64, 0, n) + for _, r := range p.buf { + if r.Gap { + gaps++ + if r.DeltaMs > maxGap { + maxGap = r.DeltaMs + } + continue + } + ds = append(ds, r.DeltaMs) + } + if len(ds) == 0 { + log.Printf("PERF frames=%d (all idle gaps; max=%.0f ms)", n, maxGap) + return } p50, p90, p99, mx := percentiles(ds) over16, over33 := 0, 0 @@ -143,16 +174,16 @@ func (p *Profiler) logSummary() { over33++ } } - log.Printf("PERF frames=%d p50=%.1f p90=%.1f p99=%.1f max=%.1f ms over16.7=%.0f%% over33.4=%.0f%%", - n, p50, p90, p99, mx, pct(over16, n), pct(over33, n)) + log.Printf("PERF frames=%d p50=%.1f p90=%.1f p99=%.1f max=%.1f ms over16.7=%.0f%% over33.4=%.0f%% gaps=%d maxGap=%.0fms", + n, p50, p90, p99, mx, pct(over16, len(ds)), pct(over33, len(ds)), gaps, maxGap) } // flush appends the buffered rows to the CSV file and clears the buffer. func (p *Profiler) flush() { if len(p.buf) > 0 && p.file != nil { for _, r := range p.buf { - fmt.Fprintf(p.file, "%d,%.3f,%.3f,%s,%.1f,%.1f,%d,%d,%d\n", - r.Seq, r.Tms, r.DeltaMs, r.Page, r.ScrollDP, r.MaxScrollDP, r.TotalLines, r.VisStart, r.VisEnd) + fmt.Fprintf(p.file, "%d,%.3f,%.3f,%s,%.1f,%.1f,%d,%d,%d,%v\n", + r.Seq, r.Tms, r.DeltaMs, r.Page, r.ScrollDP, r.MaxScrollDP, r.TotalLines, r.VisStart, r.VisEnd, r.Gap) } } p.buf = p.buf[:0] diff --git a/internal/test/e2e/idle_frames_test.go b/internal/test/e2e/idle_frames_test.go new file mode 100644 index 0000000..9f0bd86 --- /dev/null +++ b/internal/test/e2e/idle_frames_test.go @@ -0,0 +1,111 @@ +package e2e_test + +import ( + "strings" + "testing" + "time" + + "pad/internal/editor" + "pad/internal/test/e2e" + "pad/internal/ui" +) + +// TestNoFramesWhileIdle is the pre-release frame-regression guard. Frame +// emission is event-driven (architecture.md §2): once the logic goroutine +// has settled — every async result applied, every wrap-settle pass done — +// it must emit ZERO further frames while no input arrives. A non-zero +// delta means something is spinning (a ticker, a re-emission loop, a +// feedback ping-pong between layout and state) and would burn CPU and +// battery on a real device for the app's entire idle lifetime. +// +// The main-loop side (Gio presents) is measured by the same contract's +// on-device instrument: PERF-PRESENT logcat lines (cmd/pad, enabled by +// touching /PadPerf/enable; see scripts/profile_emulator.sh). + +// waitFrameSettle returns the frame count once it has been unchanged for +// quietFor (the logic is quiescent). Fatals if it never settles. +func waitFrameSettle(t *testing.T, h *e2e.Harness, quietFor time.Duration) int { + t.Helper() + deadline := time.Now().Add(10 * time.Second) + last := h.FrameCount() + lastChanged := time.Now() + for time.Now().Before(deadline) { + time.Sleep(50 * time.Millisecond) + if n := h.FrameCount(); n != last { + last, lastChanged = n, time.Now() + continue + } + if time.Since(lastChanged) >= quietFor { + return last + } + } + t.Fatal("frame count never settled within 10s") + return 0 +} + +// assertIdleFrames requires the frame count to be unchanged across an +// idleFor window that follows a settled (quietFor-stable) state. +func assertIdleFrames(t *testing.T, h *e2e.Harness, quietFor, idleFor time.Duration, phase string) { + t.Helper() + before := waitFrameSettle(t, h, quietFor) + time.Sleep(idleFor) + if after := h.FrameCount(); after != before { + t.Fatalf("%s: logic emitted %d frame(s) while idle (before=%d after=%d); emission must be event-driven", + phase, after-before, before, after) + } +} + +// TestNoFramesWhileIdle_Browser: the file-browser page, fully loaded, must +// go completely quiet. +func TestNoFramesWhileIdle_Browser(t *testing.T) { + h := e2e.NewHarness() + h.Run() + defer h.Cleanup() + h.SendConfig(1080, 2400) + if _, err := h.WaitForFrameCount(1, 5*time.Second); err != nil { + t.Fatalf("no frames: %v", err) + } + assertIdleFrames(t, h, 300*time.Millisecond, time.Second, "browser") +} + +// TestNoFramesWhileIdle_Editor: an open file after a load, a scroll, and a +// full find cycle (scan + navigate + close) must go completely quiet — +// the find settle machinery in particular must terminate, not re-trigger. +func TestNoFramesWhileIdle_Editor(t *testing.T) { + // 300 long lines: enough to scroll and to match a query at several + // positions. + var sb strings.Builder + for i := 0; i < 300; i++ { + sb.WriteString("line number 000: the quick brown fox jumps over the lazy dog by the river\n") + } + h, _ := realFileHarness(t, "idle.txt", sb.String()) + defer h.Cleanup() + h.SendConfig(1080, 2400) + + // Scroll (HandleScroll swallows input for 300ms after open). + time.Sleep(400 * time.Millisecond) + h.SendInput([]ui.InputEvent{{Handler: editor.HandleScroll, Data: 2000}}) + + // A full find cycle: open the bar, query, navigate, close. + h.SendInput([]ui.InputEvent{{Handler: editor.ToggleFind, Data: nil}}) + h.Logic().FindQueryChan() <- "quick" + deadline := time.Now().Add(5 * time.Second) + for { + v, err := h.Inspect(func(st *editor.State) any { return len(st.Editor.Find.Matches) }) + if err != nil { + t.Fatalf("Inspect: %v", err) + } + if v.(int) > 0 { + break + } + if time.Now().After(deadline) { + t.Fatal("find never matched") + } + time.Sleep(20 * time.Millisecond) + } + h.SendInput([]ui.InputEvent{{Handler: editor.FindNext, Data: nil}}) + time.Sleep(100 * time.Millisecond) + h.SendInput([]ui.InputEvent{{Handler: editor.ToggleFind, Data: nil}}) + + assertIdleFrames(t, h, 300*time.Millisecond, time.Second, "editor") +} diff --git a/scripts/profile_emulator.sh b/scripts/profile_emulator.sh new file mode 100755 index 0000000..efd3e54 --- /dev/null +++ b/scripts/profile_emulator.sh @@ -0,0 +1,152 @@ +#!/usr/bin/env bash +# Pre-release frame-regression profile for the Pad editor. +# +# Measures whether the app generates frames WITHOUT a cause. Frame emission +# is event-driven (architecture.md §2), so a correct app emits a small +# number of frames per user action and NOTHING while idle. This script +# drives a fixed sequence of actions on a connected device/emulator and +# checks the in-app profiler's CSV for phases that exceed their frame +# budget. The headless contract of the same guard is +# TestNoFramesWhileIdle (internal/test/e2e), which runs in the regular +# go-test suite. +# +# Usage: +# scripts/profile_emulator.sh [-s SERIAL] [-o OUT_DIR] +# +# Driven sequence (one app run): +# launch -> 8s idle (browser) -> open seeded file (debug cmd) -> 16s (settle + +# editor idle) -> scroll -> 2.5s -> scroll -> 2.5s -> scroll +# +# Analysis: the profiler marks rows whose previous frame is >= 100ms away +# as gaps, and flushes the CSV when a burst ends, so the CSV is complete +# and self-anchoring (no clock correlation). Rows are grouped into PHASES +# by splitting at gaps >= 2s (the script's action windows are all >= 2s +# apart; late async frames — list load, line-index build — land 100-200ms +# after their action and stay in the phase). Expected phases: +# 1. browser startup (+ 8s idle) budget 10 frames +# 2. open (+ settle + 16s editor idle) budget 20 frames +# 3..N. one per driven scroll budget 8 frames each +# A phase over budget means frames were emitted without (enough) cause — +# a ticker, a re-emission loop, a feedback ping-pong; a 1/s spinner alone +# exceeds a 16s idle phase's budget. The PERF / PERF-PRESENT logcat lines +# are printed for a human to eyeball live fps and latency. +# +# Requirements: adb, the app installed, and (Android 11+) the All-files +# access appop (set automatically when possible). +set -euo pipefail + +SERIAL="" +OUT="/tmp/pad-prof" +while getopts ":s:o:h" flag; do + case "$flag" in + s) SERIAL="$OPTARG" ;; + o) OUT="$OPTARG" ;; + h) grep '^#' "$0" | sed 's/^# \{0,1\}//'; exit 0 ;; + *) echo "unknown option" >&2; exit 2 ;; + esac +done + +PKG=pad.pad +ACT=pad.pad/org.gioui.GioActivity +PERFDIR=/storage/emulated/0/PadPerf +# The browser opens at the app's start path (cmd/pad/impl_android.go); +# seed a known scrollable file there so the tap opens real content — it is +# the newest file and the list is date-desc, so it is the first row. +NOTES=/storage/emulated/0/Notes +PROFILE_FILE=padprofile.txt +# Frame budgets per phase index (1-based): startup, open, then per scroll. +BUDGET_STARTUP="${BUDGET_STARTUP:-10}" +BUDGET_OPEN="${BUDGET_OPEN:-20}" +BUDGET_SCROLL="${BUDGET_SCROLL:-8}" + +if [ -z "$SERIAL" ]; then + SERIAL=$(adb devices | awk 'NR>1 && $2=="device" {print $1; exit}') + if [ -z "$SERIAL" ]; then + echo "no connected device; pass -s SERIAL" >&2 + exit 1 + fi +fi +adb() { command adb -s "$SERIAL" "$@"; } + +echo "== profiling on $SERIAL ==" +adb shell "mkdir -p $PERFDIR $NOTES" +adb shell "touch $PERFDIR/enable" +adb shell appops set "$PKG" MANAGE_EXTERNAL_STORAGE allow 2>/dev/null || true +mkdir -p "$OUT" +CSV="$OUT/logic_frames.csv" +awk 'BEGIN { for (i = 1; i <= 4000; i++) printf "profile line %04d: the quick brown fox jumps over the lazy dog\n", i }' > "$OUT/$PROFILE_FILE" +adb push "$OUT/$PROFILE_FILE" "$NOTES/$PROFILE_FILE" >/dev/null +cleanup() { + adb shell "rm -f $NOTES/$PROFILE_FILE" 2>/dev/null || true +} +trap cleanup EXIT + +# parse_csv prints one line per phase: frame count, max in-phase (non-gap) +# delta (ms), and the pages covered. Phases are the frame-runs split at +# gaps >= 2s (the rows themselves are still counted in their phase). +parse_csv() { + awk -F, ' + function emit() { + if (n > 0) printf "frames=%-4d maxDelta=%7.1f ms page=%s\n", n, md, pg + n = 0; md = 0; pg = "" + } + { + if ($10 == "true" && $3 + 0 >= 2000) emit() + if (n == 0) pg = $4; else if ($4 != pg) pg = pg "+" $4 + n++ + if ($10 != "true" && $3 + 0 > md) md = $3 + 0 + } + END { emit() } + ' "$1" +} + +fail=0 +adb shell am force-stop "$PKG" +adb shell "rm -f $PERFDIR/logic_frames.csv $PERFDIR/cmd" +adb logcat -c +adb shell am start -n "$ACT" >/dev/null +echo "-- app launched; driving: 8s idle, open (debug cmd), 16s, scroll x3" +sleep 8 +adb shell "echo 'open $NOTES/$PROFILE_FILE' > $PERFDIR/cmd" +sleep 16 +adb shell "echo 'frac 0.5' > $PERFDIR/cmd"; sleep 2.5 +adb shell "echo 'frac 0.2' > $PERFDIR/cmd"; sleep 2.5 +adb shell "echo 'frac 0.4' > $PERFDIR/cmd"; sleep 2 +adb shell am force-stop "$PKG" +adb pull "$PERFDIR/logic_frames.csv" "$CSV" >/dev/null + +echo "-- logcat PERF lines (live view; fps < 1 means no continuous redraw):" +adb logcat -d | grep "I $PKG.*PERF" | sed 's/^/ /' || true +echo "-- phases (split at idle gaps >= 2s):" +PHASES=$(parse_csv "$CSV") +echo "$PHASES" | sed 's/^/ /' + +# The seeded file is 4000 lines: a frame with TotalLines >= 4000 proves the +# editor actually opened it (the 'open' cmd goes through the same OpenFile +# path as a browser tap). +if ! awk -F, '$7 >= 4000 { found = 1 } END { exit !found }' "$CSV"; then + echo "FAIL: the seeded file was never opened (no frame with" \ + "TotalLines >= 4000) — check the debug 'open' command in logcat." >&2 + fail=1 +fi +i=1 +while IFS= read -r line; do + n=$(echo "$line" | sed 's/.*frames=//; s/ .*//') + if [ "$i" -eq 1 ]; then budget="$BUDGET_STARTUP" + elif [ "$i" -eq 2 ]; then budget="$BUDGET_OPEN" + else budget="$BUDGET_SCROLL"; fi + if [ "$n" -gt "$budget" ]; then + echo "FAIL: phase $i has $n frames (budget $budget) — frames are" \ + "being generated without a cause: $line" >&2 + fail=1 + fi + i=$((i + 1)) +done <<< "$PHASES" + +echo +if [ "$fail" -ne 0 ]; then + echo "RESULT: FAIL — unnecessary frame generation detected (details above)." >&2 + exit 1 +fi +echo "RESULT: PASS — every phase is within its frame budget." +echo "CSV saved: $CSV"