diff --git a/.github/workflows/perf.yaml b/.github/workflows/perf.yaml new file mode 100644 index 0000000..7d6982e --- /dev/null +++ b/.github/workflows/perf.yaml @@ -0,0 +1,160 @@ +name: Track Perf + +# `shelltime track` runs in the foreground of every shell prompt, so its latency +# is user-facing. This builds the base and head binaries and times the real +# process in interleaved rounds on one runner (perf/compare.sh), then reports +# per-scenario changes in the job summary and, on PRs, in a sticky comment. +# Regressions are warnings (annotations + report), never a failed check. + +on: + pull_request: + branches: + - main + types: + - opened + - synchronize + - reopened + push: + branches: + - main + workflow_dispatch: + inputs: + base: + description: Commit to compare against (default HEAD^1) + required: false + default: "" + rounds: + description: Interleaved rounds per binary + required: false + default: "10" + +permissions: + contents: read + +concurrency: + group: track-perf-${{ github.event.pull_request.number || github.ref }} + # Superseded PR pushes are cancelled; every main commit keeps its report. + cancel-in-progress: ${{ github.event_name == 'pull_request' }} + +jobs: + track-perf: + name: shelltime track latency + runs-on: ubuntu-24.04 + timeout-minutes: 30 + permissions: + contents: read + pull-requests: write # sticky comment; read-only on fork PRs, which get the summary only + env: + # Build both sides with head's toolchain, so a change shows the code's + # effect, not the compiler's. + GOTOOLCHAIN: local + ROUNDS: ${{ inputs.rounds || '10' }} + ITERS: "100" + THRESHOLD: "10" + steps: + - name: Checkout code + uses: actions/checkout@v5 + with: + fetch-depth: 0 + + - name: Setup Go + uses: actions/setup-go@v5 + with: + go-version-file: go.mod + cache-dependency-path: | + go.sum + perf/go.sum + + - name: Test the perf tooling + run: | + go -C perf vet ./... + go -C perf test ./... + + - name: Pick the base commit + id: base + env: + EVENT: ${{ github.event_name }} + BEFORE: ${{ github.event.before }} + INPUT_BASE: ${{ inputs.base }} + PR_NUMBER: ${{ github.event.pull_request.number }} + PR_HEAD: ${{ github.event.pull_request.head.sha }} + run: | + case "$EVENT" in + push) base=$BEFORE ;; + workflow_dispatch) base=$INPUT_BASE ;; + # pull_request checks out the merge commit: its first parent + # is exactly the base the PR is being merged onto. + *) base= ;; + esac + if [[ -z $base ]] || ! git cat-file -e "$base^{commit}" 2>/dev/null; then + base=$(git rev-parse HEAD^1) + fi + base=$(git rev-parse "$base^{commit}") + + # Harness changes need a full run even when the binary is unchanged. + force=0 + git diff --quiet "$base" HEAD -- perf .github/workflows/perf.yaml || force=1 + + if [[ $EVENT == pull_request ]]; then + base_label="\`$GITHUB_BASE_REF\` @ \`${base::7}\`" + head_label="#$PR_NUMBER @ \`${PR_HEAD::7}\`" + else + base_label="\`${base::7}\`" + head_label="\`$(git rev-parse --short=7 HEAD)\`" + fi + { + echo "sha=$base" + echo "force=$force" + echo "base_label=$base_label" + echo "head_label=$head_label" + } >> "$GITHUB_OUTPUT" + + - name: Benchmark base vs head + id: perf + env: + BASE_SHA: ${{ steps.base.outputs.sha }} + FORCE: ${{ steps.base.outputs.force }} + BASE_LABEL: ${{ steps.base.outputs.base_label }} + HEAD_LABEL: ${{ steps.base.outputs.head_label }} + run: perf/compare.sh "$BASE_SHA" WORKTREE "$RUNNER_TEMP/perf" + + - name: Job summary + if: always() + run: | + report=$RUNNER_TEMP/perf/report.md + if [[ -f $report ]]; then + cat "$report" >> "$GITHUB_STEP_SUMMARY" + fi + + - name: Comment on the PR + if: >- + always() && + github.event_name == 'pull_request' && + github.event.pull_request.head.repo.full_name == github.repository + env: + GH_TOKEN: ${{ github.token }} + PR_NUMBER: ${{ github.event.pull_request.number }} + SKIPPED: ${{ steps.perf.outputs.skipped }} + run: | + report=$RUNNER_TEMP/perf/report.md + if [[ ! -f $report ]]; then + exit 0 + fi + # An unchanged binary refreshes an existing report but never + # starts a new comment thread. + if [[ $SKIPPED == true ]]; then + perf/comment.sh "$PR_NUMBER" "$report" --update-only + else + perf/comment.sh "$PR_NUMBER" "$report" + fi + + - name: Upload results + if: always() + uses: actions/upload-artifact@v4 + with: + name: track-perf + path: | + ${{ runner.temp }}/perf/*.txt + ${{ runner.temp }}/perf/*.md + ${{ runner.temp }}/perf/*.log + if-no-files-found: ignore diff --git a/AGENTS.md b/AGENTS.md index acd72ff..a2cf324 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -15,6 +15,7 @@ This is a Go monorepo for the ShellTime CLI and daemon. - `model/`: config, API clients, shell integrations, crypto, and shared domain logic - `docs/`: user-facing docs such as `CONFIG.md` and `CC_STATUSLINE.md` - `fixtures/`: reusable test fixtures +- `perf/`: separate Go module that benchmarks the real `shelltime track` process, plus the CI comparison tooling Keep new code inside the existing package boundary. Do not mix CLI wiring, daemon internals, and model logic in the same package. @@ -31,6 +32,8 @@ Keep new code inside the existing package boundary. Do not mix CLI wiring, daemo - `go vet ./...`: run static analysis - `mockery`: regenerate mocks when interfaces change - `pp g`: regenerate PromptPal-generated artifacts when relevant +- `go -C perf test -run '^$' -bench . -benchtime 50x -count 5`: benchmark `shelltime track` latency on the current tree (`perf/` is its own module; see `perf/README.md`) +- `perf/compare.sh origin/main`: compare `track` latency of a base commit and the working tree, as the `Track Perf` workflow does on every PR and push to `main` Use Go 1.27.1, as declared in `go.mod`. diff --git a/CLAUDE.md b/CLAUDE.md index 1d9285b..726a23f 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -40,6 +40,17 @@ go test -run TestHandlerName ./daemon/ Tests use **testify** (assertions + suites). Suite-based tests use `suite.Suite` with `SetupTest`/`TearDownTest` lifecycle hooks (see `daemon/cc_info_handler_test.go` for example). Simple functions use table-driven tests. +### Performance (`shelltime track` latency) +`perf/` is a separate Go module (root `./...` skips it). It benchmarks the real binary the way the shell hooks run it: daemon and direct paths, pre and post, plus a sync. See `perf/README.md`. +```bash +# Benchmark the current tree +go -C perf test -run '^$' -bench . -benchtime 50x -count 5 + +# Compare a base commit with the working tree, as CI does +perf/compare.sh origin/main +``` +The `Track Perf` workflow (`.github/workflows/perf.yaml`) runs this on every PR and push to `main`. It posts the report as a PR comment and in the job summary. A scenario that gets more than 10% slower (and more than 0.25 ms, with p < 0.05) raises a warning, never a failure. `Track/*` scenarios skip while a real daemon owns `/tmp/shelltime.sock`. + ### Code Generation ```bash # Generate mocks (uses .mockery.yml configuration, Mockery v3) diff --git a/perf/README.md b/perf/README.md new file mode 100644 index 0000000..aa1d132 --- /dev/null +++ b/perf/README.md @@ -0,0 +1,91 @@ +# `shelltime track` performance tests + +The shell hooks (`model/hooks/`) run `shelltime track` in the foreground before +and after **every** command, so its latency sits directly between the user and +their next prompt. The benchmarks here exec the real binary, with the same flags +the zsh hook passes, in an isolated `$HOME`. That measures what users feel: +exec, Go runtime and package init, `main`'s config read and telemetry setup, +then the track logic. + +This directory is its own Go module, so `golang.org/x/perf` never takes part in +version selection for the shipped binaries, and the root `go test ./...` skips +it. + +## Scenarios + +| Benchmark | What it measures | +|---|---| +| `Startup/floor` | Runs `true`, not shelltime: the runner's fork/exec cost. Base and head run the same thing, so this row is an A/A check of runner noise | +| `Startup/version` | `shelltime --version`: process start, init, config read, no command logic | +| `Track/daemon/pre`, `/post` | The default install. A fake daemon listens on `/tmp/shelltime.sock`; track sends it the event and returns | +| `Track/direct/pre` | No daemon. track appends to `~/.shelltime/commands/pre.txt` | +| `Track/direct/post` | No daemon, below the flush threshold. track appends to `post.txt` and reads the whole store (500 synced pairs) to decide whether to sync | +| `Track/direct/post-sync` | The post that reaches `flushCount` and sends the batch to a local fake API (once every 10 commands in direct mode) | + +Every scenario checks that the binary really took its path: the fake daemon got +one event per run, the store grew, the API got one batch per run, and +`log.log` holds no errors. `track` always exits 0, so without these checks a +broken run would just look fast. A failed check fails that scenario only, and +the report shows it as āŒ. + +Besides wall time (`sec/op`), each scenario reports per-exec user and sys CPU, +p50/p95 wall time and peak RSS of the child process. + +On Linux the direct post path execs `lsb_release`. On Ubuntu that is a Python +script that adds tens of noisy milliseconds, so the harness puts a shell stub +with the same output first in `PATH`. Set `SHELLTIME_BENCH_REAL_OSINFO=1` to +measure the real one. + +## Running locally + +```sh +# Benchmark the current tree (builds ./cmd/cli once) +go -C perf test -run '^$' -bench . -benchtime 50x -count 5 + +# Benchmark a specific binary +SHELLTIME_BENCH_BIN=/path/to/shelltime go -C perf test -run '^$' -bench . -benchtime 50x + +# Reproduce the CI comparison: base commit vs the working tree, uncommitted changes included +perf/compare.sh origin/main +ROUNDS=4 ITERS=30 perf/compare.sh HEAD~1 HEAD /tmp/perf # quicker, explicit head and output dir +``` + +The `Track/*` scenarios are skipped while a real shelltime daemon owns +`/tmp/shelltime.sock`, which is the usual state of a developer machine: the +daemon would receive the fake commands. Stop the daemon to run them. The socket +path is fixed in the CLI, so it cannot be redirected. + +## In CI + +`.github/workflows/perf.yaml` runs on every pull request to `main`, every push +to `main` and on demand. It compares: + +- a pull request against the commit it is merged onto (`HEAD^1` of the merge commit), +- a push to `main` against the previous `main` tip (`github.event.before`). + +`compare.sh` builds both binaries with identical flags (`CGO_ENABLED=0 +-trimpath -buildvcs=false -ldflags "-s -w"`). If they come out byte-identical, +for example on a docs-only change, it skips the run, unless the harness itself +changed. Otherwise it compiles the harness once from head and runs it against +both binaries in 10 rounds of 100 execs per scenario. The rounds alternate in +ABBA order on the same runner, so drift and noise hit both sides alike. + +The report goes to the job summary and, on pull requests from this repository, +to a single comment that later runs update. Fork pull requests get a read-only +token, so they only get the summary. + +### Reading the report + +Values are medians across rounds, with a 95% confidence interval. A scenario is +flagged āš ļø when it is **more than 10% slower, more than 0.25 ms slower and +significant (Mann-Whitney U, p < 0.05)**. The absolute floor keeps +sub-millisecond scenarios from flagging on scheduler jitter. ~ means no +significant difference. šŸš€ is the same rule in the other direction. + +If `Startup/floor` itself moved significantly, the headline says the runner was +noisy. Treat small changes in that run with care. + +A regression never fails the check. It shows up as āš ļø in the report and as a +warning annotation on the run. Rerun the job if you suspect noise, or reproduce +it locally with `compare.sh`. To tune the gate, change `THRESHOLD` in the +workflow, or `-min-delta` in `cmd/perfreport`. diff --git a/perf/cmd/perfreport/main.go b/perf/cmd/perfreport/main.go new file mode 100644 index 0000000..45660dc --- /dev/null +++ b/perf/cmd/perfreport/main.go @@ -0,0 +1,133 @@ +// Command perfreport compares two runs of the perf benchmarks (base and head) +// and writes a markdown report. It never fails on a regression: it warns. +// +// perfreport -base a.txt -head b.txt -md report.md [-github] +// perfreport -skipped "reason" -md report.md +// +// With -github it also prints ::warning annotations for flagged scenarios and +// writes regression=true|false and skipped=true|false to $GITHUB_OUTPUT. +package main + +import ( + "flag" + "fmt" + "io" + "os" + "time" +) + +func main() { + if err := run(os.Args[1:], os.Stdout); err != nil { + fmt.Fprintln(os.Stderr, "perfreport:", err) + os.Exit(1) + } +} + +func run(args []string, stdout io.Writer) error { + fs := flag.NewFlagSet("perfreport", flag.ContinueOnError) + var ( + basePath = fs.String("base", "", "benchmark output of the base binary") + headPath = fs.String("head", "", "benchmark output of the head binary") + baseBin = fs.String("base-bin", "", "base binary, for its size") + headBin = fs.String("head-bin", "", "head binary, for its size") + benchstat = fs.String("benchstat", "", "file with `benchstat` output to embed") + mdPath = fs.String("md", "", "write the markdown report here (default stdout)") + skipped = fs.String("skipped", "", "write a report that only says why the comparison was skipped") + github = fs.Bool("github", false, "emit GitHub Actions annotations and step outputs") + o options + thresholdP float64 + ) + fs.Float64Var(&thresholdP, "threshold", 10, "flag scenarios more than this many percent slower") + fs.DurationVar(&o.minDelta, "min-delta", 250*time.Microsecond, "and more than this much slower in absolute terms") + fs.StringVar(&o.baseLabel, "base-label", "base", "how the report names the base") + fs.StringVar(&o.headLabel, "head-label", "head", "how the report names the head") + fs.StringVar(&o.note, "note", "", "extra footer text") + if err := fs.Parse(args); err != nil { + return err + } + o.threshold = thresholdP / 100 + o.noise = 0.05 + + var md string + regression := false + if *skipped != "" { + md = skippedMarkdown(*skipped) + } else { + if *basePath == "" || *headPath == "" { + return fmt.Errorf("-base and -head are required") + } + base, err := parseFile(*basePath) + if err != nil { + return err + } + head, err := parseFile(*headPath) + if err != nil { + return err + } + o.baseSize, o.headSize = fileSize(*baseBin), fileSize(*headBin) + if *benchstat != "" { + data, err := os.ReadFile(*benchstat) + if err != nil { + return err + } + o.benchstat = string(data) + } + res := compare(base, head, o) + md = res.markdown(o) + regression = res.regressions > 0 || res.failed > 0 + if *github { + for _, a := range res.annotations() { + fmt.Fprintln(stdout, a) + } + } + } + + if *mdPath == "" { + fmt.Fprint(stdout, md) + } else if err := os.WriteFile(*mdPath, []byte(md), 0o644); err != nil { + return err + } + if *github { + return writeOutputs(map[string]bool{"regression": regression, "skipped": *skipped != ""}) + } + return nil +} + +func parseFile(path string) (*samples, error) { + f, err := os.Open(path) + if err != nil { + return nil, err + } + defer f.Close() + return parse(f, path) +} + +func fileSize(path string) int64 { + if path == "" { + return 0 + } + st, err := os.Stat(path) + if err != nil { + return 0 + } + return st.Size() +} + +// writeOutputs appends step outputs to $GITHUB_OUTPUT when it is set. +func writeOutputs(outputs map[string]bool) error { + path := os.Getenv("GITHUB_OUTPUT") + if path == "" { + return nil + } + f, err := os.OpenFile(path, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0o644) + if err != nil { + return err + } + defer f.Close() + for _, k := range []string{"regression", "skipped"} { + if _, err := fmt.Fprintf(f, "%s=%t\n", k, outputs[k]); err != nil { + return err + } + } + return nil +} diff --git a/perf/cmd/perfreport/report.go b/perf/cmd/perfreport/report.go new file mode 100644 index 0000000..712733c --- /dev/null +++ b/perf/cmd/perfreport/report.go @@ -0,0 +1,410 @@ +package main + +import ( + "fmt" + "io" + "math" + "regexp" + "slices" + "strings" + "time" + + "golang.org/x/perf/benchfmt" + "golang.org/x/perf/benchmath" + "golang.org/x/perf/benchunit" +) + +// marker is the first line of every report; comment.sh finds the PR comment +// to update by it. +const marker = "" + +const ( + // wallUnit is the only unit that can flag a regression: wall time is + // what the user waits for at the prompt. + wallUnit = "sec/op" + // floorName is the fork/exec baseline, which does not depend on the + // binary under test. + floorName = "Startup/floor" +) + +// extraUnits are shown in the details table, in this order. +var extraUnits = []struct{ unit, label string }{ + {"p95-sec/op", "p95 wall"}, + {"user-sec/op", "user CPU"}, + {"sys-sec/op", "sys CPU"}, + {"peak-rss-B", "peak RSS"}, +} + +type options struct { + threshold float64 // relative slowdown that flags a regression, e.g. 0.10 + minDelta time.Duration // and the absolute slowdown it must also exceed + noise float64 // floor drift past which the run is called noisy + + baseLabel, headLabel string + baseSize, headSize int64 // binary sizes in bytes, 0 if unknown + benchstat string // raw `benchstat` output, optional + note string // extra footer line, optional +} + +// samples holds every value of every benchmark in one results file. +type samples struct { + order []string // benchmark names, first-seen order + values map[string]map[string][]float64 // name → unit → values + config map[string]string // goos, goarch, cpu, … +} + +var procsSuffix = regexp.MustCompile(`-\d+$`) + +// parse reads Go benchmark output. Names lose the "Benchmark" prefix (benchfmt +// drops it) and the -GOMAXPROCS suffix, and units are tidied (ns/op is read as +// sec/op). +func parse(r io.Reader, fileName string) (*samples, error) { + s := &samples{values: map[string]map[string][]float64{}, config: map[string]string{}} + br := benchfmt.NewReader(r, fileName) + for br.Scan() { + switch rec := br.Result().(type) { + case *benchfmt.Result: + name := procsSuffix.ReplaceAllString(rec.Name.String(), "") + units, ok := s.values[name] + if !ok { + units = map[string][]float64{} + s.values[name] = units + s.order = append(s.order, name) + } + for _, v := range rec.Values { + // The reader leaves zero values untidied ("0 sys-ns/op"). + val, unit := benchunit.Tidy(v.Value, v.Unit) + units[unit] = append(units[unit], val) + } + for _, c := range rec.Config { + if _, seen := s.config[c.Key]; !seen && c.File { + s.config[c.Key] = string(c.Value) + } + } + case *benchfmt.SyntaxError: + return nil, rec + } + } + return s, br.Err() +} + +type status int + +const ( + statusSame status = iota + statusSlower + statusFaster + statusNew // no base result: a scenario added on head + statusFailed // no head result: the scenario failed or was removed + statusFloor // the A/A baseline row +) + +// metric compares one unit of one benchmark. +type metric struct { + ok bool // both sides have values + base, head benchmath.Summary + cmp benchmath.Comparison +} + +func (m metric) significant() bool { return m.ok && m.cmp.P < m.cmp.Alpha } + +func (m metric) delta() float64 { + if !m.ok || m.base.Center == 0 { + return 0 + } + return m.head.Center/m.base.Center - 1 +} + +type row struct { + name string + status status + wall metric + extra map[string]metric + // lone holds the summary of the only side that has results, for new and + // failed rows. + lone *benchmath.Summary +} + +type result struct { + rows []row + regressions, faster, new int + failed int + noisy bool + runs int // samples per side + config map[string]string +} + +func newMetric(base, head []float64) metric { + if len(base) == 0 || len(head) == 0 { + return metric{} + } + thr := &benchmath.DefaultThresholds + // NewSample sorts its input in place. + sb := benchmath.NewSample(slices.Clone(base), thr) + sh := benchmath.NewSample(slices.Clone(head), thr) + return metric{ + ok: true, + base: benchmath.AssumeNothing.Summary(sb, 0.95), + head: benchmath.AssumeNothing.Summary(sh, 0.95), + cmp: benchmath.AssumeNothing.Compare(sb, sh), + } +} + +func compare(base, head *samples, o options) result { + res := result{config: head.config} + if len(res.config) == 0 { + res.config = base.config + } + names := slices.Clone(head.order) + for _, n := range base.order { + if !slices.Contains(names, n) { + names = append(names, n) + } + } + for _, name := range names { + b, h := base.values[name], head.values[name] + r := row{name: name, wall: newMetric(b[wallUnit], h[wallUnit]), extra: map[string]metric{}} + for _, u := range extraUnits { + r.extra[u.unit] = newMetric(b[u.unit], h[u.unit]) + } + res.runs = max(res.runs, len(h[wallUnit]), len(b[wallUnit])) + + switch { + case len(h[wallUnit]) == 0: + r.status = statusFailed + r.lone = loneSummary(b[wallUnit]) + res.failed++ + case len(b[wallUnit]) == 0: + r.status = statusNew + r.lone = loneSummary(h[wallUnit]) + res.new++ + case name == floorName: + r.status = statusFloor + res.noisy = r.wall.significant() && math.Abs(r.wall.delta()) > o.noise + default: + r.status = gate(r.wall, o) + switch r.status { + case statusSlower: + res.regressions++ + case statusFaster: + res.faster++ + } + } + res.rows = append(res.rows, r) + } + return res +} + +// gate flags a change only when it is statistically significant, larger than +// the relative threshold and larger than the absolute floor. The last guard +// stops sub-millisecond scenarios from flagging on scheduler jitter. +func gate(m metric, o options) status { + if !m.significant() { + return statusSame + } + d := m.delta() + abs := time.Duration(math.Abs(m.head.Center-m.base.Center) * float64(time.Second)) + switch { + case d > o.threshold && abs > o.minDelta: + return statusSlower + case d < -o.threshold && abs > o.minDelta: + return statusFaster + } + return statusSame +} + +func loneSummary(values []float64) *benchmath.Summary { + if len(values) == 0 { + return nil + } + s := benchmath.AssumeNothing.Summary(benchmath.NewSample(slices.Clone(values), &benchmath.DefaultThresholds), 0.95) + return &s +} + +// headline is the one-line verdict at the top of the report. +func (res result) headline(o options) string { + var parts []string + switch { + case res.regressions > 0: + parts = append(parts, fmt.Sprintf("āš ļø **%s got slower**: more than %s in wall time", plural(res.regressions, "scenario"), pct(o.threshold))) + case res.faster > 0: + parts = append(parts, fmt.Sprintf("šŸš€ **%s got faster** by more than %s", plural(res.faster, "scenario"), pct(o.threshold))) + default: + parts = append(parts, "āœ… **No significant change** in `shelltime track` latency") + } + if res.failed > 0 { + parts = append(parts, fmt.Sprintf("āŒ %s produced no result on head", plural(res.failed, "scenario"))) + } + if res.noisy { + parts = append(parts, "šŸŽ² the runner was noisy (the fork/exec floor moved too), so treat small changes with care") + } + return strings.Join(parts, " Ā· ") +} + +// markdown renders the report. +func (res result) markdown(o options) string { + var sb strings.Builder + w := func(format string, args ...any) { fmt.Fprintf(&sb, format, args...) } + + w("%s\n## ā±ļø `shelltime track` performance\n\n", marker) + w("%s\n\n", res.headline(o)) + w("Comparing %s → %s. Each scenario execs the binary the way the shell hooks do; values are the median of %d interleaved rounds. Lower is better.\n\n", + o.baseLabel, o.headLabel, res.runs) + + w("| Scenario | base | head | Ī” | p | |\n|---|--:|--:|--:|--:|:-:|\n") + for _, r := range res.rows { + switch r.status { + case statusNew: + w("| `%s` | — | %s | new | | šŸ†• |\n", r.name, summaryCell(wallUnit, r.lone)) + case statusFailed: + w("| `%s` | %s | — | | | āŒ |\n", r.name, summaryCell(wallUnit, r.lone)) + default: + w("| `%s` | %s | %s | %s | %s | %s |\n", r.name, + summaryCell(wallUnit, &r.wall.base), summaryCell(wallUnit, &r.wall.head), + deltaCell(r.wall), fmt.Sprintf("%.3f", r.wall.cmp.P), statusCell(r.status, res.noisy)) + } + } + if o.baseSize > 0 && o.headSize > 0 { + d := float64(o.headSize)/float64(o.baseSize) - 1 + w("\nBinary size: %s → %s (%+.1f%%).\n", fmtBytes(float64(o.baseSize)), fmtBytes(float64(o.headSize)), 100*d) + } + + w("\n
CPU, tail latency and memory\n\n") + w("Per exec, base → head (Ī” when significant).\n\n| Scenario |") + for _, u := range extraUnits { + w(" %s |", u.label) + } + w("\n|---|") + for range extraUnits { + w("--:|") + } + w("\n") + for _, r := range res.rows { + w("| `%s` |", r.name) + for _, u := range extraUnits { + m := r.extra[u.unit] + if !m.ok { + w(" — |") + continue + } + cell := fmtValue(u.unit, m.base.Center) + " → " + fmtValue(u.unit, m.head.Center) + if d := deltaCell(m); d != "~" { + cell += " (" + d + ")" + } + w(" %s |", cell) + } + w("\n") + } + w("\n
\n") + + if o.benchstat != "" { + w("\n
benchstat\n\n```\n%s\n```\n\n
\n", strings.TrimRight(o.benchstat, "\n")) + } + + w("\nĪ” compares medians; ~ means no significant difference (Mann-Whitney U, p ≄ 0.05). "+ + "A scenario is flagged when it is more than %s and more than %s slower with p < 0.05. "+ + "`Startup/floor` runs `true`, not shelltime: it is an A/A check of runner noise.", + pct(o.threshold), o.minDelta) + if env := runnerInfo(res.config); env != "" { + w(" Runner: %s.", env) + } + if o.note != "" { + w(" %s", o.note) + } + w("\n") + return sb.String() +} + +// annotations are GitHub workflow commands, one per flagged scenario. +func (res result) annotations() []string { + var out []string + for _, r := range res.rows { + switch r.status { + case statusSlower: + out = append(out, fmt.Sprintf("::warning title=shelltime track perf::%s is %s slower (%s → %s, p=%.3f)", + r.name, pct(r.wall.delta()), fmtSec(r.wall.base.Center), fmtSec(r.wall.head.Center), r.wall.cmp.P)) + case statusFailed: + out = append(out, fmt.Sprintf("::warning title=shelltime track perf::%s has no result on head; its benchmark failed (see the job log)", r.name)) + } + } + return out +} + +func skippedMarkdown(reason string) string { + return fmt.Sprintf("%s\n## ā±ļø `shelltime track` performance\n\nā­ļø %s\n", marker, reason) +} + +func summaryCell(unit string, s *benchmath.Summary) string { + if s == nil { + return "—" + } + return fmtValue(unit, s.Center) + " ±" + s.PctRangeString() +} + +func deltaCell(m metric) string { + if !m.ok { + return "" + } + return m.cmp.FormatDelta(m.base.Center, m.head.Center) +} + +func statusCell(s status, noisy bool) string { + switch s { + case statusSlower: + return "āš ļø" + case statusFaster: + return "šŸš€" + case statusFloor: + if noisy { + return "šŸŽ²" + } + return "A/A" + } + return "āœ…" +} + +func fmtValue(unit string, v float64) string { + switch { + case strings.HasSuffix(unit, "sec/op"): + return fmtSec(v) + case benchunit.ClassOf(unit) == benchunit.Binary: + return fmtBytes(v) + } + return fmt.Sprintf("%.3g", v) +} + +func fmtSec(v float64) string { + switch { + case v >= 1: + return fmt.Sprintf("%.2f s", v) + case v >= 1e-3: + return fmt.Sprintf("%.2f ms", v*1e3) + } + return fmt.Sprintf("%.0f µs", v*1e6) +} + +func fmtBytes(v float64) string { + return fmt.Sprintf("%.1f MiB", v/(1<<20)) +} + +func pct(f float64) string { + return fmt.Sprintf("%.0f%%", 100*math.Abs(f)) +} + +func plural(n int, noun string) string { + if n == 1 { + return "1 " + noun + } + return fmt.Sprintf("%d %ss", n, noun) +} + +func runnerInfo(config map[string]string) string { + var parts []string + if config["goos"] != "" { + parts = append(parts, config["goos"]+"/"+config["goarch"]) + } + if config["cpu"] != "" { + parts = append(parts, config["cpu"]) + } + return strings.Join(parts, ", ") +} diff --git a/perf/cmd/perfreport/report_test.go b/perf/cmd/perfreport/report_test.go new file mode 100644 index 0000000..b5fa515 --- /dev/null +++ b/perf/cmd/perfreport/report_test.go @@ -0,0 +1,129 @@ +package main + +import ( + "bytes" + "flag" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +var update = flag.Bool("update", false, "rewrite testdata/report.golden.md") + +// testdata/{base,head}.txt cover every row status: daemon/pre is 20% slower, +// daemon/post 6% slower (under the threshold), direct/pre 25% faster, +// direct/post-sync 50% slower but by only 0.1 ms, direct/post failed on head +// and direct/new exists only on head. +func TestReportGolden(t *testing.T) { + var stdout bytes.Buffer + md := filepath.Join(t.TempDir(), "report.md") + err := run([]string{ + "-base", "testdata/base.txt", "-head", "testdata/head.txt", + "-base-label", "`main` @ abc1234", "-head-label", "#42 @ def5678", + "-md", md, "-github", "-note", "Go go1.27.1.", + }, &stdout) + if err != nil { + t.Fatal(err) + } + got, err := os.ReadFile(md) + if err != nil { + t.Fatal(err) + } + golden := filepath.Join("testdata", "report.golden.md") + if *update { + if err := os.WriteFile(golden, got, 0o644); err != nil { + t.Fatal(err) + } + } + want, err := os.ReadFile(golden) + if err != nil { + t.Fatal(err) + } + if !bytes.Equal(got, want) { + t.Errorf("report differs from %s (run with -update to accept):\n%s", golden, got) + } + + wantAnnotations := "::warning title=shelltime track perf::Track/daemon/pre is 20% slower (5.99 ms → 7.19 ms, p=0.000)\n" + + "::warning title=shelltime track perf::Track/direct/post has no result on head; its benchmark failed (see the job log)\n" + if stdout.String() != wantAnnotations { + t.Errorf("annotations:\n%s\nwant:\n%s", stdout.String(), wantAnnotations) + } +} + +func TestGithubOutputs(t *testing.T) { + out := filepath.Join(t.TempDir(), "output") + t.Setenv("GITHUB_OUTPUT", out) + md := filepath.Join(t.TempDir(), "report.md") + + if err := run([]string{"-base", "testdata/base.txt", "-head", "testdata/head.txt", "-md", md, "-github"}, &bytes.Buffer{}); err != nil { + t.Fatal(err) + } + if err := run([]string{"-skipped", "Binary unchanged.", "-md", md, "-github"}, &bytes.Buffer{}); err != nil { + t.Fatal(err) + } + got, err := os.ReadFile(out) + if err != nil { + t.Fatal(err) + } + want := "regression=true\nskipped=false\nregression=false\nskipped=true\n" + if string(got) != want { + t.Errorf("GITHUB_OUTPUT = %q, want %q", got, want) + } + report, _ := os.ReadFile(md) + if !strings.HasPrefix(string(report), marker+"\n") || !strings.Contains(string(report), "ā­ļø Binary unchanged.") { + t.Errorf("skipped report = %q", report) + } +} + +func TestRequiresInputs(t *testing.T) { + if err := run([]string{"-base", "testdata/base.txt"}, &bytes.Buffer{}); err == nil { + t.Error("want an error without -head") + } +} + +func TestGate(t *testing.T) { + o := options{threshold: 0.10, minDelta: 250 * time.Microsecond} + series := func(center float64) []float64 { + vs := make([]float64, 10) + for i := range vs { + vs[i] = center * (1 + float64(i-5)/1000) + } + return vs + } + tests := []struct { + name string + base, head []float64 + want status + }{ + {"slower", series(5e-3), series(6e-3), statusSlower}, + {"faster", series(6e-3), series(5e-3), statusFaster}, + {"under threshold", series(5e-3), series(5.4e-3), statusSame}, + {"under min delta", series(200e-6), series(400e-6), statusSame}, + {"not significant", series(5e-3)[:2], series(6e-3)[:2], statusSame}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := gate(newMetric(tt.base, tt.head), o); got != tt.want { + t.Errorf("gate = %v, want %v", got, tt.want) + } + }) + } +} + +func TestNoisyFloor(t *testing.T) { + base := &samples{order: []string{floorName}, values: map[string]map[string][]float64{ + floorName: {wallUnit: {1.00e-3, 1.01e-3, 0.99e-3, 1.02e-3, 1.00e-3, 0.98e-3}}, + }} + head := &samples{order: []string{floorName}, values: map[string]map[string][]float64{ + floorName: {wallUnit: {1.20e-3, 1.21e-3, 1.19e-3, 1.22e-3, 1.20e-3, 1.18e-3}}, + }} + res := compare(base, head, options{threshold: 0.10, minDelta: 250 * time.Microsecond, noise: 0.05}) + if !res.noisy || res.regressions != 0 { + t.Fatalf("noisy = %v, regressions = %d; want a noisy run and no regression from the floor", res.noisy, res.regressions) + } + if h := res.headline(options{threshold: 0.10}); !strings.Contains(h, "noisy") { + t.Errorf("headline %q does not mention noise", h) + } +} diff --git a/perf/cmd/perfreport/testdata/base.txt b/perf/cmd/perfreport/testdata/base.txt new file mode 100644 index 0000000..11ed109 --- /dev/null +++ b/perf/cmd/perfreport/testdata/base.txt @@ -0,0 +1,130 @@ +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1176000 ns/op 1140720 p50-ns/op 1352400 p95-ns/op 17301504 peak-rss-B 529200 sys-ns/op 646800 user-ns/op +BenchmarkStartup/version-4 100 5292000 ns/op 5133240 p50-ns/op 6085800 p95-ns/op 17301504 peak-rss-B 2381400 sys-ns/op 2910600 user-ns/op +BenchmarkTrack/daemon/pre-4 100 5880000 ns/op 5703600 p50-ns/op 6762000 p95-ns/op 17301504 peak-rss-B 2646000 sys-ns/op 3234000 user-ns/op +BenchmarkTrack/daemon/post-4 100 6076000 ns/op 5893720 p50-ns/op 6987400 p95-ns/op 17301504 peak-rss-B 2734200 sys-ns/op 3341800 user-ns/op +BenchmarkTrack/direct/pre-4 100 5488000 ns/op 5323360 p50-ns/op 6311200 p95-ns/op 17301504 peak-rss-B 2469600 sys-ns/op 3018400 user-ns/op +BenchmarkTrack/direct/post-4 100 9212000 ns/op 8935640 p50-ns/op 10593800 p95-ns/op 17301504 peak-rss-B 4145400 sys-ns/op 5066600 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 196000 ns/op 190120 p50-ns/op 225400 p95-ns/op 17301504 peak-rss-B 88200 sys-ns/op 107800 user-ns/op +PASS +ok github.com/malamtime/cli/perf 40.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1215600 ns/op 1179132 p50-ns/op 1397940 p95-ns/op 17301504 peak-rss-B 547020 sys-ns/op 668580 user-ns/op +BenchmarkStartup/version-4 100 5470200 ns/op 5306094 p50-ns/op 6290730 p95-ns/op 17301504 peak-rss-B 2461590 sys-ns/op 3008610 user-ns/op +BenchmarkTrack/daemon/pre-4 100 6078000 ns/op 5895660 p50-ns/op 6989700 p95-ns/op 17301504 peak-rss-B 2735100 sys-ns/op 3342900 user-ns/op +BenchmarkTrack/daemon/post-4 100 6280600 ns/op 6092182 p50-ns/op 7222690 p95-ns/op 17301504 peak-rss-B 2826270 sys-ns/op 3454330 user-ns/op +BenchmarkTrack/direct/pre-4 100 5672800 ns/op 5502616 p50-ns/op 6523720 p95-ns/op 17301504 peak-rss-B 2552760 sys-ns/op 3120040 user-ns/op +BenchmarkTrack/direct/post-4 100 9522200 ns/op 9236534 p50-ns/op 10950530 p95-ns/op 17301504 peak-rss-B 4284990 sys-ns/op 5237210 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 202600 ns/op 196522 p50-ns/op 232990 p95-ns/op 17301504 peak-rss-B 91170 sys-ns/op 111430 user-ns/op +PASS +ok github.com/malamtime/cli/perf 41.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1191600 ns/op 1155852 p50-ns/op 1370340 p95-ns/op 17301504 peak-rss-B 536220 sys-ns/op 655380 user-ns/op +BenchmarkStartup/version-4 100 5362200 ns/op 5201334 p50-ns/op 6166530 p95-ns/op 17301504 peak-rss-B 2412990 sys-ns/op 2949210 user-ns/op +BenchmarkTrack/daemon/pre-4 100 5958000 ns/op 5779260 p50-ns/op 6851700 p95-ns/op 17301504 peak-rss-B 2681100 sys-ns/op 3276900 user-ns/op +BenchmarkTrack/daemon/post-4 100 6156600 ns/op 5971902 p50-ns/op 7080090 p95-ns/op 17301504 peak-rss-B 2770470 sys-ns/op 3386130 user-ns/op +BenchmarkTrack/direct/pre-4 100 5560800 ns/op 5393976 p50-ns/op 6394920 p95-ns/op 17301504 peak-rss-B 2502360 sys-ns/op 3058440 user-ns/op +BenchmarkTrack/direct/post-4 100 9334200 ns/op 9054174 p50-ns/op 10734330 p95-ns/op 17301504 peak-rss-B 4200390 sys-ns/op 5133810 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 198600 ns/op 192642 p50-ns/op 228390 p95-ns/op 17301504 peak-rss-B 89370 sys-ns/op 109230 user-ns/op +PASS +ok github.com/malamtime/cli/perf 42.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1221600 ns/op 1184952 p50-ns/op 1404840 p95-ns/op 17301504 peak-rss-B 549720 sys-ns/op 671880 user-ns/op +BenchmarkStartup/version-4 100 5497200 ns/op 5332284 p50-ns/op 6321780 p95-ns/op 17301504 peak-rss-B 2473740 sys-ns/op 3023460 user-ns/op +BenchmarkTrack/daemon/pre-4 100 6108000 ns/op 5924760 p50-ns/op 7024200 p95-ns/op 17301504 peak-rss-B 2748600 sys-ns/op 3359400 user-ns/op +BenchmarkTrack/daemon/post-4 100 6311600 ns/op 6122252 p50-ns/op 7258340 p95-ns/op 17301504 peak-rss-B 2840220 sys-ns/op 3471380 user-ns/op +BenchmarkTrack/direct/pre-4 100 5700800 ns/op 5529776 p50-ns/op 6555920 p95-ns/op 17301504 peak-rss-B 2565360 sys-ns/op 3135440 user-ns/op +BenchmarkTrack/direct/post-4 100 9569200 ns/op 9282124 p50-ns/op 11004580 p95-ns/op 17301504 peak-rss-B 4306140 sys-ns/op 5263060 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 203600 ns/op 197492 p50-ns/op 234140 p95-ns/op 17301504 peak-rss-B 91620 sys-ns/op 111980 user-ns/op +PASS +ok github.com/malamtime/cli/perf 43.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1200000 ns/op 1164000 p50-ns/op 1380000 p95-ns/op 17301504 peak-rss-B 540000 sys-ns/op 660000 user-ns/op +BenchmarkStartup/version-4 100 5400000 ns/op 5238000 p50-ns/op 6210000 p95-ns/op 17301504 peak-rss-B 2430000 sys-ns/op 2970000 user-ns/op +BenchmarkTrack/daemon/pre-4 100 6000000 ns/op 5820000 p50-ns/op 6900000 p95-ns/op 17301504 peak-rss-B 2700000 sys-ns/op 3300000 user-ns/op +BenchmarkTrack/daemon/post-4 100 6200000 ns/op 6014000 p50-ns/op 7130000 p95-ns/op 17301504 peak-rss-B 2790000 sys-ns/op 3410000 user-ns/op +BenchmarkTrack/direct/pre-4 100 5600000 ns/op 5432000 p50-ns/op 6440000 p95-ns/op 17301504 peak-rss-B 2520000 sys-ns/op 3080000 user-ns/op +BenchmarkTrack/direct/post-4 100 9400000 ns/op 9118000 p50-ns/op 10810000 p95-ns/op 17301504 peak-rss-B 4230000 sys-ns/op 5170000 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 200000 ns/op 194000 p50-ns/op 230000 p95-ns/op 17301504 peak-rss-B 90000 sys-ns/op 110000 user-ns/op +PASS +ok github.com/malamtime/cli/perf 44.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1182000 ns/op 1146540 p50-ns/op 1359300 p95-ns/op 17301504 peak-rss-B 531900 sys-ns/op 650100 user-ns/op +BenchmarkStartup/version-4 100 5319000 ns/op 5159430 p50-ns/op 6116850 p95-ns/op 17301504 peak-rss-B 2393550 sys-ns/op 2925450 user-ns/op +BenchmarkTrack/daemon/pre-4 100 5910000 ns/op 5732700 p50-ns/op 6796500 p95-ns/op 17301504 peak-rss-B 2659500 sys-ns/op 3250500 user-ns/op +BenchmarkTrack/daemon/post-4 100 6107000 ns/op 5923790 p50-ns/op 7023050 p95-ns/op 17301504 peak-rss-B 2748150 sys-ns/op 3358850 user-ns/op +BenchmarkTrack/direct/pre-4 100 5516000 ns/op 5350520 p50-ns/op 6343400 p95-ns/op 17301504 peak-rss-B 2482200 sys-ns/op 3033800 user-ns/op +BenchmarkTrack/direct/post-4 100 9259000 ns/op 8981230 p50-ns/op 10647850 p95-ns/op 17301504 peak-rss-B 4166550 sys-ns/op 5092450 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 197000 ns/op 191090 p50-ns/op 226550 p95-ns/op 17301504 peak-rss-B 88650 sys-ns/op 108350 user-ns/op +PASS +ok github.com/malamtime/cli/perf 45.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1210800 ns/op 1174476 p50-ns/op 1392420 p95-ns/op 17301504 peak-rss-B 544860 sys-ns/op 665940 user-ns/op +BenchmarkStartup/version-4 100 5448600 ns/op 5285142 p50-ns/op 6265890 p95-ns/op 17301504 peak-rss-B 2451870 sys-ns/op 2996730 user-ns/op +BenchmarkTrack/daemon/pre-4 100 6054000 ns/op 5872380 p50-ns/op 6962100 p95-ns/op 17301504 peak-rss-B 2724300 sys-ns/op 3329700 user-ns/op +BenchmarkTrack/daemon/post-4 100 6255800 ns/op 6068126 p50-ns/op 7194170 p95-ns/op 17301504 peak-rss-B 2815110 sys-ns/op 3440690 user-ns/op +BenchmarkTrack/direct/pre-4 100 5650400 ns/op 5480888 p50-ns/op 6497960 p95-ns/op 17301504 peak-rss-B 2542680 sys-ns/op 3107720 user-ns/op +BenchmarkTrack/direct/post-4 100 9484600 ns/op 9200062 p50-ns/op 10907290 p95-ns/op 17301504 peak-rss-B 4268070 sys-ns/op 5216530 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 201800 ns/op 195746 p50-ns/op 232070 p95-ns/op 17301504 peak-rss-B 90810 sys-ns/op 110990 user-ns/op +PASS +ok github.com/malamtime/cli/perf 46.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1195200 ns/op 1159344 p50-ns/op 1374480 p95-ns/op 17301504 peak-rss-B 537840 sys-ns/op 657360 user-ns/op +BenchmarkStartup/version-4 100 5378400 ns/op 5217048 p50-ns/op 6185160 p95-ns/op 17301504 peak-rss-B 2420280 sys-ns/op 2958120 user-ns/op +BenchmarkTrack/daemon/pre-4 100 5976000 ns/op 5796720 p50-ns/op 6872400 p95-ns/op 17301504 peak-rss-B 2689200 sys-ns/op 3286800 user-ns/op +BenchmarkTrack/daemon/post-4 100 6175200 ns/op 5989944 p50-ns/op 7101480 p95-ns/op 17301504 peak-rss-B 2778840 sys-ns/op 3396360 user-ns/op +BenchmarkTrack/direct/pre-4 100 5577600 ns/op 5410272 p50-ns/op 6414240 p95-ns/op 17301504 peak-rss-B 2509920 sys-ns/op 3067680 user-ns/op +BenchmarkTrack/direct/post-4 100 9362400 ns/op 9081528 p50-ns/op 10766760 p95-ns/op 17301504 peak-rss-B 4213080 sys-ns/op 5149320 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 199200 ns/op 193224 p50-ns/op 229080 p95-ns/op 17301504 peak-rss-B 89640 sys-ns/op 109560 user-ns/op +PASS +ok github.com/malamtime/cli/perf 47.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1219200 ns/op 1182624 p50-ns/op 1402080 p95-ns/op 17301504 peak-rss-B 548640 sys-ns/op 670560 user-ns/op +BenchmarkStartup/version-4 100 5486400 ns/op 5321808 p50-ns/op 6309360 p95-ns/op 17301504 peak-rss-B 2468880 sys-ns/op 3017520 user-ns/op +BenchmarkTrack/daemon/pre-4 100 6096000 ns/op 5913120 p50-ns/op 7010400 p95-ns/op 17301504 peak-rss-B 2743200 sys-ns/op 3352800 user-ns/op +BenchmarkTrack/daemon/post-4 100 6299200 ns/op 6110224 p50-ns/op 7244080 p95-ns/op 17301504 peak-rss-B 2834640 sys-ns/op 3464560 user-ns/op +BenchmarkTrack/direct/pre-4 100 5689600 ns/op 5518912 p50-ns/op 6543040 p95-ns/op 17301504 peak-rss-B 2560320 sys-ns/op 3129280 user-ns/op +BenchmarkTrack/direct/post-4 100 9550400 ns/op 9263888 p50-ns/op 10982960 p95-ns/op 17301504 peak-rss-B 4297680 sys-ns/op 5252720 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 203200 ns/op 197104 p50-ns/op 233680 p95-ns/op 17301504 peak-rss-B 91440 sys-ns/op 111760 user-ns/op +PASS +ok github.com/malamtime/cli/perf 48.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1186800 ns/op 1151196 p50-ns/op 1364820 p95-ns/op 17301504 peak-rss-B 534060 sys-ns/op 652740 user-ns/op +BenchmarkStartup/version-4 100 5340600 ns/op 5180382 p50-ns/op 6141690 p95-ns/op 17301504 peak-rss-B 2403270 sys-ns/op 2937330 user-ns/op +BenchmarkTrack/daemon/pre-4 100 5934000 ns/op 5755980 p50-ns/op 6824100 p95-ns/op 17301504 peak-rss-B 2670300 sys-ns/op 3263700 user-ns/op +BenchmarkTrack/daemon/post-4 100 6131800 ns/op 5947846 p50-ns/op 7051570 p95-ns/op 17301504 peak-rss-B 2759310 sys-ns/op 3372490 user-ns/op +BenchmarkTrack/direct/pre-4 100 5538400 ns/op 5372248 p50-ns/op 6369160 p95-ns/op 17301504 peak-rss-B 2492280 sys-ns/op 3046120 user-ns/op +BenchmarkTrack/direct/post-4 100 9296600 ns/op 9017702 p50-ns/op 10691090 p95-ns/op 17301504 peak-rss-B 4183470 sys-ns/op 5113130 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 197800 ns/op 191866 p50-ns/op 227470 p95-ns/op 17301504 peak-rss-B 89010 sys-ns/op 108790 user-ns/op +PASS +ok github.com/malamtime/cli/perf 49.123s diff --git a/perf/cmd/perfreport/testdata/head.txt b/perf/cmd/perfreport/testdata/head.txt new file mode 100644 index 0000000..bafd93c --- /dev/null +++ b/perf/cmd/perfreport/testdata/head.txt @@ -0,0 +1,130 @@ +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1176000 ns/op 1140720 p50-ns/op 1352400 p95-ns/op 17301504 peak-rss-B 529200 sys-ns/op 646800 user-ns/op +BenchmarkStartup/version-4 100 5344920 ns/op 5184572 p50-ns/op 6146658 p95-ns/op 17474519 peak-rss-B 2405214 sys-ns/op 2939706 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7056000 ns/op 6844320 p50-ns/op 8114400 p95-ns/op 20761805 peak-rss-B 3175200 sys-ns/op 3880800 user-ns/op +BenchmarkTrack/daemon/post-4 100 6440560 ns/op 6247343 p50-ns/op 7406644 p95-ns/op 18339594 peak-rss-B 2898252 sys-ns/op 3542308 user-ns/op +BenchmarkTrack/direct/pre-4 100 4116000 ns/op 3992520 p50-ns/op 4733400 p95-ns/op 12976128 peak-rss-B 1852200 sys-ns/op 2263800 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 294000 ns/op 285180 p50-ns/op 338100 p95-ns/op 25952256 peak-rss-B 132300 sys-ns/op 161700 user-ns/op +BenchmarkTrack/direct/new-4 100 2940000 ns/op 2851800 p50-ns/op 3381000 p95-ns/op 17301504 peak-rss-B 1323000 sys-ns/op 1617000 user-ns/op +PASS +ok github.com/malamtime/cli/perf 40.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1215600 ns/op 1179132 p50-ns/op 1397940 p95-ns/op 17301504 peak-rss-B 547020 sys-ns/op 668580 user-ns/op +BenchmarkStartup/version-4 100 5524902 ns/op 5359155 p50-ns/op 6353637 p95-ns/op 17474519 peak-rss-B 2486206 sys-ns/op 3038696 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7293600 ns/op 7074792 p50-ns/op 8387640 p95-ns/op 20761805 peak-rss-B 3282120 sys-ns/op 4011480 user-ns/op +BenchmarkTrack/daemon/post-4 100 6657436 ns/op 6457713 p50-ns/op 7656051 p95-ns/op 18339594 peak-rss-B 2995846 sys-ns/op 3661590 user-ns/op +BenchmarkTrack/direct/pre-4 100 4254600 ns/op 4126962 p50-ns/op 4892790 p95-ns/op 12976128 peak-rss-B 1914570 sys-ns/op 2340030 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 303900 ns/op 294783 p50-ns/op 349485 p95-ns/op 25952256 peak-rss-B 136755 sys-ns/op 167145 user-ns/op +BenchmarkTrack/direct/new-4 100 3039000 ns/op 2947830 p50-ns/op 3494850 p95-ns/op 17301504 peak-rss-B 1367550 sys-ns/op 1671450 user-ns/op +PASS +ok github.com/malamtime/cli/perf 41.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1191600 ns/op 1155852 p50-ns/op 1370340 p95-ns/op 17301504 peak-rss-B 536220 sys-ns/op 655380 user-ns/op +BenchmarkStartup/version-4 100 5415822 ns/op 5253347 p50-ns/op 6228195 p95-ns/op 17474519 peak-rss-B 2437120 sys-ns/op 2978702 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7149600 ns/op 6935112 p50-ns/op 8222040 p95-ns/op 20761805 peak-rss-B 3217320 sys-ns/op 3932280 user-ns/op +BenchmarkTrack/daemon/post-4 100 6525996 ns/op 6330216 p50-ns/op 7504895 p95-ns/op 18339594 peak-rss-B 2936698 sys-ns/op 3589298 user-ns/op +BenchmarkTrack/direct/pre-4 100 4170600 ns/op 4045482 p50-ns/op 4796190 p95-ns/op 12976128 peak-rss-B 1876770 sys-ns/op 2293830 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 297900 ns/op 288963 p50-ns/op 342585 p95-ns/op 25952256 peak-rss-B 134055 sys-ns/op 163845 user-ns/op +BenchmarkTrack/direct/new-4 100 2979000 ns/op 2889630 p50-ns/op 3425850 p95-ns/op 17301504 peak-rss-B 1340550 sys-ns/op 1638450 user-ns/op +PASS +ok github.com/malamtime/cli/perf 42.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1221600 ns/op 1184952 p50-ns/op 1404840 p95-ns/op 17301504 peak-rss-B 549720 sys-ns/op 671880 user-ns/op +BenchmarkStartup/version-4 100 5552172 ns/op 5385607 p50-ns/op 6384998 p95-ns/op 17474519 peak-rss-B 2498477 sys-ns/op 3053695 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7329600 ns/op 7109712 p50-ns/op 8429040 p95-ns/op 20761805 peak-rss-B 3298320 sys-ns/op 4031280 user-ns/op +BenchmarkTrack/daemon/post-4 100 6690296 ns/op 6489587 p50-ns/op 7693840 p95-ns/op 18339594 peak-rss-B 3010633 sys-ns/op 3679663 user-ns/op +BenchmarkTrack/direct/pre-4 100 4275600 ns/op 4147332 p50-ns/op 4916940 p95-ns/op 12976128 peak-rss-B 1924020 sys-ns/op 2351580 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 305400 ns/op 296238 p50-ns/op 351210 p95-ns/op 25952256 peak-rss-B 137430 sys-ns/op 167970 user-ns/op +BenchmarkTrack/direct/new-4 100 3054000 ns/op 2962380 p50-ns/op 3512100 p95-ns/op 17301504 peak-rss-B 1374300 sys-ns/op 1679700 user-ns/op +PASS +ok github.com/malamtime/cli/perf 43.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1200000 ns/op 1164000 p50-ns/op 1380000 p95-ns/op 17301504 peak-rss-B 540000 sys-ns/op 660000 user-ns/op +BenchmarkStartup/version-4 100 5454000 ns/op 5290380 p50-ns/op 6272100 p95-ns/op 17474519 peak-rss-B 2454300 sys-ns/op 2999700 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7200000 ns/op 6984000 p50-ns/op 8280000 p95-ns/op 20761805 peak-rss-B 3240000 sys-ns/op 3960000 user-ns/op +BenchmarkTrack/daemon/post-4 100 6572000 ns/op 6374840 p50-ns/op 7557800 p95-ns/op 18339594 peak-rss-B 2957400 sys-ns/op 3614600 user-ns/op +BenchmarkTrack/direct/pre-4 100 4200000 ns/op 4074000 p50-ns/op 4830000 p95-ns/op 12976128 peak-rss-B 1890000 sys-ns/op 2310000 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 300000 ns/op 291000 p50-ns/op 345000 p95-ns/op 25952256 peak-rss-B 135000 sys-ns/op 165000 user-ns/op +BenchmarkTrack/direct/new-4 100 3000000 ns/op 2910000 p50-ns/op 3450000 p95-ns/op 17301504 peak-rss-B 1350000 sys-ns/op 1650000 user-ns/op +PASS +ok github.com/malamtime/cli/perf 44.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1182000 ns/op 1146540 p50-ns/op 1359300 p95-ns/op 17301504 peak-rss-B 531900 sys-ns/op 650100 user-ns/op +BenchmarkStartup/version-4 100 5372190 ns/op 5211024 p50-ns/op 6178018 p95-ns/op 17474519 peak-rss-B 2417486 sys-ns/op 2954705 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7092000 ns/op 6879240 p50-ns/op 8155800 p95-ns/op 20761805 peak-rss-B 3191400 sys-ns/op 3900600 user-ns/op +BenchmarkTrack/daemon/post-4 100 6473420 ns/op 6279217 p50-ns/op 7444433 p95-ns/op 18339594 peak-rss-B 2913039 sys-ns/op 3560381 user-ns/op +BenchmarkTrack/direct/pre-4 100 4137000 ns/op 4012890 p50-ns/op 4757550 p95-ns/op 12976128 peak-rss-B 1861650 sys-ns/op 2275350 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 295500 ns/op 286635 p50-ns/op 339825 p95-ns/op 25952256 peak-rss-B 132975 sys-ns/op 162525 user-ns/op +BenchmarkTrack/direct/new-4 100 2955000 ns/op 2866350 p50-ns/op 3398250 p95-ns/op 17301504 peak-rss-B 1329750 sys-ns/op 1625250 user-ns/op +PASS +ok github.com/malamtime/cli/perf 45.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1210800 ns/op 1174476 p50-ns/op 1392420 p95-ns/op 17301504 peak-rss-B 544860 sys-ns/op 665940 user-ns/op +BenchmarkStartup/version-4 100 5503086 ns/op 5337993 p50-ns/op 6328549 p95-ns/op 17474519 peak-rss-B 2476389 sys-ns/op 3026697 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7264800 ns/op 7046856 p50-ns/op 8354520 p95-ns/op 20761805 peak-rss-B 3269160 sys-ns/op 3995640 user-ns/op +BenchmarkTrack/daemon/post-4 100 6631148 ns/op 6432214 p50-ns/op 7625820 p95-ns/op 18339594 peak-rss-B 2984017 sys-ns/op 3647131 user-ns/op +BenchmarkTrack/direct/pre-4 100 4237800 ns/op 4110666 p50-ns/op 4873470 p95-ns/op 12976128 peak-rss-B 1907010 sys-ns/op 2330790 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 302700 ns/op 293619 p50-ns/op 348105 p95-ns/op 25952256 peak-rss-B 136215 sys-ns/op 166485 user-ns/op +BenchmarkTrack/direct/new-4 100 3027000 ns/op 2936190 p50-ns/op 3481050 p95-ns/op 17301504 peak-rss-B 1362150 sys-ns/op 1664850 user-ns/op +PASS +ok github.com/malamtime/cli/perf 46.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1195200 ns/op 1159344 p50-ns/op 1374480 p95-ns/op 17301504 peak-rss-B 537840 sys-ns/op 657360 user-ns/op +BenchmarkStartup/version-4 100 5432184 ns/op 5269218 p50-ns/op 6247012 p95-ns/op 17474519 peak-rss-B 2444483 sys-ns/op 2987701 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7171200 ns/op 6956064 p50-ns/op 8246880 p95-ns/op 20761805 peak-rss-B 3227040 sys-ns/op 3944160 user-ns/op +BenchmarkTrack/daemon/post-4 100 6545712 ns/op 6349341 p50-ns/op 7527569 p95-ns/op 18339594 peak-rss-B 2945570 sys-ns/op 3600142 user-ns/op +BenchmarkTrack/direct/pre-4 100 4183200 ns/op 4057704 p50-ns/op 4810680 p95-ns/op 12976128 peak-rss-B 1882440 sys-ns/op 2300760 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 298800 ns/op 289836 p50-ns/op 343620 p95-ns/op 25952256 peak-rss-B 134460 sys-ns/op 164340 user-ns/op +BenchmarkTrack/direct/new-4 100 2988000 ns/op 2898360 p50-ns/op 3436200 p95-ns/op 17301504 peak-rss-B 1344600 sys-ns/op 1643400 user-ns/op +PASS +ok github.com/malamtime/cli/perf 47.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1219200 ns/op 1182624 p50-ns/op 1402080 p95-ns/op 17301504 peak-rss-B 548640 sys-ns/op 670560 user-ns/op +BenchmarkStartup/version-4 100 5541264 ns/op 5375026 p50-ns/op 6372454 p95-ns/op 17474519 peak-rss-B 2493569 sys-ns/op 3047695 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7315200 ns/op 7095744 p50-ns/op 8412480 p95-ns/op 20761805 peak-rss-B 3291840 sys-ns/op 4023360 user-ns/op +BenchmarkTrack/daemon/post-4 100 6677152 ns/op 6476837 p50-ns/op 7678725 p95-ns/op 18339594 peak-rss-B 3004718 sys-ns/op 3672434 user-ns/op +BenchmarkTrack/direct/pre-4 100 4267200 ns/op 4139184 p50-ns/op 4907280 p95-ns/op 12976128 peak-rss-B 1920240 sys-ns/op 2346960 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 304800 ns/op 295656 p50-ns/op 350520 p95-ns/op 25952256 peak-rss-B 137160 sys-ns/op 167640 user-ns/op +BenchmarkTrack/direct/new-4 100 3048000 ns/op 2956560 p50-ns/op 3505200 p95-ns/op 17301504 peak-rss-B 1371600 sys-ns/op 1676400 user-ns/op +PASS +ok github.com/malamtime/cli/perf 48.123s +goos: linux +goarch: amd64 +pkg: github.com/malamtime/cli/perf +cpu: Test CPU @ 2.10GHz +BenchmarkStartup/floor-4 100 1186800 ns/op 1151196 p50-ns/op 1364820 p95-ns/op 17301504 peak-rss-B 534060 sys-ns/op 652740 user-ns/op +BenchmarkStartup/version-4 100 5394006 ns/op 5232186 p50-ns/op 6203107 p95-ns/op 17474519 peak-rss-B 2427303 sys-ns/op 2966703 user-ns/op +BenchmarkTrack/daemon/pre-4 100 7120800 ns/op 6907176 p50-ns/op 8188920 p95-ns/op 20761805 peak-rss-B 3204360 sys-ns/op 3916440 user-ns/op +BenchmarkTrack/daemon/post-4 100 6499708 ns/op 6304717 p50-ns/op 7474664 p95-ns/op 18339594 peak-rss-B 2924869 sys-ns/op 3574839 user-ns/op +BenchmarkTrack/direct/pre-4 100 4153800 ns/op 4029186 p50-ns/op 4776870 p95-ns/op 12976128 peak-rss-B 1869210 sys-ns/op 2284590 user-ns/op +BenchmarkTrack/direct/post-sync-4 100 296700 ns/op 287799 p50-ns/op 341205 p95-ns/op 25952256 peak-rss-B 133515 sys-ns/op 163185 user-ns/op +BenchmarkTrack/direct/new-4 100 2967000 ns/op 2877990 p50-ns/op 3412050 p95-ns/op 17301504 peak-rss-B 1335150 sys-ns/op 1631850 user-ns/op +PASS +ok github.com/malamtime/cli/perf 49.123s diff --git a/perf/cmd/perfreport/testdata/report.golden.md b/perf/cmd/perfreport/testdata/report.golden.md new file mode 100644 index 0000000..75324cc --- /dev/null +++ b/perf/cmd/perfreport/testdata/report.golden.md @@ -0,0 +1,36 @@ + +## ā±ļø `shelltime track` performance + +āš ļø **1 scenario got slower**: more than 10% in wall time Ā· āŒ 1 scenario produced no result on head + +Comparing `main` @ abc1234 → #42 @ def5678. Each scenario execs the binary the way the shell hooks do; values are the median of 10 interleaved rounds. Lower is better. + +| Scenario | base | head | Ī” | p | | +|---|--:|--:|--:|--:|:-:| +| `Startup/floor` | 1.20 ms ±2% | 1.20 ms ±2% | ~ | 1.000 | A/A | +| `Startup/version` | 5.39 ms ±2% | 5.44 ms ±2% | ~ | 0.123 | āœ… | +| `Track/daemon/pre` | 5.99 ms ±2% | 7.19 ms ±2% | +20.00% | 0.000 | āš ļø | +| `Track/daemon/post` | 6.19 ms ±2% | 6.56 ms ±2% | +6.00% | 0.000 | āœ… | +| `Track/direct/pre` | 5.59 ms ±2% | 4.19 ms ±2% | -25.00% | 0.000 | šŸš€ | +| `Track/direct/post-sync` | 200 µs ±2% | 299 µs ±2% | +50.00% | 0.000 | āœ… | +| `Track/direct/new` | — | 2.99 ms ±2% | new | | šŸ†• | +| `Track/direct/post` | 9.38 ms ±2% | — | | | āŒ | + +
CPU, tail latency and memory + +Per exec, base → head (Ī” when significant). + +| Scenario | p95 wall | user CPU | sys CPU | peak RSS | +|---|--:|--:|--:|--:| +| `Startup/floor` | 1.38 ms → 1.38 ms | 659 µs → 659 µs | 539 µs → 539 µs | 16.5 MiB → 16.5 MiB | +| `Startup/version` | 6.20 ms → 6.26 ms | 2.96 ms → 2.99 ms | 2.43 ms → 2.45 ms | 16.5 MiB → 16.7 MiB (+1.00%) | +| `Track/daemon/pre` | 6.89 ms → 8.26 ms (+20.00%) | 3.29 ms → 3.95 ms (+20.00%) | 2.69 ms → 3.23 ms (+20.00%) | 16.5 MiB → 19.8 MiB (+20.00%) | +| `Track/daemon/post` | 7.12 ms → 7.54 ms (+6.00%) | 3.40 ms → 3.61 ms (+6.00%) | 2.78 ms → 2.95 ms (+6.00%) | 16.5 MiB → 17.5 MiB (+6.00%) | +| `Track/direct/pre` | 6.43 ms → 4.82 ms (-25.00%) | 3.07 ms → 2.31 ms (-25.00%) | 2.51 ms → 1.89 ms (-25.00%) | 16.5 MiB → 12.4 MiB (-25.00%) | +| `Track/direct/post-sync` | 230 µs → 344 µs (+50.00%) | 110 µs → 165 µs (+50.00%) | 90 µs → 135 µs (+50.00%) | 16.5 MiB → 24.8 MiB (+50.00%) | +| `Track/direct/new` | — | — | — | — | +| `Track/direct/post` | — | — | — | — | + +
+ +Ī” compares medians; ~ means no significant difference (Mann-Whitney U, p ≄ 0.05). A scenario is flagged when it is more than 10% and more than 250µs slower with p < 0.05. `Startup/floor` runs `true`, not shelltime: it is an A/A check of runner noise. Runner: linux/amd64, Test CPU @ 2.10GHz. Go go1.27.1. diff --git a/perf/comment.sh b/perf/comment.sh new file mode 100755 index 0000000..ae343b5 --- /dev/null +++ b/perf/comment.sh @@ -0,0 +1,29 @@ +#!/usr/bin/env bash +# Create or update the pull request comment that holds the perf report. +# +# perf/comment.sh [--update-only] +# +# The comment is found by the report's first line, a hidden marker, among the +# comments github-actions posted. With --update-only an existing comment is +# refreshed but no new one is created. Needs GH_TOKEN and GITHUB_REPOSITORY, +# which Actions provides. +set -euo pipefail + +usage="usage: perf/comment.sh [--update-only]" +pr=${1:?$usage} +report=${2:?$usage} +mode=${3:-} +repo=${GITHUB_REPOSITORY:?GITHUB_REPOSITORY is not set} + +marker=$(head -n 1 "$report") +id=$(gh api --paginate "repos/$repo/issues/$pr/comments" \ + --jq ".[] | select(.user.login == \"github-actions[bot]\" and (.body | startswith(\"$marker\"))) | .id" | + tail -n 1) + +if [[ -n $id ]]; then + gh api --method PATCH "repos/$repo/issues/comments/$id" -F body=@"$report" >/dev/null + echo "updated comment $id" +elif [[ $mode != --update-only ]]; then + gh api --method POST "repos/$repo/issues/$pr/comments" -F body=@"$report" >/dev/null + echo "posted a new comment" +fi diff --git a/perf/compare.sh b/perf/compare.sh new file mode 100755 index 0000000..cb319d7 --- /dev/null +++ b/perf/compare.sh @@ -0,0 +1,115 @@ +#!/usr/bin/env bash +# Compare `shelltime track` latency between two commits, the way CI does. +# +# perf/compare.sh [head-ref|WORKTREE] [outdir] +# +# Builds both binaries with identical flags, runs one harness (from this +# checkout) against both in interleaved rounds on the same machine, and writes +# /report.md. The head defaults to WORKTREE: the checkout as it is, +# uncommitted changes included. +# +# Environment: +# ROUNDS interleaved rounds per binary (10) +# ITERS execs per scenario per round (100) +# THRESHOLD percent slowdown that flags a scenario (10) +# FORCE=1 compare even when the two binaries are byte-identical +# BASE_LABEL, HEAD_LABEL how the report names the two sides +set -euo pipefail + +usage="usage: perf/compare.sh [head-ref|WORKTREE] [outdir]" +base_ref=${1:?$usage} +head_ref=${2:-WORKTREE} +root=$(git rev-parse --show-toplevel) +out=${3:-$(mktemp -d "${TMPDIR:-/tmp}/shelltime-perf.XXXXXX")} +rounds=${ROUNDS:-10} +iters=${ITERS:-100} + +mkdir -p "$out" +out=$(cd "$out" && pwd) +rm -rf "$out/a" "$out/b" +rm -f "$out"/{a.txt,b.txt,round.txt,benchstat.txt,base-build.log,report.md,perf.test} + +scratch=$(mktemp -d "${TMPDIR:-/tmp}/shelltime-perf-src.XXXXXX") +cleanup() { + for wt in "$scratch"/*/; do + [[ -d $wt ]] && git -C "$root" worktree remove --force "$wt" >/dev/null 2>&1 || true + done + rm -rf "$scratch" + git -C "$root" worktree prune +} +trap cleanup EXIT + +# checkout : a detached worktree of ref, printed as a path. +checkout() { + local sha + sha=$(git -C "$root" rev-parse --verify "$1^{commit}") + git -C "$root" worktree add --detach --quiet "$scratch/$2" "$sha" + echo "$scratch/$2" +} + +# build : the CLI with release-like flags. -trimpath and +# -buildvcs=false keep the checkout path and VCS stamp out of the binary, so +# identical code gives byte-identical binaries. +build() { + (cd "$1" && CGO_ENABLED=0 go build -trimpath -buildvcs=false \ + -ldflags "-s -w -X main.version=perf" -o "$2" ./cmd/cli) +} + +report() { + go -C "$root/perf" run ./cmd/perfreport -md "$out/report.md" ${GITHUB_ACTIONS:+-github} "$@" +} + +base_sha=$(git -C "$root" rev-parse --short=7 --verify "$base_ref^{commit}") +if [[ $head_ref == WORKTREE ]]; then + head_src=$root + head_desc="the working tree" +else + head_src=$(checkout "$head_ref" head) + head_desc=$(git -C "$root" rev-parse --short=7 --verify "$head_ref^{commit}") +fi +base_label=${BASE_LABEL:-\`$base_sha\`} +head_label=${HEAD_LABEL:-$head_desc} + +echo "building head ($head_desc) and base ($base_sha)" +build "$head_src" "$out/b/shelltime" +base_src=$(checkout "$base_ref" base) +if ! build "$base_src" "$out/a/shelltime" 2>"$out/base-build.log"; then + cat "$out/base-build.log" >&2 + report -skipped "The base commit $base_label does not build, so there is nothing to compare against." + echo "report: $out/report.md" + exit 0 +fi + +if [[ ${FORCE:-0} != 1 ]] && cmp -s "$out/a/shelltime" "$out/b/shelltime"; then + report -skipped "The \`shelltime\` binary is byte-identical to $base_label, so its performance cannot have changed." + echo "report: $out/report.md" + exit 0 +fi + +# One harness, built from this checkout, measures both binaries. +go -C "$root/perf" test -c -o "$out/perf.test" . + +for ((i = 1; i <= rounds; i++)); do + # ABBA order, so neither side always runs first. + if ((i % 2)); then order="a b"; else order="b a"; fi + for side in $order; do + echo "round $i/$rounds: $([[ $side == a ]] && echo base || echo head)" + if ! SHELLTIME_BENCH_BIN="$out/$side/shelltime" "$out/perf.test" \ + -test.run='^$' -test.bench=. -test.benchtime="${iters}x" -test.count=1 \ + -test.timeout=20m >"$out/round.txt" 2>&1; then + # A failed scenario only loses its own result; show why. + grep -v '^Benchmark' "$out/round.txt" >&2 || true + fi + cat "$out/round.txt" >>"$out/$side.txt" + done +done +rm -f "$out/round.txt" + +(cd "$root/perf" && go tool benchstat base="$out/a.txt" head="$out/b.txt") >"$out/benchstat.txt" 2>&1 || true + +report -base "$out/a.txt" -head "$out/b.txt" \ + -base-bin "$out/a/shelltime" -head-bin "$out/b/shelltime" \ + -benchstat "$out/benchstat.txt" -threshold "${THRESHOLD:-10}" \ + -base-label "$base_label" -head-label "$head_label" \ + -note "$(go env GOVERSION), $rounds rounds Ɨ $iters execs per scenario and binary." +echo "report: $out/report.md" diff --git a/perf/doc.go b/perf/doc.go new file mode 100644 index 0000000..805186e --- /dev/null +++ b/perf/doc.go @@ -0,0 +1,20 @@ +// Package perf benchmarks the latency of the real `shelltime` binary. +// +// `shelltime track` runs in the foreground of every shell prompt (see +// model/hooks), so what users feel is the whole process: exec, Go runtime and +// package init, config read, then the track logic. The benchmarks here exec a +// built binary per iteration, in an isolated $HOME, the same way the hooks do. +// +// This is a separate module so its tooling dependencies (golang.org/x/perf) +// never take part in version selection for the shipped CLI and daemon. +// +// Run against the current tree: +// +// go -C perf test -run '^$' -bench . -benchtime 50x -count 5 +// +// Compare two commits the way CI does: +// +// perf/compare.sh origin/main +// +// See perf/README.md for the scenarios and how the report is read. +package perf diff --git a/perf/go.mod b/perf/go.mod new file mode 100644 index 0000000..b7fe4d7 --- /dev/null +++ b/perf/go.mod @@ -0,0 +1,9 @@ +module github.com/malamtime/cli/perf + +go 1.27.1 + +tool golang.org/x/perf/cmd/benchstat + +require golang.org/x/perf v0.0.0-20260929162123-406019bb8b68 + +require github.com/aclements/go-moremath v0.0.0-20210112150236-f10218a38794 // indirect diff --git a/perf/go.sum b/perf/go.sum new file mode 100644 index 0000000..79c901f --- /dev/null +++ b/perf/go.sum @@ -0,0 +1,4 @@ +github.com/aclements/go-moremath v0.0.0-20210112150236-f10218a38794 h1:xlwdaKcTNVW4PtpQb8aKA4Pjy0CdJHEqvFbAnvR5m2g= +github.com/aclements/go-moremath v0.0.0-20210112150236-f10218a38794/go.mod h1:7e+I0LQFUI9AXWxOfsQROs9xPhoJtbsyWcjJqDd4KPY= +golang.org/x/perf v0.0.0-20260929162123-406019bb8b68 h1:nyQ/b4GTH65GoH7T/JFxssBadcBB57DTy6JNyQEfZBA= +golang.org/x/perf v0.0.0-20260929162123-406019bb8b68/go.mod h1:Pth32a9JhKKavemj73LtFqHHyyMhqz+K7tUZcG5tTWM= diff --git a/perf/harness_test.go b/perf/harness_test.go new file mode 100644 index 0000000..705b435 --- /dev/null +++ b/perf/harness_test.go @@ -0,0 +1,583 @@ +//go:build unix + +package perf + +import ( + "bufio" + "bytes" + "encoding/json" + "errors" + "fmt" + "io" + "net" + "net/http" + "net/http/httptest" + "os" + "os/exec" + "path/filepath" + "runtime" + "slices" + "strconv" + "strings" + "sync" + "sync/atomic" + "syscall" + "testing" + "time" +) + +// daemonSocket mirrors model.DefaultSocketPath. track's fast path stats this +// fixed path, so the fake daemon has to listen exactly here. +const daemonSocket = "/tmp/shelltime.sock" + +// The command every track scenario reports, in the shape the zsh hook sends it +// (model/hooks/zsh.zsh). +const ( + benchUser = "bench" + benchShell = "zsh" + benchSession = int64(1759800000) + benchCommand = "git status --short" + benchPPID = 4242 +) + +const ( + // seedPairs is how many already-synced pre/post pairs sit in the txt store. + // Nothing prunes the store between two `shelltime gc` runs (one per new + // shell), so a busy shell carries a few hundred, and the direct post path + // reads all of them on every command. + seedPairs = 500 + // flushCount is the config's flush threshold. post-sync seeds + // flushCount-1 pending pairs so every measured post triggers a sync. + flushCount = 10 + // maxFixtureBytes keeps each store file well under the 512 KiB scanner + // buffer in model/db.go, past which reading post.txt corrupts lines. + maxFixtureBytes = 400 << 10 + // warmupRuns untimed runs per scenario warm the page cache and the + // sandbox, as on a user's machine where the binary runs every command. + warmupRuns = 5 +) + +// baseConfig is a typical logged-in config. The endpoint is a closed local +// port: if a scenario that must not sync ever does, the request fails, logs an +// error and requireNoErrors fails the benchmark. +const baseConfig = `token: bench-token +apiEndpoint: http://127.0.0.1:9 +flushCount: 10 +` + +var ( + // workDir holds per-process scratch files: the lazily built binary and + // the lsb_release stub. + workDir string + devNull *os.File + + binOnce sync.Once + binPath string + binErr error + + pathOnce sync.Once + childPATH string + pathErr error +) + +func TestMain(m *testing.M) { + os.Exit(func() int { + dir, err := os.MkdirTemp("", "shelltime-perf-") + if err != nil { + fmt.Fprintln(os.Stderr, err) + return 1 + } + defer os.RemoveAll(dir) + workDir = dir + + devNull, err = os.OpenFile(os.DevNull, os.O_RDWR, 0) + if err != nil { + fmt.Fprintln(os.Stderr, err) + return 1 + } + defer devNull.Close() + + return m.Run() + }()) +} + +// shelltimeBin returns the binary under test: $SHELLTIME_BENCH_BIN, or the +// CLI built from this checkout with release-like flags on first use, so a +// plain `go test` that runs no benchmark never pays for the build. +func shelltimeBin(b *testing.B) string { + b.Helper() + binOnce.Do(func() { + if p := os.Getenv("SHELLTIME_BENCH_BIN"); p != "" { + if binPath, binErr = filepath.Abs(p); binErr == nil { + _, binErr = os.Stat(binPath) + } + return + } + root, err := repoRoot() + if err != nil { + binErr = err + return + } + binPath = filepath.Join(workDir, "shelltime") + cmd := exec.Command("go", "build", "-trimpath", "-buildvcs=false", + "-ldflags", "-s -w -X main.version=perf", "-o", binPath, "./cmd/cli") + cmd.Dir = root + cmd.Env = append(os.Environ(), "CGO_ENABLED=0") + if out, err := cmd.CombinedOutput(); err != nil { + binErr = fmt.Errorf("build shelltime: %v\n%s", err, out) + } + }) + if binErr != nil { + b.Fatal(binErr) + } + return binPath +} + +// repoRoot is the CLI module this module sits in. +func repoRoot() (string, error) { + root, err := filepath.Abs("..") + if err != nil { + return "", err + } + data, err := os.ReadFile(filepath.Join(root, "go.mod")) + if err != nil { + return "", err + } + for line := range strings.Lines(string(data)) { + if strings.TrimSpace(line) == "module github.com/malamtime/cli" { + return root, nil + } + } + return "", fmt.Errorf("%s is not the shelltime CLI module; set SHELLTIME_BENCH_BIN", root) +} + +// childPath is the PATH the binary runs with. On Linux the direct post path +// execs `lsb_release -a` (model.GetOSAndVersion), which is a Python script on +// Ubuntu: tens of noisy milliseconds that would bury any change in shelltime +// itself. A shell stub with the same output keeps the exec but not the noise. +// SHELLTIME_BENCH_REAL_OSINFO=1 measures the real one. +func childPath(b *testing.B) string { + b.Helper() + pathOnce.Do(func() { + childPATH = os.Getenv("PATH") + if runtime.GOOS != "linux" || os.Getenv("SHELLTIME_BENCH_REAL_OSINFO") != "" { + return + } + stubDir := filepath.Join(workDir, "stub") + if pathErr = os.MkdirAll(stubDir, 0o755); pathErr != nil { + return + } + stub := "#!/bin/sh\nprintf 'Distributor ID:\\tUbuntu\\nDescription:\\tUbuntu 24.04 LTS\\nRelease:\\t24.04\\nCodename:\\tnoble\\n'\n" + pathErr = os.WriteFile(filepath.Join(stubDir, "lsb_release"), []byte(stub), 0o755) + childPATH = stubDir + string(os.PathListSeparator) + childPATH + }) + if pathErr != nil { + b.Fatal(pathErr) + } + return childPATH +} + +// sandbox is an isolated $HOME with a .shelltime/config.yaml. +type sandbox struct { + b *testing.B + bin string + home string + env []string +} + +func newSandbox(b *testing.B, bin, config string) *sandbox { + b.Helper() + home := b.TempDir() + s := &sandbox{ + b: b, + bin: bin, + home: home, + env: []string{"HOME=" + home, "USER=" + benchUser, "PATH=" + childPath(b), "LANG=C"}, + } + if config != "" { + if err := os.MkdirAll(s.path("commands"), 0o755); err != nil { + b.Fatal(err) + } + if err := os.WriteFile(s.path("config.yaml"), []byte(config), 0o644); err != nil { + b.Fatal(err) + } + } + return s +} + +// path joins elem under the sandbox's ~/.shelltime. +func (s *sandbox) path(elem ...string) string { + return filepath.Join(append([]string{s.home, ".shelltime"}, elem...)...) +} + +type runStat struct { + wall, user, sys time.Duration + rss int64 // peak resident set, bytes +} + +// run execs the binary once with stdio on /dev/null, like the hooks' &>/dev/null. +func (s *sandbox) run(args ...string) runStat { + cmd := exec.Command(s.bin, args...) + cmd.Env = s.env + cmd.Dir = s.home + cmd.Stdin, cmd.Stdout, cmd.Stderr = devNull, devNull, devNull + start := time.Now() + err := cmd.Run() + wall := time.Since(start) + if err != nil { + s.b.Fatalf("%s %s: %v", filepath.Base(s.bin), strings.Join(args, " "), err) + } + st := runStat{wall: wall, user: cmd.ProcessState.UserTime(), sys: cmd.ProcessState.SystemTime()} + if ru, ok := cmd.ProcessState.SysUsage().(*syscall.Rusage); ok { + st.rss = int64(ru.Maxrss) + if runtime.GOOS != "darwin" { // Linux reports KiB, macOS bytes. + st.rss *= 1024 + } + } + return st +} + +// requireNoErrors fails the benchmark if the CLI logged an error. track exits 0 +// whatever happens, so a run that broke early would otherwise just look fast. +func (s *sandbox) requireNoErrors() { + s.b.Helper() + f, err := os.Open(s.path("log.log")) + if errors.Is(err, os.ErrNotExist) { + return + } + if err != nil { + s.b.Fatal(err) + } + defer f.Close() + sc := bufio.NewScanner(f) + sc.Buffer(nil, 1<<20) + for sc.Scan() { + if strings.Contains(sc.Text(), "level=ERROR") { + s.b.Fatalf("shelltime logged an error: %s", sc.Text()) + } + } +} + +// measure does warmupRuns untimed runs, then times one exec per iteration. +// reset, if set, runs before every exec with the timer stopped, so cost does +// not drift as the store grows. It returns the total number of execs. +func measure(b *testing.B, reset func(), run func() runStat) int { + b.Helper() + for range warmupRuns { + if reset != nil { + reset() + } + run() + } + var stats []runStat + for b.Loop() { + if reset != nil { + b.StopTimer() + reset() + b.StartTimer() + } + stats = append(stats, run()) + } + report(b, stats) + return warmupRuns + len(stats) +} + +// report adds per-exec CPU time, wall-time percentiles and peak RSS next to +// ns/op. These are the child's numbers, which is why -benchmem is not used: +// it would measure the harness. +func report(b *testing.B, stats []runStat) { + if len(stats) == 0 { + return + } + n := float64(len(stats)) + walls := make([]time.Duration, len(stats)) + var user, sys time.Duration + var rss int64 + for i, st := range stats { + walls[i] = st.wall + user += st.user + sys += st.sys + rss += st.rss + } + slices.Sort(walls) + pct := func(p float64) float64 { + return float64(walls[int(p*float64(len(walls)-1))].Nanoseconds()) + } + b.ReportMetric(float64(user.Nanoseconds())/n, "user-ns/op") + b.ReportMetric(float64(sys.Nanoseconds())/n, "sys-ns/op") + b.ReportMetric(pct(0.50), "p50-ns/op") + b.ReportMetric(pct(0.95), "p95-ns/op") + b.ReportMetric(float64(rss)/n, "peak-rss-B") +} + +// trackArgs is a hook call: model/hooks/zsh.zsh passes exactly these flags. +func trackArgs(phase string) []string { + args := []string{"track", "-s=" + benchShell, "-id=" + strconv.FormatInt(benchSession, 10), + "-cmd=" + benchCommand, "-p=" + phase, "--ppid=" + strconv.Itoa(benchPPID)} + if phase == "post" { + args = append(args, "-r=0") + } + return args +} + +// requireNoDaemon skips while something owns the daemon socket: a real daemon +// would receive the fake commands, and the direct scenarios would take the +// daemon fast path. A stale socket file left by a dead daemon is removed. +func requireNoDaemon(b *testing.B) { + b.Helper() + if _, err := os.Lstat(daemonSocket); errors.Is(err, os.ErrNotExist) { + return + } + if conn, err := net.DialTimeout("unix", daemonSocket, 50*time.Millisecond); err == nil { + conn.Close() + b.Skipf("a shelltime daemon is listening on %s; stop it to run the track benchmarks", daemonSocket) + } + if err := os.Remove(daemonSocket); err != nil { + b.Skipf("cannot remove stale %s: %v", daemonSocket, err) + } +} + +// fakeDaemon accepts on the daemon socket, reads each message to EOF (the CLI +// writes one JSON message and closes) and counts the track events it gets. +type fakeDaemon struct { + ln *net.UnixListener + served chan struct{} + conns sync.WaitGroup + + mu sync.Mutex + events map[string]int // by message type; "invalid" for anything unexpected +} + +func startFakeDaemon(b *testing.B) *fakeDaemon { + b.Helper() + requireNoDaemon(b) + ln, err := net.ListenUnix("unix", &net.UnixAddr{Name: daemonSocket, Net: "unix"}) + if err != nil { + b.Fatalf("listen on %s: %v", daemonSocket, err) + } + d := &fakeDaemon{ln: ln, served: make(chan struct{}), events: map[string]int{}} + go d.serve() + b.Cleanup(func() { + ln.Close() // also unlinks the socket file + <-d.served + d.conns.Wait() + }) + return d +} + +func (d *fakeDaemon) serve() { + defer close(d.served) + for { + conn, err := d.ln.Accept() + if err != nil { + return + } + d.conns.Add(1) + go func() { + defer d.conns.Done() + defer conn.Close() + conn.SetDeadline(time.Now().Add(5 * time.Second)) + data, _ := io.ReadAll(conn) + var msg struct { + Type string `json:"type"` + Payload struct { + Command struct { + Cmd string `json:"cmd"` + } `json:"command"` + } `json:"payload"` + } + kind := "invalid" + if json.Unmarshal(data, &msg) == nil && msg.Payload.Command.Cmd == benchCommand { + kind = msg.Type + } + d.mu.Lock() + d.events[kind]++ + d.mu.Unlock() + }() + } +} + +// expect fails unless exactly runs events of msgType, and nothing else, arrived. +func (d *fakeDaemon) expect(b *testing.B, msgType string, runs int) { + b.Helper() + snapshot := func() (got, total int) { + d.mu.Lock() + defer d.mu.Unlock() + for k, n := range d.events { + total += n + if k == msgType { + got = n + } + } + return got, total + } + deadline := time.Now().Add(2 * time.Second) + got, total := snapshot() + for got < runs && time.Now().Before(deadline) { + time.Sleep(5 * time.Millisecond) + got, total = snapshot() + } + if got != runs || total != runs { + b.Fatalf("fake daemon got %d %q events and %d others for %d runs; track did not take the daemon path", + got, msgType, total-got, runs) + } +} + +// fakeAPI stands in for the server's POST /api/v1/track. It answers 204, one +// of the two statuses model.SendHTTPRequestJSON accepts. +type fakeAPI struct { + srv *httptest.Server + syncs atomic.Int64 // batches of exactly flushCount records + unexpects atomic.Int64 +} + +func startFakeAPI(b *testing.B) *fakeAPI { + b.Helper() + a := &fakeAPI{} + a.srv = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + var body struct { + Data []json.RawMessage `json:"data"` + } + if r.Method != http.MethodPost || r.URL.Path != "/api/v1/track" || + json.NewDecoder(r.Body).Decode(&body) != nil || len(body.Data) != flushCount { + a.unexpects.Add(1) + } else { + a.syncs.Add(1) + } + w.WriteHeader(http.StatusNoContent) + })) + b.Cleanup(a.srv.Close) + return a +} + +// storedCommand mirrors the JSON of model.Command, as the txt store holds it. +type storedCommand struct { + Shell string `json:"shell"` + SessionID int64 `json:"sid"` + Command string `json:"cmd"` + Main string `json:"main"` + Hostname string `json:"hn"` + Username string `json:"un"` + Time time.Time `json:"t"` + EndTime time.Time `json:"et"` + Result int `json:"result"` + Phase int `json:"phase"` + PPID int `json:"ppid,omitempty"` +} + +// storeLine mirrors model.Command.ToLine: JSON, a tab, the recording time in +// Unix nanoseconds, a newline. +func storeLine(c storedCommand, recorded time.Time) []byte { + buf, err := json.Marshal(c) + if err != nil { + panic(err) + } + buf = append(buf, '\t') + buf = strconv.AppendInt(buf, recorded.UnixNano(), 10) + return append(buf, '\n') +} + +// seedCommands is the mix the store is seeded with. Commands repeat, as in a +// real history, so the store's per-command groups have many entries. +var seedCommands = []string{ + "ls -la", "git status", "git diff --stat", "go test ./...", "cd ~/projects/shelltime", + "kubectl get pods -n default", "docker ps -a", "vim main.go", "make build", + "curl -H 'Authorization: Bearer abc123' https://example.com/api", "npm run dev", + "rg TODO --type go", "export GITHUB_TOKEN=ghp_xxxxxxxxxxxxxxxxxxxx", "htop", +} + +// storeFixture is a seeded txt store and the state to restore it to. +type storeFixture struct { + s *sandbox + postSize int64 + cursor []byte +} + +// seedStore writes synced pre/post pairs the cursor already covers, then +// pending pairs after it, then an open pre for the benchmark command so each +// measured post has one to pair with. All of it is in the recent past, inside +// the store's ten-day pairing window and before every measured run. +func seedStore(s *sandbox, synced, pending int) storeFixture { + s.b.Helper() + hostname, _ := os.Hostname() + base := time.Now().Add(-6 * time.Hour) + var pre, post bytes.Buffer + var cursor time.Time + at := func(i int) time.Time { return base.Add(time.Duration(i) * 3 * time.Second) } + + for i := range synced + pending { + c := storedCommand{ + Shell: benchShell, + SessionID: benchSession, + Command: seedCommands[i%len(seedCommands)], + Hostname: hostname, + Username: benchUser, + Time: at(i), + PPID: benchPPID, + } + pre.Write(storeLine(c, c.Time)) + + end := c.Time.Add(800 * time.Millisecond) + c.Phase, c.Time, c.EndTime, c.Result = 1, end, end, i%3 + post.Write(storeLine(c, end)) + if i == synced-1 { + // The store re-reads records at the cursor (Before, not + // !After), so it sits just past the last synced one. + cursor = end.Add(time.Nanosecond) + } + } + open := storedCommand{ + Shell: benchShell, SessionID: benchSession, Command: benchCommand, + Hostname: hostname, Username: benchUser, Time: at(synced + pending), PPID: benchPPID, + } + pre.Write(storeLine(open, open.Time)) + + if pre.Len() > maxFixtureBytes || post.Len() > maxFixtureBytes { + s.b.Fatalf("fixture too large (pre %d B, post %d B, limit %d B)", pre.Len(), post.Len(), maxFixtureBytes) + } + f := storeFixture{s: s, postSize: int64(post.Len()), cursor: fmt.Appendf(nil, "\n%d\n", cursor.UnixNano())} + for name, data := range map[string][]byte{"pre.txt": pre.Bytes(), "post.txt": post.Bytes(), "cursor.txt": f.cursor} { + if err := os.WriteFile(s.path("commands", name), data, 0o644); err != nil { + s.b.Fatal(err) + } + } + return f +} + +// check reports whether the last run appended to post.txt and moved the cursor. +func (f storeFixture) check() (postGrew, cursorMoved bool) { + f.s.b.Helper() + st, err := os.Stat(f.s.path("commands", "post.txt")) + if err != nil { + f.s.b.Fatal(err) + } + cursor, err := os.ReadFile(f.s.path("commands", "cursor.txt")) + if err != nil { + f.s.b.Fatal(err) + } + return st.Size() > f.postSize, !bytes.Equal(cursor, f.cursor) +} + +// restore puts post.txt and cursor.txt back to their seeded state. +func (f storeFixture) restore() { + f.s.b.Helper() + if err := os.Truncate(f.s.path("commands", "post.txt"), f.postSize); err != nil { + f.s.b.Fatal(err) + } + if err := os.WriteFile(f.s.path("commands", "cursor.txt"), f.cursor, 0o644); err != nil { + f.s.b.Fatal(err) + } +} + +// countLines counts newline-terminated lines in the file at path. +func countLines(b *testing.B, path string) int { + b.Helper() + data, err := os.ReadFile(path) + if errors.Is(err, os.ErrNotExist) { + return 0 + } + if err != nil { + b.Fatal(err) + } + return bytes.Count(data, []byte{'\n'}) +} diff --git a/perf/track_bench_test.go b/perf/track_bench_test.go new file mode 100644 index 0000000..7dffe45 --- /dev/null +++ b/perf/track_bench_test.go @@ -0,0 +1,109 @@ +//go:build unix + +package perf + +import ( + "os/exec" + "testing" +) + +// BenchmarkStartup is the baseline the track numbers sit on. +func BenchmarkStartup(b *testing.B) { + // floor is a trivial binary: the runner's own fork/exec cost. It does not + // depend on the binary under test, so a base/head difference here means + // the run was noisy (an A/A check the report uses). + b.Run("floor", func(b *testing.B) { + bin, err := exec.LookPath("true") + if err != nil { + b.Skip(err) + } + s := newSandbox(b, bin, "") + measure(b, nil, func() runStat { return s.run() }) + }) + + // version is process start, package init and main's config read and + // telemetry setup, with no command logic. + b.Run("version", func(b *testing.B) { + s := newSandbox(b, shelltimeBin(b), baseConfig) + measure(b, nil, func() runStat { return s.run("--version") }) + s.requireNoErrors() + }) +} + +// BenchmarkTrack is `shelltime track` as the shell hooks run it, once before +// (pre) and once after (post) every command. +func BenchmarkTrack(b *testing.B) { + // daemon: the default install. The daemon is listening, so track hands + // it the event over the socket and returns. + b.Run("daemon", func(b *testing.B) { + for _, phase := range []string{"pre", "post"} { + b.Run(phase, func(b *testing.B) { + s := newSandbox(b, shelltimeBin(b), baseConfig) + d := startFakeDaemon(b) + runs := measure(b, nil, func() runStat { return s.run(trackArgs(phase)...) }) + d.expect(b, "track_"+phase, runs) + s.requireNoErrors() + }) + } + }) + + // direct: no daemon. track writes the txt store itself, and on post reads + // the whole store to decide whether to sync. + b.Run("direct", func(b *testing.B) { + b.Run("pre", func(b *testing.B) { + requireNoDaemon(b) + s := newSandbox(b, shelltimeBin(b), baseConfig) + runs := measure(b, nil, func() runStat { return s.run(trackArgs("pre")...) }) + if got := countLines(b, s.path("commands", "pre.txt")); got != runs { + b.Fatalf("pre.txt has %d lines after %d runs; track did not take the direct path", got, runs) + } + s.requireNoErrors() + }) + + // post: below the flush threshold, so no sync. This is the common + // direct-mode post and its cost grows with the store. + b.Run("post", func(b *testing.B) { + requireNoDaemon(b) + s := newSandbox(b, shelltimeBin(b), baseConfig) + f := seedStore(s, seedPairs, 0) + ok := 0 + verify := func() { + if grew, moved := f.check(); grew && !moved { + ok++ + } + } + reset := func() { verify(); f.restore() } + runs := measure(b, reset, func() runStat { return s.run(trackArgs("post")...) }) + verify() + // The first reset runs before any exec, so it never counts. + if ok != runs { + b.Fatalf("only %d of %d runs appended a post without syncing; track did not take the direct path", ok, runs) + } + s.requireNoErrors() + }) + + // post-sync: the post that reaches the flush threshold and sends the + // batch over HTTP, once every flushCount commands in direct mode. + b.Run("post-sync", func(b *testing.B) { + requireNoDaemon(b) + api := startFakeAPI(b) + s := newSandbox(b, shelltimeBin(b), + "token: bench-token\napiEndpoint: "+api.srv.URL+"\nflushCount: 10\n") + f := seedStore(s, seedPairs, flushCount-1) + ok := 0 + verify := func() { + if grew, moved := f.check(); grew && moved { + ok++ + } + } + reset := func() { verify(); f.restore() } + runs := measure(b, reset, func() runStat { return s.run(trackArgs("post")...) }) + verify() + if ok != runs || api.syncs.Load() != int64(runs) || api.unexpects.Load() != 0 { + b.Fatalf("%d runs: %d appended and synced, server got %d batches of %d and %d unexpected requests", + runs, ok, api.syncs.Load(), flushCount, api.unexpects.Load()) + } + s.requireNoErrors() + }) + }) +}