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.
211 lines
5.1 KiB
Go
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)
|
|
}
|