Pad/internal/perf/perf.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
	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)
}