From 8cbf2f43ec307e1795677298ef2e514cabdd9e67 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 7 Oct 2026 10:33:24 +0000 Subject: [PATCH] feat(perf): benchmark shelltime track latency on every PR and main push The shell hooks run `shelltime track` in the foreground before and after every command, so its whole-process latency is user-facing. Nothing measured it. perf/ is a separate Go module (so golang.org/x/perf never affects version selection for the shipped binaries) with: - a harness that execs the real binary per iteration, as the zsh hook does, in an isolated $HOME: startup baseline, daemon pre/post against a fake daemon socket, and direct pre/post/post-sync against a seeded txt store and a fake API. Each scenario checks it took the intended path, because track always exits 0. - perfreport, which compares base and head with benchmath (medians, Mann-Whitney U) and renders a markdown report. A scenario is flagged when it is >10% and >0.25 ms slower with p < 0.05. - compare.sh, which builds base and head with identical flags, skips when the binaries are byte-identical, and runs one harness against both in interleaved ABBA rounds. The Track Perf workflow runs it on pull requests, pushes to main and on demand. It writes the report to the job summary and a sticky PR comment, and raises warning annotations on regressions without failing the check. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01QuSfoWGrqsxjw5Yyegzzyt --- .github/workflows/perf.yaml | 160 +++++ AGENTS.md | 3 + CLAUDE.md | 11 + perf/README.md | 91 +++ perf/cmd/perfreport/main.go | 133 ++++ perf/cmd/perfreport/report.go | 410 ++++++++++++ perf/cmd/perfreport/report_test.go | 129 ++++ perf/cmd/perfreport/testdata/base.txt | 130 ++++ perf/cmd/perfreport/testdata/head.txt | 130 ++++ perf/cmd/perfreport/testdata/report.golden.md | 36 ++ perf/comment.sh | 29 + perf/compare.sh | 115 ++++ perf/doc.go | 20 + perf/go.mod | 9 + perf/go.sum | 4 + perf/harness_test.go | 583 ++++++++++++++++++ perf/track_bench_test.go | 109 ++++ 17 files changed, 2102 insertions(+) create mode 100644 .github/workflows/perf.yaml create mode 100644 perf/README.md create mode 100644 perf/cmd/perfreport/main.go create mode 100644 perf/cmd/perfreport/report.go create mode 100644 perf/cmd/perfreport/report_test.go create mode 100644 perf/cmd/perfreport/testdata/base.txt create mode 100644 perf/cmd/perfreport/testdata/head.txt create mode 100644 perf/cmd/perfreport/testdata/report.golden.md create mode 100755 perf/comment.sh create mode 100755 perf/compare.sh create mode 100644 perf/doc.go create mode 100644 perf/go.mod create mode 100644 perf/go.sum create mode 100644 perf/harness_test.go create mode 100644 perf/track_bench_test.go 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() + }) + }) +}