Pad/internal/perf/perf.go
Greg Pomerantz be48ad8157 perf: default-off in-app profiler + debug scroll jumps; verify scroll perf & clamping
internal/perf: single-goroutine profiler (no locks). When enabled by the
/storage/emulated/0/PadPerf/enable marker it records one CSV row per logic
frame (seq, ms, frame delta, page, scroll Dp, max-scroll Dp, total lines,
visible byte range), logs a rolling ~1/s summary, and on Stop reports
nearest-rank p50/p90/p99/max. Flushes per row-batch but never fsyncs per
flush (avoids periodic hitches in the logic path).

editor: PerfRecord package-level hook (nil when off) + ProbeRecord;
Logic.emitFrame() now centralizes every frame emission so the profiler sees
each logic frame exactly once, on the owner goroutine. State gains
VisibleStart/VisibleEnd so the probe can confirm shaping stays
viewport-bounded.

logic: optional debug cmd poller (off by default) watches <dir>/cmd as a
one-shot file (top/bottom/frac <0..1>/dp <int>) and the owner applies a
clamped [0,MaxScroll] jump + frame. Enables deterministic large-offset scroll
tests without pixel taps.

main: wires the profiler when the marker file exists; logs present-fps
every 2s; stops the profiler on Destroy.

docs: README package inventory (add internal/perf); architecture §11
profiler facility; spec §5 invariant 7 (scroll always clamped to
[0,maxScroll]) + §6 measured rows; development_plan v5 + Phase 6 results.

Verified: go build/vet + full -race green. On-device 10 MB file:
logic-frame cadence flat across offsets 0.02->1.0 (no large-offset
degradation), visible byte range <=4.3 KB at every offset, clamping exact
across 2->130,955-line files, PSS plateaus ~250 MB (bounded, no leak);
profiler overhead negligible.
2026-08-16 16:53:28 -04:00

211 lines
5.1 KiB
Go

// Package perf provides a lightweight, dependency-free in-app frame profiler.
//
// It is owned by a single goroutine (the logic goroutine) and records
// per-frame timing plus a small context (scroll offset, max scroll, total
// lines, visible byte range) so scroll performance and clamping can be
// analysed offline. It is an instrumentation facility: the app enables it at
// runtime (see cmd/pad) and the per-frame cost is a slice append plus
// occasional log/flush. With the record hook nil (the default), it is unused.
package perf
import (
"fmt"
"log"
"math"
"os"
"path/filepath"
"sort"
"time"
)
// Ctx is the per-frame context recorded alongside timing.
type Ctx struct {
Page string // "editor" | "browser"
ScrollDP float32 // scroll offset (Dp)
MaxScrollDP float32 // max scroll (Dp)
TotalLines int
VisStart int // visible byte range start
VisEnd int // visible byte range end (exclusive)
}
// Row is one recorded frame, the unit of CSV output.
type Row struct {
Seq int
Tms float64 // ms since profiling started
DeltaMs float64 // ms since previous frame emission
Page string
ScrollDP float32
MaxScrollDP float32
TotalLines int
VisStart int
VisEnd int
}
// Profiler records logic-frame cadence plus context. All methods must be
// called from the owning goroutine only (no locks).
type Profiler struct {
enabled bool
outPath string
start time.Time
last time.Time
lastLog time.Time
lastFlush time.Time
buf []Row
seq int
file *os.File
}
// New creates a profiler. If enabled and outDir is non-empty, it creates the
// output directory and file (named outDir/name). A failed file disables CSV
// output but keeps the logcat summaries.
func New(enabled bool, outDir, name string) *Profiler {
p := &Profiler{enabled: enabled}
if !enabled {
return p
}
p.start = time.Now()
p.lastLog = time.Now()
p.lastFlush = time.Now()
if outDir != "" {
if err := os.MkdirAll(outDir, 0o755); err == nil {
p.outPath = filepath.Join(outDir, name)
if f, err := os.Create(p.outPath); err == nil {
p.file = f
} else {
log.Printf("PERF: cannot create %s: %v", p.outPath, err)
}
} else {
log.Printf("PERF: cannot create dir %s: %v", outDir, err)
}
}
return p
}
// Record is called once per frame emission, on the owner goroutine. It is the
// only hot-path cost: a slice append, with a logcat summary ~1/s and a disk
// flush ~2/s (the flush is a single small write, never per-frame).
func (p *Profiler) Record(ctx Ctx) {
if !p.enabled {
return
}
now := time.Now()
if p.start.IsZero() {
p.start = now
p.lastLog = now
p.lastFlush = now
}
var delta time.Duration
if !p.last.IsZero() {
delta = now.Sub(p.last)
}
p.last = now
p.seq++
p.buf = append(p.buf, Row{
Seq: p.seq,
Tms: float64(now.Sub(p.start).Nanoseconds()) / 1e6,
DeltaMs: float64(delta.Nanoseconds()) / 1e6,
Page: ctx.Page,
ScrollDP: ctx.ScrollDP,
MaxScrollDP: ctx.MaxScrollDP,
TotalLines: ctx.TotalLines,
VisStart: ctx.VisStart,
VisEnd: ctx.VisEnd,
})
if now.Sub(p.lastLog) >= time.Second {
p.logSummary()
p.lastLog = now
}
if now.Sub(p.lastFlush) >= 2*time.Second {
p.flush()
p.lastFlush = now
}
}
// logSummary prints a rolling percentile summary of the frames buffered since
// the last flush to logcat.
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
}
p50, p90, p99, mx := percentiles(ds)
over16, over33 := 0, 0
for _, d := range ds {
if d > 16.7 {
over16++
}
if d > 33.4 {
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))
}
// 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)
}
}
p.buf = p.buf[:0]
}
// Stop flushes remaining rows and closes the file. Call once on shutdown.
func (p *Profiler) Stop() {
if !p.enabled {
return
}
p.flush()
if p.file != nil {
p.file.Close()
p.file = nil
}
log.Printf("PERF stopped: %d frames, out=%s", p.seq, p.outPath)
}
// percentiles returns p50/p90/p99/max of ds in ms.
func percentiles(ds []float64) (p50, p90, p99, mx float64) {
if len(ds) == 0 {
return
}
s := make([]float64, len(ds))
copy(s, ds)
sort.Float64s(s)
p50 = s[pctlIdx(len(s), 0.50)]
p90 = s[pctlIdx(len(s), 0.90)]
p99 = s[pctlIdx(len(s), 0.99)]
if p99 < p90 {
p99 = p90
}
mx = s[len(s)-1]
return
}
// pctlIdx returns the nearest-rank index for fraction f (in [0,1]) of n
// samples: the smallest i such that i/n >= f, clamped to [0, n-1].
func pctlIdx(n int, f float64) int {
i := int(math.Ceil(float64(n)*f)) - 1
if i < 0 {
i = 0
}
if i >= n {
i = n - 1
}
return i
}
func pct(part, whole int) float64 {
if whole == 0 {
return 0
}
return 100 * float64(part) / float64(whole)
}