Add pre-release frame-regression profiling

Ensures the app never generates frames without a cause (frame emission
is event-driven; a spinner would burn CPU/battery for the app's entire
idle life). Verified on the emulator and the phone: healthy runs show
ZERO frames across all idle windows (PERF-PRESENT fps < 1).

- perf: rows whose previous frame is >= 100ms away are idle gaps, not
  slow frames — flagged in the CSV (new gap column) and kept out of the
  logcat summary's latency percentiles (reported as gaps=N maxGap=...).
  A frame >= 2s after the previous one flushes the CSV, so a burst's
  rows are persisted the moment the next burst starts (an idle tail or
  force-stop no longer loses the last burst).
- editor: debug 'open <path>' command (cmd-file poller, perf mode):
  opens a file from any page via the same OpenFile path as a browser
  tap — deterministic, no pixel tapping.
- e2e: TestNoFramesWhileIdle (browser + editor after load/scroll/find)
  asserts the logic emits ZERO frames across an idle window once
  settled — the headless contract, in the regular go-test suite.
- scripts/profile_emulator.sh: drives launch, 8s idle, open (seeded
  4000-line file), 16s idle, 3 scrolls on a device/emulator; groups the
  CSV into phases at idle gaps >= 2s and FAILs on a phase over its frame
  budget (1/s spinner exceeds a 16s idle budget; faster ones balloon a
  phase or show in PERF-PRESENT). Validated both ways: PASS on a healthy
  build (emulator + phone), FAIL on an injected 500ms frame spinner.
- doc: architecture.md §11 updated (gap handling, burst flush, debug
  open, frame-regression guard, 2026-08 measurements).
This commit is contained in:
Greg Pomerantz 2026-08-20 14:18:08 -04:00
parent c789de4b44
commit ac1c32e4c0
5 changed files with 360 additions and 21 deletions

View File

@ -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 <int>` 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 <int>` jump the editor's `ScrollOffset` (clamped to
`[0, MaxScroll]`) and emit a frame; `open <path>` 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 56 frames, open 56, and 12 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).

View File

@ -358,7 +358,8 @@ func (l *Logic) emitFrame() {
}
// EnableDebugCmdPoll starts a background poller (debug-only) that watches
// <dir>/cmd for a one-shot scroll command and forwards it to the owner for
// <dir>/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 <int>". Must be
// called on the logic goroutine.
// poller. Commands: "open <path>" (any page), and, on the editor page,
// "top", "bottom", "frac <0..1>", "dp <int>". 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 <path>" 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":

View File

@ -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]

View File

@ -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 <sd>/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")
}

152
scripts/profile_emulator.sh Executable file
View File

@ -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"