// 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 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 { 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, Gap: delta >= gapThreshold, }) 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 } // 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. 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 } 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 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%% 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,%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] } // 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) }