diff --git a/cmd/genspec-tui/README.md b/cmd/genspec-tui/README.md index 5ef3a6c8..411e961a 100644 --- a/cmd/genspec-tui/README.md +++ b/cmd/genspec-tui/README.md @@ -63,6 +63,15 @@ the scan runs under, plus codescan's own loader: | `-toolchain-free-loader` | `false` | load packages with codescan's own loader instead of the go command (experimental) | | `-stub-stdlib` | `false` | synthesize the standard library instead of reading GOROOT (needs `-toolchain-free-loader`) | +A third group observes the run rather than configuring it — see +[What a scan cost](#what-a-scan-cost-m): + +| Flag | Default | Meaning | +|------|---------|---------| +| `-profile` | `false` | profile every scan: a CPU profile and per-phase allocation profiles, reported under `m` and written for `go tool pprof` | +| `-profile-dir` | a fresh temp dir | where `-profile` writes its `.pprof` files | +| `-mem-profile-rate` | `0` | with `-profile`, `runtime.MemProfileRate`: `0` samples every 512 KiB, `1` records every allocation exactly | + Every boolean scanner option can be toggled live with `o`; the spec re-renders on close, which makes the popup the fastest way to see what a flag such as `EmitRefSiblings` actually changes. The rows are grouped (discovery & scope · @@ -137,6 +146,7 @@ the cursor falls back to its nearest surviving ancestor. | `v` / `V` | validate the generated spec / switch the diagnostics pane between scan and validation | | `F5` | reload the open file from disk (asks before discarding unsaved edits) | | `o` | scanner options popup (`space` toggles, `Esc`/`o` applies and rescans) | +| `m` | what the last scan cost — wall clock and memory, split between scanning and rendering; the profiles too under `-profile` | | `ctrl+q` / `ctrl+c` | quit | ### Spec pane @@ -213,6 +223,91 @@ The entries cover the twenty `swagger:` annotations. Individual body keywords too many for a popup to be the right place — so each annotation's entry says instead which family of keywords its body accepts. +## What a scan cost (`m`) + +`m` opens a card describing the run that just finished: how long it took, what +it allocated, what it left live, and how much the process holds from the OS. +Time and memory are both split between **scanning** (codescan) and **rendering** +(serializing the same document twice, as JSON and again as YAML), because the +run is fenced three times — before the scan, after it, and after rendering. Under +`-profile` the same two phases are bracketed by the profiler, so what the sampler +says and what the fences say describe the same halves of the same work. + +A `split` line at the top recaps the whole thing as ratios — `time 96% / 4% · +memory 86% / 14%`, and `cpu` too under `-profile` — because the question a reader +usually arrives with is *which phase is this?*, and two figures in different +units is a comparison they would otherwise do in their head. Time and memory can +disagree sharply, which is why both are there. + +It is a modal rather than another status-line field: the status line already +carries the pane hints, the follow badge and the search prompt, and this is a +figure most sessions never ask for. + +Two things those figures are not, both stated on the card: + +- **The window is process-wide.** `runtime.ReadMemStats` accounts for the whole + process, and while a scan runs the redraw loop, the spinner and the file + watcher allocate on other goroutines. +- **A rescan holds two documents.** The previous spec is only released once the + new one lands, so on a rescan the retained figure reads high by about one + document. That is arithmetic, not a leak. + +### Profiled runs (`-profile`) + +A scalar cannot say who spent it, which is the ceiling on everything above. +Start with `-profile` and each scan is also profiled: the card then reports +**where the CPU went** and **what allocated it, per phase**, by function. The +process-wide caveat stops mattering, because the noise arrives named — a redraw +row you discount rather than a confound you cannot separate. + +```sh +genspec-tui -profile -workdir ../my-api + +# every allocation counted rather than sampled every 512 KiB — accurate, and slow +genspec-tui -profile -mem-profile-rate=1 -workdir ../my-api +``` + +The card grows scrolling when it outgrows the terminal (`↑↓`/`jk`, `PgUp`/`PgDn`, +`Home`/`End`), and names the artifacts it wrote, with the commands that open them: + +```sh +go tool pprof -http=: /cpu-scan.pprof +go tool pprof -http=: -base /mem-before.pprof /mem-after-scan.pprof +``` + +Five artifacts are written: a CPU profile per phase (`cpu-scan`, `cpu-render`) +and three heap snapshots — before, after scanning, after rendering — so `-base` +reproduces either phase in the real tool. What the in-TUI tables give you +is the answer without leaving the session; the flame graph is one command away. + +Caveats worth knowing before reading a table: + +- **Sampling.** At the default rate the heap profiler records one allocation per + 512 KiB, and the figures are scaled back up the way pprof does. The card says + `estimated from sampling`, or `every allocation counted` under + `-mem-profile-rate=1`. +- **Samples, not measurements.** The CPU profiler runs at 100 Hz, so a scan under + a second yields a few dozen samples and cannot rank functions; the card says so + rather than dressing a handful of samples up as a ranking. Both phases are + bracketed, but rendering is often shorter than the sampler's 10 ms interval and + simply catches nothing — which the card states, because an absent section reads + as an oversight while "nothing sampled" is a measurement. +- **The observer is excluded.** Stopping one phase's CPU profile flushes it + through a compressor and starting the next allocates its buffers, all of it + between two fences. Those allocations are dropped from the tables rather than + reported: in the short phase they would otherwise crowd out its real sites. +- **Observing costs.** A profiled run collects at each fence and carries the + sampler's overhead, so the summary figures at the top of the card are worse + than the same run unprofiled. The tables are the accurate account. +- **Not a runtime toggle.** The heap sampling rate is a property of the process + and is fixed at launch: two runs in one session are then comparable. +- **One at a time.** The CPU profiler is a process-wide singleton, so if a second + scan starts while one is in flight (changing an option mid-scan), it runs + without a CPU profile and says so. +- **The last run only.** Every scan writes the same five filenames, so a rescan + overwrites its predecessor. Copy them elsewhere before saving a file if you want + to compare two runs. + ## Reloading `F5` re-reads the open file from disk. Disk is the source of truth here, so diff --git a/cmd/genspec-tui/go.mod b/cmd/genspec-tui/go.mod index 2bd4ccc3..3427eecf 100644 --- a/cmd/genspec-tui/go.mod +++ b/cmd/genspec-tui/go.mod @@ -14,6 +14,7 @@ require ( github.com/go-openapi/strfmt v0.27.0 github.com/go-openapi/testify/v2 v2.6.0 github.com/go-openapi/validate v0.26.3 + github.com/google/pprof v0.0.0-20260802141513-ef3492d7dac3 github.com/muesli/termenv v0.16.0 go.yaml.in/yaml/v3 v3.0.5 ) diff --git a/cmd/genspec-tui/go.sum b/cmd/genspec-tui/go.sum index 46ad0bf6..600296e2 100644 --- a/cmd/genspec-tui/go.sum +++ b/cmd/genspec-tui/go.sum @@ -80,6 +80,8 @@ github.com/goccy/go-yaml v1.19.2 h1:PmFC1S6h8ljIz6gMRBopkjP1TVT7xuwrButHID66PoM= github.com/goccy/go-yaml v1.19.2/go.mod h1:XBurs7gK8ATbW4ZPGKgcbrY1Br56PdM69F7LkFRi1kA= github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= +github.com/google/pprof v0.0.0-20260802141513-ef3492d7dac3 h1:LMLX+LgTNWpfvCBdFebv6EsYotImrt/Ppc5cXIriCSo= +github.com/google/pprof v0.0.0-20260802141513-ef3492d7dac3/go.mod h1:jl5iWTm0/hd5PjEYEOuwAJ57L/CibdZfrqZ5XA5GrCk= github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/lucasb-eyer/go-colorful v1.4.0 h1:UtrWVfLdarDgc44HcS7pYloGHJUjHV/4FwW4TvVgFr4= diff --git a/cmd/genspec-tui/internal/ux/chrome.go b/cmd/genspec-tui/internal/ux/chrome.go index 39c4769f..47b46a2c 100644 --- a/cmd/genspec-tui/internal/ux/chrome.go +++ b/cmd/genspec-tui/internal/ux/chrome.go @@ -5,10 +5,10 @@ package ux import ( "fmt" - "time" "github.com/charmbracelet/lipgloss" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/humanize" "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/theme" ) @@ -56,7 +56,7 @@ func (m *Model) headerLine() string { case m.scan.Running: tail = m.scan.Spin.View() + theme.Status().Render("scanning") case m.scan.Elapsed > 0: - tail = theme.Status().Render("ready (" + humanDuration(m.scan.Elapsed) + ")") + tail = theme.Status().Render("ready (" + humanize.Duration(m.scan.Elapsed) + ")") } // Measured, not guessed. Assembled around the work dir rather than through a format string, so nothing in the data @@ -74,24 +74,6 @@ func (m *Model) headerLine() string { return lipgloss.NewStyle().MaxWidth(m.width).Render(line) } -// humanDuration renders d compactly: "947ms", "3s", "1m 3s" (minute form drops a zero-second remainder, e.g. "2m"). -func humanDuration(d time.Duration) string { - switch { - case d < time.Second: - return fmt.Sprintf("%dms", d.Milliseconds()) - case d < time.Minute: - return fmt.Sprintf("%ds", int(d.Round(time.Second).Seconds())) - default: - d = d.Round(time.Second) - mins := int(d / time.Minute) - secs := int((d % time.Minute) / time.Second) - if secs == 0 { - return fmt.Sprintf("%dm", mins) - } - return fmt.Sprintf("%dm %ds", mins, secs) - } -} - // statusLine renders the bottom line, clipped to the terminal. // // Same reasoning as the header: several of its variants embed something unbounded - a JSON pointer, a follow target, a diff --git a/cmd/genspec-tui/internal/ux/diagnostics_test.go b/cmd/genspec-tui/internal/ux/diagnostics_test.go index f532e4de..10385f58 100644 --- a/cmd/genspec-tui/internal/ux/diagnostics_test.go +++ b/cmd/genspec-tui/internal/ux/diagnostics_test.go @@ -257,7 +257,7 @@ func TestDoScanCollectsDiagnostics(t *testing.T) { WorkDir: dir, Packages: []string{"."}, ScanModels: true, - }) + }, scan.Profiling{}) if res.Err != nil { t.Fatalf("scan should not hard-fail on soft diagnostics: %v", res.Err) diff --git a/cmd/genspec-tui/internal/ux/fixtures_test.go b/cmd/genspec-tui/internal/ux/fixtures_test.go index 0a3eb5b4..9228cf00 100644 --- a/cmd/genspec-tui/internal/ux/fixtures_test.go +++ b/cmd/genspec-tui/internal/ux/fixtures_test.go @@ -8,6 +8,7 @@ import ( "github.com/go-openapi/codescan" "github.com/go-openapi/codescan/cmd/genspec-tui/internal/index" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/scan" "github.com/go-openapi/codescan/internal/parsers/grammar" "github.com/go-openapi/codescan/internal/scanner" ) @@ -31,7 +32,7 @@ func testModel(t *testing.T, opts ...modelOpt) *Model { func testModelIn(t *testing.T, dir string, opts ...modelOpt) *Model { t.Helper() - m := New(codescan.Options{WorkDir: dir, Packages: []string{"./..."}}) + m := New(codescan.Options{WorkDir: dir, Packages: []string{"./..."}}, scan.Profiling{}) t.Cleanup(m.Close) m.width, m.height = 80, 24 diff --git a/cmd/genspec-tui/internal/ux/help/help.go b/cmd/genspec-tui/internal/ux/help/help.go index 612c6ba9..8bf38972 100644 --- a/cmd/genspec-tui/internal/ux/help/help.go +++ b/cmd/genspec-tui/internal/ux/help/help.go @@ -63,6 +63,7 @@ var helpSections = []helpSection{ {"v", "validate the generated spec (go-openapi/validate)"}, {"V", "switch the diagnostics pane between scan and validation"}, {"o", "scanner options"}, + {"m", "what the last scan cost (time, memory, and the profiles under -profile)"}, {"ctrl+q ctrl+c", "quit"}, }}, {"spec pane", []helpEntry{ diff --git a/cmd/genspec-tui/internal/ux/humanize/doc.go b/cmd/genspec-tui/internal/ux/humanize/doc.go new file mode 100644 index 00000000..0a6d4297 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/humanize/doc.go @@ -0,0 +1,8 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +// Package humanize renders durations, sizes and counts the way the chrome shows them to a reader. +// +// Its own package because the header line and the run-cost overlay both need the same spellings, and neither owns the +// other: a duration that reads "1m 3s" in one place and "63s" in the other is the same measurement told two ways. +package humanize diff --git a/cmd/genspec-tui/internal/ux/humanize/humanize.go b/cmd/genspec-tui/internal/ux/humanize/humanize.go new file mode 100644 index 00000000..0000de79 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/humanize/humanize.go @@ -0,0 +1,86 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package humanize + +import ( + "fmt" + "time" +) + +// Duration renders d compactly: "947ms", "3s", "1m 3s" (minute form drops a zero-second remainder, e.g. "2m"). +func Duration(d time.Duration) string { + switch { + case d < time.Second: + return fmt.Sprintf("%dms", d.Milliseconds()) + case d < time.Minute: + return fmt.Sprintf("%ds", int(d.Round(time.Second).Seconds())) + default: + d = d.Round(time.Second) + mins := int(d / time.Minute) + secs := int((d % time.Minute) / time.Second) + if secs == 0 { + return fmt.Sprintf("%dm", mins) + } + + return fmt.Sprintf("%dm %ds", mins, secs) + } +} + +// The binary units memory is reported in. A megabyte here is 1024 KB, matching what every other tool a reader would +// compare this against (top, ps, the Go runtime's own docs) means by MB. +const ( + kb = 1 << 10 + mb = 1 << 20 + gb = 1 << 30 +) + +// Bytes renders a size: "912 B", "44 KB", "412.3 MB", "1.21 GB". +// +// Precision grows with the unit rather than staying fixed, because the reader's question changes with it: at kilobytes +// nobody cares about a fraction, while at gigabytes two decimals are the difference between two readings. +func Bytes(n uint64) string { + switch { + case n < kb: + return fmt.Sprintf("%d B", n) + case n < mb: + return fmt.Sprintf("%.0f KB", float64(n)/kb) + case n < gb: + return fmt.Sprintf("%.1f MB", float64(n)/mb) + default: + return fmt.Sprintf("%.2f GB", float64(n)/gb) + } +} + +// SignedBytes renders a difference, always carrying its sign: "+38.0 MB", "-4.1 MB", "+0 B". +// +// The sign is explicit even when positive: these are read as changes, and a bare number invites being read as a total. +func SignedBytes(n int64) string { + if n >= 0 { + return "+" + Bytes(uint64(n)) + } + + // Negating MinInt64 overflows. Adding one before the negation keeps it in range, at the cost of a single byte at a + // magnitude no heap difference can reach. + // + //nolint:gosec // -(n+1) is non-negative for every n < 0, which is the only branch this is reached on + return "-" + Bytes(uint64(-(n+1))+1) +} + +// SignedCount renders a count difference in short form: "+410 k", "-1.2 M", "+37". +func SignedCount(n int64) string { + sign := "+" + if n < 0 { + sign = "-" + n = -n + } + + switch { + case n < 1_000: + return fmt.Sprintf("%s%d", sign, n) + case n < 1_000_000: + return fmt.Sprintf("%s%.0f k", sign, float64(n)/1_000) + default: + return fmt.Sprintf("%s%.1f M", sign, float64(n)/1_000_000) + } +} diff --git a/cmd/genspec-tui/internal/ux/humanize/humanize_test.go b/cmd/genspec-tui/internal/ux/humanize/humanize_test.go new file mode 100644 index 00000000..b18755f2 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/humanize/humanize_test.go @@ -0,0 +1,83 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package humanize_test + +import ( + "testing" + "time" + + "github.com/go-openapi/testify/v2/assert" + + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/humanize" +) + +func TestDuration(t *testing.T) { + for _, tc := range []struct { + in time.Duration + want string + }{ + {947 * time.Millisecond, "947ms"}, + {0, "0ms"}, + {time.Second, "1s"}, + {3200 * time.Millisecond, "3s"}, + {59 * time.Second, "59s"}, + {time.Minute, "1m"}, + {2 * time.Minute, "2m"}, + {63 * time.Second, "1m 3s"}, + } { + assert.Equal(t, tc.want, humanize.Duration(tc.in), "%s", tc.in) + } +} + +func TestBytes(t *testing.T) { + for _, tc := range []struct { + in uint64 + want string + }{ + {0, "0 B"}, + {912, "912 B"}, + {1023, "1023 B"}, + {1024, "1 KB"}, + {1024*1024 - 1, "1024 KB"}, // rounds up to the next unit's worth without changing unit + {1024 * 1024, "1.0 MB"}, + {432 * 1024 * 1024, "432.0 MB"}, + {1024 * 1024 * 1024, "1.00 GB"}, + {3*1024*1024*1024 + 512*1024*1024, "3.50 GB"}, + } { + assert.Equal(t, tc.want, humanize.Bytes(tc.in), "%d", tc.in) + } +} + +func TestSignedBytes(t *testing.T) { + for _, tc := range []struct { + in int64 + want string + }{ + {0, "+0 B"}, + {38 * 1024 * 1024, "+38.0 MB"}, + {-4 * 1024 * 1024, "-4.0 MB"}, + {-512, "-512 B"}, + } { + assert.Equal(t, tc.want, humanize.SignedBytes(tc.in), "%d", tc.in) + } + + // A heap difference can never reach here, but arithmetic that wraps at the extreme is a bug wherever it lives. + assert.NotPanics(t, func() { humanize.SignedBytes(-1 << 62) }) +} + +func TestSignedCount(t *testing.T) { + for _, tc := range []struct { + in int64 + want string + }{ + {0, "+0"}, + {37, "+37"}, + {-999, "-999"}, + {410_000, "+410 k"}, + {-12_400, "-12 k"}, + {1_250_000, "+1.2 M"}, + } { + assert.Equal(t, tc.want, humanize.SignedCount(tc.in), "%d", tc.in) + } +} diff --git a/cmd/genspec-tui/internal/ux/integration_test.go b/cmd/genspec-tui/internal/ux/integration_test.go index 5e71b885..007d1672 100644 --- a/cmd/genspec-tui/internal/ux/integration_test.go +++ b/cmd/genspec-tui/internal/ux/integration_test.go @@ -767,7 +767,7 @@ func scanPetstore(t *testing.T) *Model { WorkDir: fixturesDir(t), Packages: []string{"./goparsing/petstore/..."}, ScanModels: true, - }) + }, scan.Profiling{}) }) res := petstoreRes require.NoError(t, res.Err, "the petstore fixture must scan cleanly") diff --git a/cmd/genspec-tui/internal/ux/key/bindings.go b/cmd/genspec-tui/internal/ux/key/bindings.go index da88e78f..110fe430 100644 --- a/cmd/genspec-tui/internal/ux/key/bindings.go +++ b/cmd/genspec-tui/internal/ux/key/bindings.go @@ -33,6 +33,7 @@ const ( G Binding = "g" F Binding = "f" I Binding = "i" + M Binding = "m" N Binding = "n" V Binding = "v" Y Binding = "y" diff --git a/cmd/genspec-tui/internal/ux/keys.go b/cmd/genspec-tui/internal/ux/keys.go index a2434780..d9b4699f 100644 --- a/cmd/genspec-tui/internal/ux/keys.go +++ b/cmd/genspec-tui/internal/ux/keys.go @@ -83,6 +83,9 @@ func (m *Model) handleKey(msg tea.KeyMsg) tea.Cmd { case key.H, key.Question: m.help.Open() return nil + case key.M: + m.runstats.Open() + return nil case key.O: m.exitFollow() m.refs.Reset() diff --git a/cmd/genspec-tui/internal/ux/model.go b/cmd/genspec-tui/internal/ux/model.go index f54bc9fc..cd89888b 100644 --- a/cmd/genspec-tui/internal/ux/model.go +++ b/cmd/genspec-tui/internal/ux/model.go @@ -18,6 +18,7 @@ import ( "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/options" "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/panels" "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/reference" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/runstats" "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/scan" ) @@ -25,6 +26,10 @@ import ( type Model struct { cfg codescan.Options + // What each scan captures about itself, fixed at launch. Not a runtime toggle: the heap sampling rate is set once + // for the process, so a run profiled under one rate cannot be compared with a run profiled under another. + profiling scan.Profiling + // Terminal geometry, and the regions recalcLayout carves out of it (kept for mouse hit-testing). width, height int leftW, topH, diagH int @@ -83,6 +88,7 @@ type Model struct { options options.Overlay confirm confirm.Overlay reference reference.Overlay + runstats runstats.Overlay // What an accepted confirmation will do. The overlay records the answer; naming the action is the model's job. pendingConfirm confirmAction @@ -141,9 +147,13 @@ const ( // // A file watcher is started best-effort - if it can't initialize, live reload is simply unavailable and the user // falls back to r (manual rescan). -func New(cfg codescan.Options) *Model { +// +// prof travels separately from the scan config because it is not one: it says what to observe about a run, not what +// the run should produce. Its zero value profiles nothing. +func New(cfg codescan.Options, prof scan.Profiling) *Model { m := &Model{ cfg: cfg, + profiling: prof, focused: paneTree, leftPct: defaultLeftPct, diagPct: defaultDiagPct, @@ -157,6 +167,7 @@ func New(cfg codescan.Options) *Model { help: help.New(), confirm: confirm.New(), reference: reference.New(), + runstats: runstats.New(), } // Built after the struct exists: the options rows bind to the scan-config booleans by pointer, and those pointers // have to be into m.cfg (valid because m is heap-allocated) rather than into the caller's copy. diff --git a/cmd/genspec-tui/internal/ux/overlay.go b/cmd/genspec-tui/internal/ux/overlay.go index 06e51936..d88b9690 100644 --- a/cmd/genspec-tui/internal/ux/overlay.go +++ b/cmd/genspec-tui/internal/ux/overlay.go @@ -32,7 +32,7 @@ type Overlay interface { // The confirmation comes first: it is the only one holding an action back, and a question that could be buried under // another modal would be a question the user cannot answer. func (m *Model) overlays() []Overlay { - return []Overlay{&m.confirm, &m.options, &m.help, &m.reference} + return []Overlay{&m.confirm, &m.options, &m.help, &m.reference, &m.runstats} } // activeOverlay returns the overlay currently covering the UI, or nil when none is. diff --git a/cmd/genspec-tui/internal/ux/render_test.go b/cmd/genspec-tui/internal/ux/render_test.go index e528f550..d3f0ba7a 100644 --- a/cmd/genspec-tui/internal/ux/render_test.go +++ b/cmd/genspec-tui/internal/ux/render_test.go @@ -279,24 +279,6 @@ func TestStatusLineFits(t *testing.T) { } } -func TestHumanDuration(t *testing.T) { - for _, tc := range []struct { - in time.Duration - want string - }{ - {947 * time.Millisecond, "947ms"}, - {0, "0ms"}, - {time.Second, "1s"}, - {3200 * time.Millisecond, "3s"}, - {59 * time.Second, "59s"}, - {time.Minute, "1m"}, - {2 * time.Minute, "2m"}, - {63 * time.Second, "1m 3s"}, - } { - assert.Equal(t, tc.want, humanDuration(tc.in), "%s", tc.in) - } -} - func TestShortenPath(t *testing.T) { assert.Equal(t, "/a/b", shortenPath("/a/b", 10), "a path that fits is untouched") assert.Equal(t, "…c/ddd", shortenPath("/aaa/bbb/ccc/ddd", 6)) diff --git a/cmd/genspec-tui/internal/ux/runstats/doc.go b/cmd/genspec-tui/internal/ux/runstats/doc.go new file mode 100644 index 00000000..83c7d5a9 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats/doc.go @@ -0,0 +1,9 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +// Package runstats shows what the last scan cost: the wall clock, and the memory the process moved across the run. +// +// The measurement itself belongs to the scan package (see [scan.Cost], which states what the figures do and do not +// mean); this package only lays them out. The split is deliberate - the fences have to be taken around the work, on +// the goroutine doing it, while what a reader is told about them is a rendering decision. +package runstats diff --git a/cmd/genspec-tui/internal/ux/runstats/runstats.go b/cmd/genspec-tui/internal/ux/runstats/runstats.go new file mode 100644 index 00000000..bef3c37d --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats/runstats.go @@ -0,0 +1,423 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package runstats + +import ( + "fmt" + "strconv" + "strings" + + tea "github.com/charmbracelet/bubbletea" + "github.com/charmbracelet/lipgloss" + + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/humanize" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/key" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/scan" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/theme" +) + +// Overlay reports what the last scan cost. +// +// The zero value is a closed overlay holding no reading; the root model feeds it each result and composites its View +// over the base UI. +// +// It is a modal rather than another status-line field on purpose: the status line is already carrying the pane hints, +// the follow badge and the search prompt, and none of those can be given up for a figure most sessions never ask for. +type Overlay struct { + width, height int + + isOpen bool + scroll int + + cost scan.Cost + profile *scan.ProfileReport + rescan bool +} + +// New builds a closed overlay. +func New() Overlay { + return Overlay{} +} + +// Set records the cost of the run that has just landed. +// +// rescan says whether that run replaced a document the model was already holding, which the card has to disclose: at +// the closing fence the previous spec and the new one are both live, so the retained figure reads high by about one +// document. Neither the scan nor this overlay can see that on its own - only the model knows what it was holding. +func (o *Overlay) Set(c scan.Cost, report *scan.ProfileReport, rescan bool) { + o.cost = c + o.profile = report + o.rescan = rescan + o.scroll = 0 +} + +// SetSize fits the overlay to outer dimensions w×h. +func (o *Overlay) SetSize(w, h int) { + o.width = w + o.height = h +} + +// IsOpen reports whether the overlay is currently covering the UI. +func (o *Overlay) IsOpen() bool { return o.isOpen } + +// Open shows the card, always from the top: it is opened to read the last run, not resumed. +func (o *Overlay) Open() { + o.isOpen = true + o.scroll = 0 +} + +// Close hides it. +func (o *Overlay) Close() { + o.isOpen = false + o.scroll = 0 +} + +// HandleKey scrolls or dismisses the overlay, and swallows everything else. +// +// Unprofiled, the card fits a screen and the movement keys do nothing; a profiled run adds three tables, and a table +// below the fold is a measurement nobody sees. Quitting belongs to the root model, which checks for it before the +// overlay ever sees the key. +func (o *Overlay) HandleKey(msg tea.KeyMsg) tea.Cmd { + if delta, ok := key.Nav(key.MsgBinding(msg), o.visibleRows(), len(o.lines())); ok { + o.scrollBy(delta) + + return nil + } + + switch key.MsgBinding(msg) { + case key.Esc, key.M, key.Enter: + o.Close() + } + + return nil +} + +// The modal's fixed texts, named so the frame can be measured against them as well as against the figures. +const ( + title = "Last run" + footer = "esc / m: close" + + // What the reading is and is not. Stated on the card rather than in the README, because the numbers are read here + // and a caveat nobody sees is a caveat that does not exist. + noteWindow = "measured across the whole run: the redraw loop and the file watcher allocate on other goroutines too" + noteRescan = "this run replaced a spec still held while it ran, so retained reads high by about one document" + + // A profiled run is measured while being watched: the sampler costs time, and the profiler collects at each fence + // to keep its own figures current. The tables below are the accurate account; these figures are not. + noteProfiled = "profiled run: these figures carry the profiler's overhead and its collections — read the tables below,\n" + + " which exclude the profiler's own work" + + empty = "no run measured yet" + emptyHint = "the first scan is still running" +) + +// The two columns the figures line up in: a label, then its value right-aligned so the units stack. +const ( + labelW = 13 + valueW = 11 +) + +// confidentSamples is the point below which the CPU table is a hint rather than a ranking. +// +// The sampler runs at 100 Hz, so this is a second of CPU: under it, the gap between the first row and the third is a +// couple of samples, and reordering them would take nothing. +const confidentSamples = 100 + +// View renders the card, with scrolling once it outgrows the terminal. +func (o *Overlay) View() string { + all := o.lines() + visible := o.visibleRows() + + shown := all + top := 0 + if len(all) > visible { + top = min(max(o.scroll, 0), len(all)-visible) + shown = all[top : top+visible] + } + + head := title + if o.profile != nil { + head += " · profiled" + } + + return theme.ModalAt(o.contentWidth(all)).Render( + theme.Accent().Render(head) + "\n\n" + + strings.Join(shown, "\n") + "\n\n" + + theme.Status().Render(o.footer(top, len(all))), + ) +} + +// scrollBy moves the window, clamped so it can never scroll past the end. +func (o *Overlay) scrollBy(delta int) { + o.scroll = min(max(o.scroll+delta, 0), max(len(o.lines())-o.visibleRows(), 0)) +} + +// visibleRows is how many body rows fit between the modal's chrome. +func (o *Overlay) visibleRows() int { + const chrome = 10 // border 2 + padding 2 + title 2 + footer 2, with slack + + return max(o.height-chrome, 3) +} + +// footer states the range as well as the keys: a profiled run does not fit a screen, and a table below the fold is a +// measurement nobody knows was taken. +func (o *Overlay) footer(top, total int) string { + visible := o.visibleRows() + if total <= visible { + return footer + } + + return fmt.Sprintf("%d–%d of %d · ↑↓/jk: scroll · %s", top+1, min(top+visible, total), total, footer) +} + +// contentWidth pins the frame to the widest line it can EVER show, not the widest one currently on screen - sizing to +// the window is what makes a box appear to twitch as its content scrolls under it. +func (o *Overlay) contentWidth(lines []string) int { + return max( + lipgloss.Width(strings.Join(lines, "\n")), + lipgloss.Width(title+" · profiled"), + lipgloss.Width(o.footer(0, len(lines))), + ) +} + +// lines renders the card body: the figures, then what they do and do not mean. +func (o *Overlay) lines() []string { + if !o.cost.Measured { + return []string{theme.Status().Render(empty), "", theme.Status().Render(emptyHint)} + } + + c := o.cost + lines := []string{ + o.recap(), + "", + row("elapsed", humanize.Duration(c.ScanFor+c.RenderFor), + "scanning "+humanize.Duration(c.ScanFor)+" · rendering "+humanize.Duration(c.RenderFor)), + "", + row("allocated", humanize.Bytes(c.Allocated()), "churned through, garbage included"), + sub("scanning", humanize.Bytes(c.AllocScan)), + sub("rendering", humanize.Bytes(c.AllocRender)), + "", + row("retained", humanize.SignedBytes(c.Retained()), + humanize.Bytes(c.LiveBefore)+" → "+humanize.Bytes(c.LiveAfter)+" live"), + sub("scanning", humanize.SignedBytes(c.RetainScan)), + sub("rendering", humanize.SignedBytes(c.RetainRender)), + "", + row("objects", humanize.SignedCount(c.Objects), "live on the heap"), + row("GC cycles", strconv.FormatUint(uint64(c.GCCycles), 10), ""), + row("from the OS", humanize.Bytes(c.Sys), "high-water: the runtime rarely hands it back"), + "", + } + + // What these figures are not. Under a profiled run the first caveat is answered by the tables below - the noise is + // named there - but two new ones apply, since observing the run costs the run something. + if o.profile == nil { + lines = append(lines, theme.Status().Render(noteWindow)) + } else { + lines = append(lines, theme.Status().Render(noteProfiled)) + } + if o.rescan { + lines = append(lines, theme.Status().Render(noteRescan)) + } + + return append(lines, o.profileLines()...) +} + +// recap is the one line a reader takes away: how the run divided between its two phases. +// +// The detail below answers it in absolute terms, but two figures in different units are a comparison the reader has to +// do in their head, and the answer they are usually after - is this a scanning problem or a rendering problem? - is a +// ratio. Time and memory can disagree sharply (a phase that churns while barely running, or the reverse), which is +// exactly why both are here rather than one standing in for the other. +// +// Under a profiled run the sampled CPU split joins them, and is the more honest of the two clocks: wall time counts +// waiting, CPU time counts working. +func (o *Overlay) recap() string { + c := o.cost + parts := []string{ + share("time", int64(c.ScanFor), int64(c.RenderFor)), + share("memory", int64(c.AllocScan), int64(c.AllocRender)), //nolint:gosec // allocation figures never approach MaxInt64 + } + + if p := o.profile; p != nil && (p.Scan.Sampled() || p.Render.Sampled()) { + parts = append(parts, share("cpu", int64(p.Scan.CPUTotal), int64(p.Render.CPUTotal))) + } + + return " " + pad("split", labelW) + strings.Join(parts, " · ") + + theme.Status().Render(" scanning / rendering") +} + +// share renders one split as two percentages that add up to a hundred. +// +// The second is derived from the first rather than rounded on its own: independently rounded halves produce "96% / 5%", +// which reads as an arithmetic error in a line whose whole job is to be glanced at. +func share(label string, scanning, rendering int64) string { + total := scanning + rendering + if total <= 0 { + return label + " n/a" + } + + pct := (scanning*100 + total/2) / total + + return fmt.Sprintf("%s %d%% / %d%%", label, pct, 100-pct) +} + +// profileLines renders what the profiler saw: for each phase, where the CPU went and what allocated the memory, then +// where the artifacts are. +// +// This is the account the figures above cannot give. A scalar cannot say who spent it, so the caveat about the redraw +// loop and the watcher can only be stated there; here they are simply rows, and a reader discounts them by name. +func (o *Overlay) profileLines() []string { + p := o.profile + if p == nil { + return nil + } + + lines := []string{""} + for _, phase := range []scan.PhaseProfile{p.Scan, p.Render} { + lines = append(lines, o.cpu(phase)...) + lines = append(lines, o.sites(phase, p.Exact)...) + } + + lines = append(lines, theme.Accent().Render(" artifacts")) + for _, path := range append([]string{p.Scan.CPUPath, p.Render.CPUPath}, p.MemPaths...) { + if path != "" { + lines = append(lines, " "+theme.Status().Render(path)) + } + } + if p.Scan.CPUPath != "" { + lines = append(lines, "", " "+theme.Status().Render("go tool pprof -http=: "+p.Scan.CPUPath)) + } + if len(p.MemPaths) == scan.MemSnapshots { + lines = append(lines, " "+theme.Status().Render( + "go tool pprof -http=: -base "+p.MemPaths[0]+" "+p.MemPaths[1])) + } + + for _, note := range p.Notes { + lines = append(lines, "", theme.Status().Render(" "+note)) + } + + return lines +} + +// cpu renders one phase's CPU table, or says why there is none. +// +// A phase with no samples still gets its heading. Rendering is short enough that the sampler often catches nothing at +// all, and that is worth saying: an absent section reads as an oversight, while "nothing sampled" is a measurement. +func (o *Overlay) cpu(phase scan.PhaseProfile) []string { + heading := theme.Accent().Render(" where the CPU went — " + phase.Label) + + switch { + case phase.CPUPath == "": + return []string{heading + theme.Status().Render(" not profiled"), ""} + case !phase.Sampled(): + return []string{heading + theme.Status().Render( + " nothing sampled: the phase was shorter than the sampler's 10 ms interval"), ""} + } + + samples := "samples" + if phase.CPUSamples == 1 { + samples = "sample" + } + lines := []string{heading + theme.Status().Render(fmt.Sprintf(" %s across %d %s, every goroutine included", + humanize.Duration(phase.CPUTotal), phase.CPUSamples, samples))} + + // A percentage is only worth as much as the samples under it. At 100 Hz a sub-second phase gives a handful, and a + // row drawn from two of them ranks nothing - so the card says which of the two tables this is. + if phase.CPUSamples < confidentSamples { + lines = append(lines, " "+theme.Status().Render( + "too few to rank functions: profile a larger tree, or read the artifact below")) + } + for _, f := range phase.CPU { + lines = append(lines, " "+lead(fmt.Sprintf("%.0f%%", f.Share*100), 5)+ + lead(humanize.Duration(f.Flat), 9)+" "+shortFunc(f.Name)) + } + + return append(lines, "") +} + +// sites renders one phase's allocation table, or says why it is empty. +func (o *Overlay) sites(phase scan.PhaseProfile, exact bool) []string { + estimate := "estimated from sampling" + if exact { + estimate = "every allocation counted" + } + + lines := []string{theme.Accent().Render(" what allocated it — "+phase.Label) + theme.Status().Render(" "+estimate)} + if len(phase.Alloc) == 0 { + return append(lines, " "+theme.Status().Render("nothing sampled in this phase"), "") + } + + for _, s := range phase.Alloc { + lines = append(lines, " "+lead(humanize.Bytes(uint64(max(s.Bytes, 0))), 10)+ + lead(humanize.SignedCount(s.Objects), 9)+" "+shortFunc(s.Name)) + } + + return append(lines, "") +} + +// shortFunc drops everything up to the last path segment of a symbol, so a table of Go function names stays a table. +// +// "github.com/go-openapi/codescan/internal/builders/schema.(*Builder).Build" is eighty columns of mostly repository, +// and the modal is deliberately not wrapped: what a reader needs is the package and the method. +// +// A major-version segment is carried along with the segment before it: "go.yaml.in/yaml/v3.is_space" trimmed to +// "v3.is_space" names no package at all, while "yaml/v3.is_space" says which library is doing the work. +func shortFunc(name string) string { + i := strings.LastIndex(name, "/") + if i < 0 { + return name + } + + if isMajorVersion(name[i+1:]) { + if j := strings.LastIndex(name[:i], "/"); j >= 0 { + return name[j+1:] + } + + return name + } + + return name[i+1:] +} + +// isMajorVersion reports whether a path segment is a module major version - "v3", or "v3.is_space" once the symbol is +// attached to it. +func isMajorVersion(segment string) bool { + rest, _, _ := strings.Cut(segment, ".") + if len(rest) < 2 || rest[0] != 'v' { + return false + } + + for _, r := range rest[1:] { + if r < '0' || r > '9' { + return false + } + } + + return true +} + +// row renders one figure: label, value right-aligned in its column, and an optional gloss. +func row(label, value, note string) string { + line := " " + pad(label, labelW) + lead(value, valueW) + if note != "" { + line += " " + theme.Status().Render(note) + } + + return line +} + +// sub renders a breakdown line under the figure it decomposes, indented so the two read as one block. +func sub(label, value string) string { + return " " + pad(theme.Status().Render(label), labelW-2) + theme.Status().Render(lead(value, valueW)) +} + +// pad left-aligns s in a column w wide, measuring what is drawn rather than the bytes (the labels may be styled). +func pad(s string, w int) string { + return s + strings.Repeat(" ", max(w-lipgloss.Width(s), 0)) +} + +// lead right-aligns s in a column w wide, which is what makes the units line up under one another. +func lead(s string, w int) string { + return strings.Repeat(" ", max(w-lipgloss.Width(s), 0)) + s +} diff --git a/cmd/genspec-tui/internal/ux/runstats/runstats_test.go b/cmd/genspec-tui/internal/ux/runstats/runstats_test.go new file mode 100644 index 00000000..bbdcda16 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats/runstats_test.go @@ -0,0 +1,289 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package runstats_test + +import ( + "strings" + "testing" + "time" + + tea "github.com/charmbracelet/bubbletea" + + "github.com/go-openapi/testify/v2/assert" + "github.com/go-openapi/testify/v2/require" + + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/runstats" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/scan" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/testutils" +) + +const mb = 1 << 20 + +// aRun is a plausible reading, with round figures so the card's own formatting is what the assertions read. +func aRun() scan.Cost { + return scan.Cost{ + Measured: true, + ScanFor: 2 * time.Second, + RenderFor: 92 * time.Millisecond, + + AllocScan: 356 * mb, + AllocRender: 56 * mb, + + RetainScan: 31 * mb, + RetainRender: 7 * mb, + + LiveBefore: 94 * mb, + LiveAfter: 132 * mb, + + Objects: 410_000, + GCCycles: 7, + Sys: 221 * mb, + } +} + +func view(t *testing.T, o *runstats.Overlay) string { + t.Helper() + + o.SetSize(100, 40) + + return testutils.StripANSI(o.View()) +} + +func TestOverlayReportsTheRun(t *testing.T) { + o := runstats.New() + o.Set(aRun(), nil, false) + + got := view(t, &o) + + assert.Contains(t, got, "Last run") + assert.Contains(t, got, "2s", "the wall clock") + assert.Contains(t, got, "rendering 92ms") + + assert.Contains(t, got, "412.0 MB", "allocated is the two halves together") + assert.Contains(t, got, "356.0 MB") + assert.Contains(t, got, "56.0 MB") + + assert.Contains(t, got, "+38.0 MB", "retained carries its sign") + assert.Contains(t, got, "94.0 MB → 132.0 MB live") + + assert.Contains(t, got, "+410 k") + assert.Contains(t, got, "221.0 MB", "what the process holds from the OS") +} + +// The line a reader glances at: which phase the run went on, in both currencies at once. +func TestOverlayRecapsTheSplit(t *testing.T) { + o := runstats.New() + o.Set(aRun(), nil, false) + + got := view(t, &o) + + assert.Contains(t, got, "time 96% / 4%", "2s scanning against 92ms rendering") + assert.Contains(t, got, "memory 86% / 14%", "356 MB against 56 MB") + assert.Contains(t, got, "scanning / rendering", "which way round the pairs read") + assert.NotContains(t, got, "cpu ", "there is no CPU account without a profile") +} + +// The sampled CPU split joins the recap only when there is one, and is the honest clock: wall time counts waiting. +func TestOverlayRecapsTheSampledCPU(t *testing.T) { + o := runstats.New() + o.Set(aRun(), aProfile(), false) + o.SetSize(160, 120) + + assert.Contains(t, testutils.StripANSI(o.View()), "cpu 96% / 4%", "2s of samples against 90ms") +} + +// Halves rounded independently produce "96% / 5%", which reads as an arithmetic error in a line meant to be glanced at. +func TestOverlayRecapAddsUp(t *testing.T) { + run := aRun() + run.ScanFor, run.RenderFor = 955*time.Millisecond, 45*time.Millisecond + run.AllocScan, run.AllocRender = 0, 0 + + o := runstats.New() + o.Set(run, nil, false) + + got := view(t, &o) + + assert.Contains(t, got, "time 96% / 4%") + assert.Contains(t, got, "memory n/a", "a phase pair that allocated nothing has no ratio to report") +} + +// The figures are read here and nowhere else, so what they do not mean has to be on the card. +func TestOverlayDisclosesWhatItMeasured(t *testing.T) { + o := runstats.New() + + o.Set(aRun(), nil, false) + first := view(t, &o) + assert.Contains(t, first, "other goroutines", "the window is process-wide") + assert.NotContains(t, first, "replaced a spec", "the first run replaced nothing") + + o.Set(aRun(), nil, true) + assert.Contains(t, view(t, &o), "replaced a spec", + "a rescan was measured while the previous document was still live") +} + +func TestOverlayBeforeAnyRun(t *testing.T) { + o := runstats.New() + + got := view(t, &o) + + assert.Contains(t, got, "no run measured yet") + assert.NotContains(t, got, "allocated", "a zero cost must not be shown as a measurement") +} + +// aProfile is what a profiled run hands over: who spent the CPU, who asked for the memory, and where the artifacts are. +func aProfile() *scan.ProfileReport { + return &scan.ProfileReport{ + Dir: "/tmp/genspec-tui-profile-42", + MemPaths: []string{"/tmp/p/mem-before.pprof", "/tmp/p/mem-after-scan.pprof", "/tmp/p/mem-after-render.pprof"}, + Scan: scan.PhaseProfile{ + Label: "scanning", + CPUPath: "/tmp/genspec-tui-profile-42/cpu-scan.pprof", + CPUTotal: 2 * time.Second, + CPUSamples: 200, + CPU: []scan.Func{ + {Name: "go/types.(*Checker).checkFiles", Flat: 900 * time.Millisecond, Share: 0.45}, + { + Name: "github.com/go-openapi/codescan/internal/builders/schema.(*Builder).Build", + Flat: time.Second / 2, + Share: 0.25, + }, + }, + Alloc: []scan.Site{{Name: "go/parser.ParseFile", Bytes: 182 * mb, Objects: 410_000}}, + }, + Render: scan.PhaseProfile{ + Label: "rendering", + CPUPath: "/tmp/genspec-tui-profile-42/cpu-render.pprof", + CPUTotal: 90 * time.Millisecond, + CPUSamples: 9, + CPU: []scan.Func{{Name: "encoding/json.Marshal", Flat: 90 * time.Millisecond, Share: 1}}, + Alloc: []scan.Site{ + {Name: "encoding/json.Marshal", Bytes: 48 * mb, Objects: 12_000}, + {Name: "go.yaml.in/yaml/v3.yaml_emitter_emit", Bytes: 5 * mb, Objects: 21}, + }, + }, + } +} + +func TestOverlayReportsAProfiledRun(t *testing.T) { + o := runstats.New() + o.Set(aRun(), aProfile(), false) + o.SetSize(160, 120) // tall enough that nothing is below the fold + + got := testutils.StripANSI(o.View()) + + assert.Contains(t, got, "Last run · profiled") + assert.Contains(t, got, "profiler's overhead", "the summary figures now carry the observer's cost") + assert.NotContains(t, got, "other goroutines", + "the process-wide caveat is answered by the tables: the noise arrives named") + + assert.Contains(t, got, "where the CPU went — scanning") + assert.Contains(t, got, "where the CPU went — rendering", "both phases are profiled, and both are reported") + assert.Contains(t, got, "types.(*Checker).checkFiles", "the repository path is trimmed off the symbol") + assert.NotContains(t, got, "github.com/go-openapi/codescan/internal/builders") + assert.Contains(t, got, "schema.(*Builder).Build") + assert.Contains(t, got, "45%") + + assert.Contains(t, got, "what allocated it — scanning") + assert.Contains(t, got, "182.0 MB") + assert.Contains(t, got, "what allocated it — rendering") + assert.Contains(t, got, "yaml/v3.yaml_emitter_emit", + "a major-version segment keeps the package before it: v3.yaml_emitter_emit names no library") + assert.Contains(t, got, "estimated from sampling") + + assert.Contains(t, got, "too few to rank functions", + "nine samples of rendering is a hint, and says so; two hundred of scanning does not") + assert.Contains(t, got, "/tmp/genspec-tui-profile-42/cpu-scan.pprof") + assert.Contains(t, got, "/tmp/genspec-tui-profile-42/cpu-render.pprof") + assert.Contains(t, got, "go tool pprof -http=: -base /tmp/p/mem-before.pprof /tmp/p/mem-after-scan.pprof", + "the command that reproduces the scanning phase in the real tool") +} + +// Exactness is a property of the run's sampling rate, and the reader has to be told which one they are looking at. +func TestOverlaySaysWhetherAllocationsWereCounted(t *testing.T) { + o := runstats.New() + report := aProfile() + report.Exact = true + o.Set(aRun(), report, false) + o.SetSize(160, 120) + + assert.Contains(t, testutils.StripANSI(o.View()), "every allocation counted") +} + +// A phase the sampler never caught says so, rather than showing an empty table that reads as "nothing allocated". +func TestOverlayOnAnEmptyPhase(t *testing.T) { + o := runstats.New() + report := aProfile() + report.Render.Alloc = nil + o.Set(aRun(), report, false) + o.SetSize(160, 120) + + assert.Contains(t, testutils.StripANSI(o.View()), "nothing sampled in this phase") +} + +// The tables do not fit a terminal, and a table below the fold is a measurement nobody knows was taken. +func TestOverlayScrolls(t *testing.T) { + o := runstats.New() + o.Set(aRun(), aProfile(), false) + o.SetSize(120, 24) + + head := testutils.StripANSI(o.View()) + assert.Contains(t, head, " of ", "the footer says how much is below") + assert.NotContains(t, head, "cpu-scan.pprof", "the artifacts are further down") + + _ = o.HandleKey(tea.KeyMsg{Type: tea.KeyEnd}) + tail := testutils.StripANSI(o.View()) + + assert.NotEqual(t, head, tail, "End moved the window") + assert.Contains(t, tail, "cpu-scan.pprof") + assert.Equal(t, width(head), width(tail), "the frame is pinned, so the box does not twitch as it scrolls") +} + +func TestOverlayOpensAndCloses(t *testing.T) { + for _, msg := range []tea.KeyMsg{ + {Type: tea.KeyEsc}, + testutils.KeyRune('m'), + {Type: tea.KeyEnter}, + } { + o := runstats.New() + o.Open() + require.True(t, o.IsOpen()) + + _ = o.HandleKey(msg) + + assert.False(t, o.IsOpen(), "%v closes the card", msg) + } +} + +// The card covers the UI, so a key it does not own is swallowed rather than acted on behind it. +func TestOverlaySwallowsOtherKeys(t *testing.T) { + o := runstats.New() + o.Open() + + for _, msg := range []tea.KeyMsg{testutils.KeyRune('r'), testutils.KeyRune('j'), {Type: tea.KeyF3}} { + assert.Nil(t, o.HandleKey(msg)) + assert.True(t, o.IsOpen(), "%v left the card open", msg) + } +} + +// The frame is pinned to the widest line it can show, so the box does not resize as the figures change. +func TestOverlayFrameIsStable(t *testing.T) { + o := runstats.New() + o.Set(aRun(), nil, false) + narrow := width(view(t, &o)) + + big := aRun() + big.AllocScan = 3 * 1024 * mb + o.Set(big, nil, true) + + assert.GreaterOrEqual(t, width(view(t, &o)), narrow, "a wider figure widens the frame rather than clipping") +} + +func width(s string) int { + w := 0 + for line := range strings.SplitSeq(s, "\n") { + w = max(w, len([]rune(line))) + } + + return w +} diff --git a/cmd/genspec-tui/internal/ux/runstats_test.go b/cmd/genspec-tui/internal/ux/runstats_test.go new file mode 100644 index 00000000..f4e77caa --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats_test.go @@ -0,0 +1,127 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +// Tests for the run-cost card: the key that opens it, and what the model feeds it. + +package ux + +import ( + "errors" + "testing" + + tea "github.com/charmbracelet/bubbletea" + + "github.com/go-openapi/testify/v2/assert" + "github.com/go-openapi/testify/v2/require" + + "github.com/go-openapi/codescan" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/scan" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/testutils" +) + +// errScanFailed stands in for a hard error out of codescan.Run. +var errScanFailed = errors.New("no packages") + +func TestRunStats_OpensOnM(t *testing.T) { + m := testModel(t, sized(100, 40)) + + _ = m.handleKey(testutils.KeyRune('m')) + + assert.True(t, m.runstats.IsOpen(), "m opens the run-cost card") + assert.Contains(t, testutils.StripANSI(m.runstats.View()), "Last run") +} + +func TestRunStats_CapturesKeysWhileOpen(t *testing.T) { + m := testModel(t, sized(100, 40)) + _ = m.handleKey(testutils.KeyRune('m')) + require.True(t, m.runstats.IsOpen()) + + for _, msg := range []tea.KeyMsg{testutils.KeyRune('r'), testutils.KeyRune('o'), testutils.KeyRune('/')} { + _ = m.handleKey(msg) + } + + assert.True(t, m.runstats.IsOpen(), "still open") + assert.False(t, m.scan.Running, "r did not start a scan behind the card") + assert.False(t, m.options.IsOpen(), "o did not open the options behind the card") + assert.False(t, m.search.Active(), "/ did not open search behind the card") + + _ = m.handleKey(tea.KeyMsg{Type: tea.KeyEsc}) + assert.False(t, m.runstats.IsOpen()) +} + +// m is an ordinary character in the editor; opening a modal there would make the buffer unusable. +func TestRunStats_DoesNotHijackTheEditor(t *testing.T) { + m := testModel(t, sized(100, 40)) + m.loadFileQuietly(testutils.WriteTempGo(t, "package p\n")) + m.focused, m.leftMode = paneTree, modeView + _ = m.fileView.StartEdit() + require.True(t, m.fileView.Editing()) + + _ = m.handleKey(testutils.KeyRune('m')) + + assert.False(t, m.runstats.IsOpen(), "m typed into the editor is a character, not a command") +} + +// The card reports the run the model absorbed, and is told whether that run replaced a document - which is what makes +// its retained figure readable. +func TestRunStats_TakesTheCostFromTheScan(t *testing.T) { + m := testModel(t, sized(100, 40)) + + first := scan.ResultMsg{JSON: "{}", Cost: scan.Cost{Measured: true, AllocScan: 4 << 20, LiveAfter: 2 << 20}} + m.absorbScan(first) + + require.True(t, m.scan.Cost.Measured, "the model keeps what the run cost") + assert.Equal(t, uint64(4<<20), m.scan.Cost.AllocScan) + assert.NotContains(t, testutils.StripANSI(m.runstats.View()), "replaced a spec", + "nothing was held before the first scan") + + m.absorbScan(first) + assert.Contains(t, testutils.StripANSI(m.runstats.View()), "replaced a spec", + "the second run was measured with the first document still live") +} + +// The whole point of the profiled mode: what the process-wide figures cannot attribute, the tables name. +func TestRunStats_ProfiledRunNamesWhoSpentIt(t *testing.T) { + dir := t.TempDir() + + res := scan.Do(codescan.Options{ + WorkDir: fixturesDir(t), + Packages: []string{"./goparsing/classification/..."}, + }, scan.Profiling{Enabled: true, Dir: dir}) + require.NoError(t, res.Err) + + report := res.Profile + require.NotNil(t, report, "a profiled run reports") + assert.Len(t, report.MemPaths, scan.MemSnapshots) + require.NotEmpty(t, report.Scan.Alloc, "scanning allocates, and the profiler says where") + assert.NotEmpty(t, report.Scan.Alloc[0].Name) + + // Tall enough for the whole card: what scrolling does to it is the overlay's own business, and is tested there. + m := testModelIn(t, fixturesDir(t), sized(200, 120)) + _, _ = m.Update(res) + _ = m.handleKey(testutils.KeyRune('m')) + + card := testutils.StripANSI(m.runstats.View()) + assert.Contains(t, card, "profiled") + assert.Contains(t, card, "what allocated it — scanning") + assert.Contains(t, card, report.Dir, "the artifacts are named where they were written") + assert.Contains(t, card, "go tool pprof", "with the command that opens them") + + // Both phases are bracketed, and each says what it caught - a small corpus renders far too fast to sample, and + // that is a measurement rather than a gap. + assert.Contains(t, card, "where the CPU went — scanning") + assert.Contains(t, card, "where the CPU went — rendering") + if !report.Render.Sampled() { + assert.Contains(t, card, "nothing sampled") + } +} + +// A run that failed still costs something, and the reading is the only account of where it went. +func TestRunStats_KeepsTheCostOfAFailedScan(t *testing.T) { + m := testModel(t, sized(100, 40)) + + m.absorbScan(scan.ResultMsg{Err: errScanFailed, Cost: scan.Cost{Measured: true, AllocScan: 1 << 20}}) + + assert.True(t, m.scan.Cost.Measured) + assert.Contains(t, testutils.StripANSI(m.runstats.View()), "allocated") +} diff --git a/cmd/genspec-tui/internal/ux/scan/cost.go b/cmd/genspec-tui/internal/ux/scan/cost.go new file mode 100644 index 00000000..1afe58fa --- /dev/null +++ b/cmd/genspec-tui/internal/ux/scan/cost.go @@ -0,0 +1,119 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package scan + +import ( + "runtime" + "time" +) + +// Cost is what one scan cost to run: how long each half took, and what the process's memory did across it. +// +// Two things it is NOT, both of which the overlay showing it has to say out loud: +// +// It is not codescan's cost. [runtime.ReadMemStats] accounts for the whole process, and while a scan runs the render +// loop, the spinner ticking at ~10Hz and the file watcher all allocate on other goroutines. This is everything the +// process allocated across the scan window - the only figure a process can honestly report about itself. +// +// It is not a peak. Three fences give three readings, and a scan that balloons and drops back between two of them +// leaves no trace here. Sampling would catch that, and would perturb what it measures (ReadMemStats stops the world). +// +// Every field is a difference between fences, computed once in costOf rather than re-derived wherever it is shown. +type Cost struct { + // Measured distinguishes a real reading from the zero value - the state before the first scan lands, where every + // difference would otherwise read as a legitimate zero. + Measured bool + + // ScanFor / RenderFor split the wall clock the same way the memory figures are split. + ScanFor time.Duration + RenderFor time.Duration + + // AllocScan / AllocRender are what was allocated in each half, garbage included: the churn, not the retention. + AllocScan uint64 + AllocRender uint64 + + // RetainScan / RetainRender are what each half left live behind it. Signed, because a half that triggers a + // collection can finish with less live than it started with. + RetainScan int64 + RetainRender int64 + + // LiveBefore / LiveAfter are the live heap at the outer fences, so the retained difference can be read against the + // size it moved from. + LiveBefore uint64 + LiveAfter uint64 + + // Objects is the change in live heap objects, which says whether the retained bytes are a few big buffers or a + // great many small nodes. + Objects int64 + + // GCCycles is how many collections ran across the window, and Sys how much memory the process holds from the OS at + // the end - effectively a high-water mark, since the Go runtime rarely gives it back. + GCCycles uint32 + Sys uint64 +} + +// Allocated is the whole run's churn. +func (c Cost) Allocated() uint64 { return c.AllocScan + c.AllocRender } + +// Retained is what the whole run left live. The two halves sum to it by construction. +func (c Cost) Retained() int64 { return c.RetainScan + c.RetainRender } + +// memFence is one reading of the process's memory, taken at one of the three points [Do] measures. +type memFence struct { + total uint64 // TotalAlloc: everything ever allocated, garbage included + live uint64 // HeapAlloc: what is live at this instant + objects uint64 // HeapObjects: how many things that live heap is made of + gc uint32 // NumGC + sys uint64 // Sys: obtained from the OS +} + +// fence reads the runtime's account of the process. +// +// Deliberately without a runtime.GC() first, the same call cmd/genspec-wasi makes: forcing a collection would report a +// tidier heap than the one the scan actually ran with, which is the opposite of the question being asked. +func fence() memFence { + var m runtime.MemStats + runtime.ReadMemStats(&m) + + return memFence{total: m.TotalAlloc, live: m.HeapAlloc, objects: m.HeapObjects, gc: m.NumGC, sys: m.Sys} +} + +// costOf differences the three fences: before the scan, after it, and after the document has been rendered. +// +// A run that failed passes the same fence twice, which reports the failed half honestly (whatever it managed to +// allocate) and the half that never ran as zero. +func costOf(before, scanned, rendered memFence, scanFor, renderFor time.Duration) Cost { + return Cost{ + Measured: true, + ScanFor: scanFor, + RenderFor: renderFor, + + AllocScan: scanned.total - before.total, + AllocRender: rendered.total - scanned.total, + + RetainScan: diff(scanned.live, before.live), + RetainRender: diff(rendered.live, scanned.live), + + LiveBefore: before.live, + LiveAfter: rendered.live, + + Objects: diff(rendered.objects, before.objects), + GCCycles: rendered.gc - before.gc, + Sys: rendered.sys, + } +} + +// diff subtracts two readings as a signed change. +// +// Heap figures are unsigned but their difference is not: a collection between two fences legitimately makes the later +// reading the smaller one. +func diff(after, before uint64) int64 { + if after >= before { + //nolint:gosec // a heap difference cannot approach MaxInt64; the guard is on the direction, not the magnitude + return int64(after - before) + } + + //nolint:gosec // same + return -int64(before - after) +} diff --git a/cmd/genspec-tui/internal/ux/scan/cost_test.go b/cmd/genspec-tui/internal/ux/scan/cost_test.go new file mode 100644 index 00000000..799ec871 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/scan/cost_test.go @@ -0,0 +1,79 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package scan + +import ( + "testing" + "time" + + "github.com/go-openapi/testify/v2/assert" + "github.com/go-openapi/testify/v2/require" +) + +func TestCostOf(t *testing.T) { + before := memFence{total: 1_000, live: 500, objects: 40, gc: 3, sys: 9_000} + scanned := memFence{total: 5_000, live: 2_500, objects: 190, gc: 6, sys: 12_000} + rendered := memFence{total: 6_000, live: 3_000, objects: 210, gc: 7, sys: 13_000} + + c := costOf(before, scanned, rendered, 2*time.Second, 100*time.Millisecond) + + require.True(t, c.Measured) + assert.Equal(t, 2*time.Second, c.ScanFor) + assert.Equal(t, 100*time.Millisecond, c.RenderFor) + + assert.Equal(t, uint64(4_000), c.AllocScan) + assert.Equal(t, uint64(1_000), c.AllocRender) + assert.Equal(t, uint64(5_000), c.Allocated(), "the halves account for the whole run's churn") + + assert.Equal(t, int64(2_000), c.RetainScan) + assert.Equal(t, int64(500), c.RetainRender) + assert.Equal(t, int64(2_500), c.Retained()) + assert.Equal(t, c.Retained(), diff(c.LiveAfter, c.LiveBefore), + "the split must agree with the outer fences it is derived from") + + assert.Equal(t, int64(170), c.Objects) + assert.Equal(t, uint32(4), c.GCCycles) + assert.Equal(t, uint64(13_000), c.Sys, "Sys is read at the end, not differenced") +} + +// A half that collects more than it allocates finishes with LESS live than it started with. Reading that as an unsigned +// difference would report an enormous positive number - the whole point of holding the retained figures signed. +func TestCostOfAcrossACollection(t *testing.T) { + before := memFence{total: 1_000, live: 900, objects: 90} + scanned := memFence{total: 5_000, live: 300, objects: 20} + rendered := memFence{total: 5_500, live: 400, objects: 25} + + c := costOf(before, scanned, rendered, time.Second, time.Second) + + assert.Equal(t, int64(-600), c.RetainScan) + assert.Equal(t, int64(100), c.RetainRender) + assert.Equal(t, int64(-500), c.Retained()) + assert.Equal(t, int64(-65), c.Objects) + assert.Equal(t, uint64(4_500), c.Allocated(), "churn is unaffected: TotalAlloc only ever grows") +} + +// A run that failed is fenced twice at the same point, so the half that never happened reads as zero rather than as +// something the reader has to discount. +func TestCostOfAFailedRun(t *testing.T) { + before := memFence{total: 1_000, live: 500} + scanned := memFence{total: 3_000, live: 1_500} + + c := costOf(before, scanned, scanned, time.Second, 0) + + assert.Equal(t, uint64(2_000), c.AllocScan) + assert.Zero(t, c.AllocRender) + assert.Zero(t, c.RetainRender) + assert.Equal(t, uint64(1_500), c.LiveAfter) +} + +func TestZeroCostIsNotAMeasurement(t *testing.T) { + assert.False(t, Cost{}.Measured, + "the state before the first scan must be distinguishable from a run that cost nothing") +} + +func TestDiff(t *testing.T) { + assert.Equal(t, int64(5), diff(15, 10)) + assert.Equal(t, int64(-5), diff(10, 15)) + assert.Zero(t, diff(10, 10)) +} diff --git a/cmd/genspec-tui/internal/ux/scan/profile.go b/cmd/genspec-tui/internal/ux/scan/profile.go new file mode 100644 index 00000000..cbbd4d68 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/scan/profile.go @@ -0,0 +1,521 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package scan + +import ( + "bytes" + "fmt" + "math" + "os" + "path/filepath" + "runtime" + "runtime/pprof" + "sort" + "strings" + "sync" + "time" + + "github.com/google/pprof/profile" +) + +// Profiling is what a run was asked to capture, and where the artifacts go. +// +// Off by default, and switched at launch rather than from the options overlay: [runtime.MemProfileRate] is meant to be +// set once and held constant for the life of the process, so a mid-session toggle would make consecutive readings +// incomparable - and a rate low enough to be exact is expensive enough to change what it measures. +type Profiling struct { + Enabled bool + + // Dir is where the .pprof artifacts are written, so the same run can be opened in go tool pprof. + Dir string +} + +// ProfileReport is what a profiled run observed, already reduced to what a reader is shown. +// +// This is the account that the [Cost] figures cannot give. Cost is a process-wide scalar: while a scan runs, the +// redraw loop and the file watcher allocate on other goroutines, and no arithmetic separates them out afterwards. A +// profile is per stack, so the same noise arrives named - a row to discount rather than a confound. +type ProfileReport struct { + Dir string + + // MemPaths are the heap snapshots, in fence order, for opening the same run in the real tool. + MemPaths []string + + // Scan and Render are the two phases, measured the same way. Rendering is the shorter by far - often too short + // for the CPU sampler to catch anything - but that is a fact about a particular run, and one the reader is told + // rather than one this design decides for them. + Scan PhaseProfile + Render PhaseProfile + + // Exact says the allocation figures are counted rather than estimated (MemProfileRate 1). + Exact bool + + // Notes carries whatever went wrong. A profile is an observation of the run, never a precondition for it, so a + // failure here is reported and nothing more. + Notes []string +} + +// PhaseProfile is what the profiler saw during one phase of a run. +type PhaseProfile struct { + // Label names the phase in the report, and in the note when it could not be sampled. + Label string + + // CPUPath is the profile written for this phase, empty when it could not be captured. + CPUPath string + + // CPUTotal is the CPU time the samples account for, which is not the wall clock: it counts every goroutine that + // ran, and counts nothing while they were all blocked. + CPUTotal time.Duration + // CPUSamples is how many samples that time is made of. The sampler runs at 100 Hz, so a phase shorter than its + // interval yields none at all, and a handful ranks nothing: the count is what says how much to believe the table. + CPUSamples int64 + CPU []Func + + // Alloc attributes what the phase allocated to the site that asked for it. + Alloc []Site +} + +// Sampled reports whether the CPU sampler caught anything in this phase. +func (p PhaseProfile) Sampled() bool { return len(p.CPU) > 0 } + +// Func is one function's flat share of the CPU samples. +type Func struct { + Name string + Flat time.Duration + Share float64 +} + +// Site is one allocation site: the function that asked for the memory, and how much of it. +type Site struct { + Name string + Bytes int64 + Objects int64 +} + +// MemSnapshots is how many heap snapshots a complete run leaves behind: before, after scanning, after rendering. +// +// Exported because a reader of the report has to know that the first two bracket the scan and the last two the +// render - which is what makes `go tool pprof -base` reproduce either phase. +const MemSnapshots = 3 + +// topN is how many rows of each table the card shows. Past this the tail is noise a reader would not act on, and the +// artifacts are on disk for anyone who wants all of it. +const topN = 8 + +// cpuProfiler serializes profiled runs. +// +// The CPU profiler is a process-wide singleton, and two scans can genuinely be in flight at once - changing an option +// while one is running starts another. Rather than have the second fail (or, worse, stop the first one's profile), it +// runs unprofiled and says so. +// +//nolint:gochecknoglobals // the resource being guarded is itself process-global +var cpuProfiler sync.Mutex + +// profiler captures a run. The zero value is the disabled profiler, whose methods all do nothing. +type profiler struct { + report *ProfileReport + + cpuFile *os.File + cpuPhase *PhaseProfile // the phase the open profile belongs to + held bool // whether the CPU profiler singleton is ours + + before []runtime.MemProfileRecord + scanned []runtime.MemProfileRecord +} + +// newProfiler starts a profiled run, or returns the disabled profiler when one was not asked for (or cannot be had). +func newProfiler(p Profiling) *profiler { + if !p.Enabled { + return &profiler{} + } + + prof := &profiler{report: &ProfileReport{Dir: p.Dir, Exact: runtime.MemProfileRate == 1}} + + if err := os.MkdirAll(p.Dir, 0o750); err != nil { + prof.notef("no profile directory: %v", err) + + return prof + } + + prof.report.Scan.Label, prof.report.Render.Label = "scanning", "rendering" + + // Held for the WHOLE run, not per phase: the two phases are profiled one after the other, and letting go between + // them would let another scan take the sampler halfway through this one's measurement. + if !cpuProfiler.TryLock() { + prof.notef("another profiled scan is in flight; this one is not CPU profiled") + } else { + prof.held = true + prof.startCPU(&prof.report.Scan, "cpu-scan.pprof") + } + + prof.before = prof.snapshot(filepath.Join(p.Dir, "mem-before.pprof")) + + return prof +} + +// startCPU begins sampling into phase's own profile, giving up quietly (with a note) if it cannot. +func (p *profiler) startCPU(phase *PhaseProfile, name string) { + if !p.held { + return // the sampler belongs to another run + } + + path := filepath.Join(p.report.Dir, name) + f, err := os.Create(path) + if err != nil { + p.notef("no CPU profile for %s: %v", phase.Label, err) + + return + } + if err := pprof.StartCPUProfile(f); err != nil { + p.notef("no CPU profile for %s: %v", phase.Label, err) + _ = f.Close() + + return + } + p.cpuFile = f + p.cpuPhase = phase + phase.CPUPath = path +} + +// scanDone closes the scanning phase and opens the rendering one. +// +// Each phase gets its own CPU profile rather than one profile split by reading the stacks: the phases are sequential, +// so the bracket is exact, and rendering - the shorter by far - is then measured the same way as the scan rather than +// being assumed too small to look at. +func (p *profiler) scanDone() { + if p.report == nil { + return + } + + // The sampler stops before the heap snapshot, so the snapshot's own work is not attributed to the scan, and the + // next phase's sampler starts after it for the same reason. + p.stopCPU() + p.scanned = p.snapshot(filepath.Join(p.report.Dir, "mem-after-scan.pprof")) + p.startCPU(&p.report.Render, "cpu-render.pprof") +} + +// done closes the run and reduces everything captured into the report. +func (p *profiler) done() *ProfileReport { + if p.report == nil { + return nil + } + + p.stopCPU() // no-op unless the run failed before scanDone + rendered := p.snapshot(filepath.Join(p.report.Dir, "mem-after-render.pprof")) + if p.scanned == nil { + // The run never reached rendering, so everything it allocated belongs to the scan - the same convention the + // cost fences follow when they close on the phase that failed. + p.scanned = rendered + } + + p.report.Scan.Alloc = sites(p.before, p.scanned) + p.report.Render.Alloc = sites(p.scanned, rendered) + p.readCPU(&p.report.Scan) + p.readCPU(&p.report.Render) + p.release() + + return p.report +} + +// stopCPU ends sampling for the phase in flight. Safe to call twice. +func (p *profiler) stopCPU() { + if p.cpuFile == nil { + return + } + + pprof.StopCPUProfile() + if err := p.cpuFile.Close(); err != nil { + p.notef("CPU profile for %s not written: %v", p.cpuPhase.Label, err) + p.cpuPhase.CPUPath = "" + } + p.cpuFile = nil + p.cpuPhase = nil +} + +// release hands the sampler back, once the whole run is measured. +func (p *profiler) release() { + if p.held { + cpuProfiler.Unlock() + p.held = false + } +} + +// snapshot records the allocation profile at one fence, and writes it out for go tool pprof. +// +// It forces a collection first - the exact opposite of the rule the unprofiled fences follow, and right here for the +// same reason it is wrong there. [runtime.MemProfile] is only current as of the last collection, so a phase measured +// without one loses its tail; and a profiled run is asking to be measured accurately, having already accepted that it +// is not measuring itself. +func (p *profiler) snapshot(path string) []runtime.MemProfileRecord { + runtime.GC() + + records := memRecords() + + f, err := os.Create(path) + if err != nil { + p.notef("no heap snapshot: %v", err) + + return records + } + defer func() { _ = f.Close() }() + + if err := pprof.WriteHeapProfile(f); err != nil { + p.notef("no heap snapshot: %v", err) + + return records + } + p.report.MemPaths = append(p.report.MemPaths, path) + + return records +} + +// readCPU parses back the profile we just wrote and reduces it to the functions that spent the time. +// +// Parsing our own output rather than sampling in parallel: the file is the artifact anyway, and one reduction of one +// source cannot disagree with itself. +func (p *profiler) readCPU(phase *PhaseProfile) { + if phase.CPUPath == "" { + return + } + + raw, err := os.ReadFile(phase.CPUPath) + if err != nil { + p.notef("CPU profile for %s unreadable: %v", phase.Label, err) + + return + } + + prof, err := profile.Parse(bytes.NewReader(raw)) + if err != nil { + p.notef("CPU profile for %s unparseable: %v", phase.Label, err) + + return + } + + phase.CPU, phase.CPUTotal, phase.CPUSamples = cpuFuncs(prof) +} + +func (p *profiler) notef(format string, args ...any) { + if p.report == nil { + return + } + p.report.Notes = append(p.report.Notes, fmt.Sprintf(format, args...)) +} + +// memRecords reads the whole allocation profile. +// +// The retry is the documented dance: the count can grow between asking how many records there are and reading them. +func memRecords() []runtime.MemProfileRecord { + // inuseZero true: a phase's allocations count whether or not they survived it, which is the question being asked. + n, _ := runtime.MemProfile(nil, true) + for range 3 { + records := make([]runtime.MemProfileRecord, n+64) + var ok bool + n, ok = runtime.MemProfile(records, true) + if ok { + return records[:n] + } + } + + return nil +} + +// sites attributes what was allocated between two fences to the function that asked for it. +// +// Flat attribution, to the innermost frame: "who called make" is the question a reader acts on, and a cumulative tree +// in a terminal table would answer a different one badly. +func sites(before, after []runtime.MemProfileRecord) []Site { + base := make(map[uint64]runtime.MemProfileRecord, len(before)) + for _, r := range before { + base[key(r)] = r + } + + byFunc := make(map[string]*Site) + for _, r := range after { + bytesN, objects := r.AllocBytes, r.AllocObjects + if b, seen := base[key(r)]; seen { + bytesN -= b.AllocBytes + objects -= b.AllocObjects + } + if objects <= 0 || bytesN <= 0 { + continue + } + objects, bytesN = unsample(objects, bytesN) + + name, ours := frameName(r.Stack()) + if ours { + // The profiler's own allocations, excluded rather than reported: stopping one phase's CPU profile flushes it + // through a compressor, and starting the next allocates its buffers, all of it between two fences. Left in, + // the rendering table - the short phase, where it is a visible share - would be reporting the observer. + continue + } + site, seen := byFunc[name] + if !seen { + site = &Site{Name: name} + byFunc[name] = site + } + site.Bytes += bytesN + site.Objects += objects + } + + return rank(byFunc) +} + +// rank orders the sites by what they allocated and keeps the head of the table. +// +// The tail is not lost, only unshown: every record is in the heap snapshots on disk, where a reader who wants the long +// version has the real tool to read it with. +func rank(byFunc map[string]*Site) []Site { + out := make([]Site, 0, len(byFunc)) + for _, s := range byFunc { + out = append(out, *s) + } + sort.Slice(out, func(i, j int) bool { + if out[i].Bytes != out[j].Bytes { + return out[i].Bytes > out[j].Bytes + } + + return out[i].Name < out[j].Name + }) + + return out[:min(len(out), topN)] +} + +// key identifies a record across two snapshots, by hashing its whole call stack. +// +// The whole stack, and with a real mixer, because a collision here does not merely misattribute a row: two records +// sharing a key make one of them difference against the other's counters, which manufactures allocation that never +// happened - including in the phase where a fence was closed twice on the same snapshot and the answer must be zero. +func key(r runtime.MemProfileRecord) uint64 { + const ( + offset64 = 14695981039346656037 + prime64 = 1099511628211 + ) + + h := uint64(offset64) + for _, pc := range r.Stack() { + h ^= uint64(pc) + h *= prime64 + } + + return h +} + +// unsample corrects a sampled record back to what it estimates was really allocated. +// +// The heap profiler samples one allocation per MemProfileRate bytes, so a record stands for more than it recorded, and +// by how much depends on the size of the objects it saw: at the default rate a stack allocating 8-byte nodes is +// sampled far more rarely per byte than one allocating megabyte buffers. This is the correction pprof itself applies +// (scaleHeapSample) - without it the table would under-report by orders of magnitude and disagree with the card above +// it. +func unsample(objects, bytesN int64) (int64, int64) { + rate := int64(runtime.MemProfileRate) + if rate <= 1 || objects == 0 || bytesN == 0 { + return objects, bytesN // every allocation was recorded: the counts are the truth + } + + avg := float64(bytesN) / float64(objects) + scale := 1 / (1 - math.Exp(-avg/float64(rate))) + + return int64(float64(objects) * scale), int64(float64(bytesN) * scale) +} + +// frameName names the allocation site: the innermost frame outside the runtime. +// +// Every allocation passes through the same handful of runtime helpers - newobject, growslice, convTstring - so taking +// the innermost frame verbatim labels much of the table with the fact that memory was allocated, which is what the +// table is already about. The caller is the answer to "who asked for it". +// +// A stack that is runtime frames all the way down keeps its innermost one: it is a real answer, just a rarer one. +// +// ours reports that the stack is the profiler's own work rather than the run's. +func frameName(stack []uintptr) (name string, ours bool) { + if len(stack) == 0 { + return "(unknown)", false + } + + frames := runtime.CallersFrames(stack) + innermost, caller := "", "" + for { + f, more := frames.Next() + if f.Function != "" { + if strings.HasPrefix(f.Function, "runtime/pprof.") { + return "", true + } + if caller == "" && !strings.HasPrefix(f.Function, "runtime.") && !strings.HasPrefix(f.Function, "internal/") { + caller = f.Function + } + if innermost == "" { + innermost = f.Function + } + } + if !more { + break + } + } + + // The walk continues past the caller rather than returning at it, because a pprof frame further out is what marks + // the whole stack as the profiler's own. + switch { + case caller != "": + return caller, false + case innermost != "": + return innermost, false + default: + return "(unknown)", false + } +} + +// cpuFuncs reduces a parsed CPU profile to the functions that spent the time, flat, biggest first. +// +// The second sample value is the one to read: a CPU profile carries samples/count and cpu/nanoseconds, and time is +// what a reader is comparing against the wall clock on the card. +func cpuFuncs(prof *profile.Profile) ([]Func, time.Duration, int64) { + const ( + count = 0 // index of samples/count in a CPU profile's sample values + nanos = 1 // index of cpu/nanoseconds + ) + + if prof == nil || len(prof.SampleType) <= nanos { + return nil, 0, 0 + } + + var total, samples int64 + byFunc := make(map[string]int64) + for _, s := range prof.Sample { + if len(s.Value) <= nanos || len(s.Location) == 0 { + continue + } + v := s.Value[nanos] + total += v + samples += s.Value[count] + byFunc[leafName(s.Location[0])] += v + } + if total == 0 { + return nil, 0, 0 + } + + out := make([]Func, 0, len(byFunc)) + for name, v := range byFunc { + out = append(out, Func{Name: name, Flat: time.Duration(v), Share: float64(v) / float64(total)}) + } + sort.Slice(out, func(i, j int) bool { + if out[i].Flat != out[j].Flat { + return out[i].Flat > out[j].Flat + } + + return out[i].Name < out[j].Name + }) + + return out[:min(len(out), topN)], time.Duration(total), samples +} + +// leafName names the function a sample was taken in. +func leafName(loc *profile.Location) string { + if loc == nil || len(loc.Line) == 0 || loc.Line[0].Function == nil { + return "(unknown)" + } + + return loc.Line[0].Function.Name +} diff --git a/cmd/genspec-tui/internal/ux/scan/profile_test.go b/cmd/genspec-tui/internal/ux/scan/profile_test.go new file mode 100644 index 00000000..5f71be7d --- /dev/null +++ b/cmd/genspec-tui/internal/ux/scan/profile_test.go @@ -0,0 +1,236 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package scan + +import ( + "context" + "fmt" + "runtime" + "runtime/pprof" + "testing" + "time" + + "github.com/google/pprof/profile" + + "github.com/go-openapi/testify/v2/assert" + "github.com/go-openapi/testify/v2/require" +) + +// record fabricates one profile record over a real call stack, so the frames it names resolve like the runtime's own. +// +// skip 2 puts the caller's own frame innermost, which is the site the table is expected to name. +func record(objects, bytesN int64) runtime.MemProfileRecord { + var r runtime.MemProfileRecord + r.AllocObjects, r.AllocBytes = objects, bytesN + runtime.Callers(2, r.Stack0[:]) + + return r +} + +// countEveryAllocation pins the sampling rate for a test whose figures are exact ones. +// +// Left at the default, every number below would come back multiplied by the sampling correction, which is tested on +// its own in TestUnsampleCorrectsForSampling. +func countEveryAllocation(t *testing.T) { + t.Helper() + + saved := runtime.MemProfileRate + t.Cleanup(func() { runtime.MemProfileRate = saved }) + runtime.MemProfileRate = 1 +} + +func TestSitesDifferenceTheFences(t *testing.T) { + countEveryAllocation(t) + + before := []runtime.MemProfileRecord{record(10, 1_000)} + after := []runtime.MemProfileRecord{record(25, 4_000)} + // Same stack in both, so the site must report the difference and not the total. + after[0].Stack0 = before[0].Stack0 + + got := sites(before, after) + + require.Len(t, got, 1) + assert.Equal(t, int64(3_000), got[0].Bytes, "what the phase allocated, not what the process had allocated") + assert.Equal(t, int64(15), got[0].Objects) + assert.Contains(t, got[0].Name, "TestSitesDifferenceTheFences", "attributed to the site that asked") + + name, ours := frameName(after[0].Stack()) + assert.False(t, ours) + assert.NotContains(t, name, "runtime.", "the runtime helper every allocation goes through names nobody") +} + +// A stack that only appears after the fence is entirely the phase's own. +func TestSitesCountsANewStackWhole(t *testing.T) { + countEveryAllocation(t) + + got := sites(nil, []runtime.MemProfileRecord{record(4, 512)}) + + require.Len(t, got, 1) + assert.Equal(t, int64(512), got[0].Bytes) +} + +// A stack that did not move between the fences allocated nothing during it, and would otherwise fill the table with +// rows reporting zero. +func TestSitesDropsWhatDidNotMove(t *testing.T) { + same := []runtime.MemProfileRecord{record(10, 1_000)} + + assert.Empty(t, sites(same, same)) +} + +// The same snapshot on both sides of a fence must difference to nothing, whatever it holds. +// +// This is the shape a failed run takes - it closes twice on the same reading - and a weak identity for a record turns +// it into a table of allocations that never happened, because two colliding stacks difference against each other. +func TestSitesIdentifiesRecordsByTheirWholeStack(t *testing.T) { + countEveryAllocation(t) + + snapshot := make([]runtime.MemProfileRecord, 0, 512) + for i := range 512 { + var r runtime.MemProfileRecord + r.AllocObjects, r.AllocBytes = int64(i+1), int64(i+1)*128 + // Synthetic stacks that a weaker key (a few frames, a weak mix) would fold together. + for depth := range 12 { + r.Stack0[depth] = uintptr(0x400000 + i*8 + depth) + } + snapshot = append(snapshot, r) + } + + assert.Empty(t, sites(snapshot, snapshot), "nothing happened between a fence and itself") +} + +// Observing a run costs allocations of its own - stopping a phase's CPU profile flushes it through a compressor, and +// starting the next allocates its buffers - and those land between two fences like anything else. Reported, they would +// crowd out the short phase's real sites with the observer's own work. +func TestSitesExcludesTheProfilersOwnWork(t *testing.T) { + countEveryAllocation(t) + + var ours runtime.MemProfileRecord + // pprof.Do puts a genuine runtime/pprof frame on the stack, which is what marks a record as the profiler's. + pprof.Do(context.Background(), pprof.Labels("k", "v"), func(context.Context) { + ours = record(1, 8*1024) + }) + mine := record(1, 8*1024) + + assert.Empty(t, sites(nil, []runtime.MemProfileRecord{ours}), "the profiler's own allocations are not the run's") + assert.Len(t, sites(nil, []runtime.MemProfileRecord{mine}), 1, "and everything else still counts") +} + +func TestRankOrdersAndCaps(t *testing.T) { + byFunc := make(map[string]*Site) + for i := range topN + 4 { + name := fmt.Sprintf("pkg.Func%02d", i) + byFunc[name] = &Site{Name: name, Bytes: int64(i+1) * 1_000, Objects: int64(i)} + } + + got := rank(byFunc) + + require.Len(t, got, topN, "the tail is on disk, not on the card") + assert.Equal(t, "pkg.Func11", got[0].Name, "biggest first") + for i := 1; i < len(got); i++ { + assert.Greater(t, got[i-1].Bytes, got[i].Bytes) + } +} + +// The heap profiler samples one allocation per MemProfileRate bytes, so a record stands for more than it saw. Without +// the correction the table would disagree with the figures above it by orders of magnitude. +func TestUnsampleCorrectsForSampling(t *testing.T) { + saved := runtime.MemProfileRate + t.Cleanup(func() { runtime.MemProfileRate = saved }) + + runtime.MemProfileRate = 1 + objects, bytesN := unsample(3, 300) + assert.Equal(t, int64(3), objects, "every allocation was recorded: nothing to estimate") + assert.Equal(t, int64(300), bytesN) + + runtime.MemProfileRate = 512 * 1024 + smallObjects, smallBytes := unsample(1, 64) // a 64-byte object is sampled once in ~8000 + assert.Greater(t, smallBytes, int64(64*1_000), "small allocations are scaled up hard") + assert.Greater(t, smallObjects, int64(1_000)) + + bigObjects, bigBytes := unsample(1, 8*1024*1024) // far above the rate: seen almost every time + assert.Less(t, bigBytes, int64(9*1024*1024), "a large allocation is barely scaled") + assert.Equal(t, int64(1), bigObjects) +} + +func TestCPUFuncsRanksByTime(t *testing.T) { + prof := &profile.Profile{ + SampleType: []*profile.ValueType{{Type: "samples", Unit: "count"}, {Type: "cpu", Unit: "nanoseconds"}}, + Sample: []*profile.Sample{ + {Value: []int64{1, int64(300 * time.Millisecond)}, Location: []*profile.Location{loc("scan")}}, + {Value: []int64{1, int64(200 * time.Millisecond)}, Location: []*profile.Location{loc("scan")}}, + {Value: []int64{1, int64(500 * time.Millisecond)}, Location: []*profile.Location{loc("render")}}, + }, + } + + got, total, samples := cpuFuncs(prof) + + require.Len(t, got, 2) + assert.Equal(t, time.Second, total) + assert.Equal(t, int64(3), samples, "how much the ranking is worth") + assert.Equal(t, "render", got[0].Name) + assert.InDelta(t, 0.5, got[0].Share, 0.001) + assert.Equal(t, "scan", got[1].Name, "the two scan samples fold into one row") + assert.Equal(t, 500*time.Millisecond, got[1].Flat) +} + +func TestCPUFuncsOnNothingSampled(t *testing.T) { + got, total, samples := cpuFuncs(&profile.Profile{ + SampleType: []*profile.ValueType{{Type: "samples"}, {Type: "cpu"}}, + }) + + assert.Empty(t, got) + assert.Zero(t, total) + assert.Zero(t, samples) + assert.Empty(t, func() []Func { g, _, _ := cpuFuncs(nil); return g }(), + "a profile that never parsed is not a panic") +} + +// The disabled profiler is the common case: it must cost nothing and produce no report. +func TestProfilerDisabled(t *testing.T) { + p := newProfiler(Profiling{}) + + p.scanDone() + + assert.Nil(t, p.done()) +} + +func TestProfilerCapturesARun(t *testing.T) { + dir := t.TempDir() + + p := newProfiler(Profiling{Enabled: true, Dir: dir}) + sink := make([][]byte, 0, 128) + for range 128 { + sink = append(sink, make([]byte, 8*1024)) + } + p.scanDone() + sink = append(sink, make([]byte, 64*1024)) + report := p.done() + runtime.KeepAlive(sink) + + require.NotNil(t, report) + assert.Equal(t, dir, report.Dir) + assert.Len(t, report.MemPaths, MemSnapshots, "one heap snapshot per fence, for go tool pprof -base") + assert.NotEmpty(t, report.Scan.Alloc, "the allocations between the first two fences are attributed") + assert.FileExists(t, report.Scan.CPUPath) + assert.FileExists(t, report.Render.CPUPath, "the rendering phase is bracketed too") +} + +// The CPU profiler is a process-wide singleton, so a second profiled run cannot have it - and must not take it from +// the first, nor fail the scan it belongs to. +func TestProfilerYieldsTheCPUSingleton(t *testing.T) { + first := newProfiler(Profiling{Enabled: true, Dir: t.TempDir()}) + second := newProfiler(Profiling{Enabled: true, Dir: t.TempDir()}) + + require.NotNil(t, second.done()) + assert.Contains(t, second.report.Notes[0], "another profiled scan is in flight") + assert.Empty(t, second.report.Scan.CPUPath) + + report := first.done() + require.NotNil(t, report) + assert.NotEmpty(t, report.Scan.CPUPath, "the run that got there first keeps its profile") +} + +func loc(fn string) *profile.Location { + return &profile.Location{Line: []profile.Line{{Function: &profile.Function{Name: fn}}}} +} diff --git a/cmd/genspec-tui/internal/ux/scan/scan.go b/cmd/genspec-tui/internal/ux/scan/scan.go index 7b4b7ce8..98cdc3d3 100644 --- a/cmd/genspec-tui/internal/ux/scan/scan.go +++ b/cmd/genspec-tui/internal/ux/scan/scan.go @@ -17,14 +17,16 @@ import ( // ResultMsg carries the outcome of a whole-scope scan. // -// The spec rendered as both JSON and YAML, path and definition counts for the header, how long the scan took, -// every diagnostic the build emitted in source order, and any hard error from codescan.Run. +// The spec rendered as both JSON and YAML, path and definition counts for the header, how long the scan took, what it +// cost to run, every diagnostic the build emitted in source order, and any hard error from codescan.Run. type ResultMsg struct { JSON string YAML string Paths int Defs int Elapsed time.Duration + Cost Cost + Profile *ProfileReport // nil unless the run was profiled Diags []grammar.Diagnostic Provenance []scanner.Provenance Err error @@ -36,10 +38,10 @@ type ResultMsg struct { // // It runs in a tea.Cmd goroutine so packages.Load latency never blocks the event loop. cfg is taken by value so the // goroutine has a stable snapshot even if the model mutates its options. -func Run(cfg codescan.Options) tea.Cmd { +func Run(cfg codescan.Options, prof Profiling) tea.Cmd { return func() tea.Msg { start := time.Now() - res := Do(cfg) + res := Do(cfg, prof) res.Elapsed = time.Since(start) return res } @@ -47,8 +49,15 @@ func Run(cfg codescan.Options) tea.Cmd { // Do performs the scan and rendering, returning the result without timing (runScan stamps the elapsed time around it). // +// It fences the work three times - before the scan, after it, and once the document has been rendered - so the result +// carries what the run cost as well as what it produced. The inner split is what makes the reading actionable: it +// separates what codescan spent from what serializing the same document twice, as JSON and again as YAML, spent on top. +// +// A profiled run brackets the same two phases with the profiler as well, so what the sampler says and what the fences +// say describe the same halves of the same work. +// // It is exposed by this package to allow for e2e tests. -func Do(cfg codescan.Options) ResultMsg { +func Do(cfg codescan.Options, prof Profiling) ResultMsg { // OnDiagnostic fires synchronously inside codescan.Run, on this same goroutine, so a plain append is race-free. // // Diagnostics collected before a hard error are still worth surfacing, so we carry them on every return. @@ -65,14 +74,32 @@ func Do(cfg codescan.Options) ResultMsg { provs = append(provs, p) } + // The profiler brackets each phase from OUTSIDE the fences: its own snapshots collect and allocate, and a fence + // that read after one of them would be reporting the profiler as well as the run. + p := newProfiler(prof) + before := fence() + + scanStart := time.Now() sw, err := codescan.Run(&cfg) + scanFor := time.Since(scanStart) + scanned := fence() + if err != nil { - return ResultMsg{Diags: diags, Provenance: provs, Err: err} + return ResultMsg{ + Diags: diags, Provenance: provs, Err: err, + Cost: costOf(before, scanned, scanned, scanFor, 0), Profile: p.done(), + } } + p.scanDone() + + renderStart := time.Now() jb, err := json.MarshalIndent(sw, "", " ") if err != nil { - return ResultMsg{Diags: diags, Provenance: provs, Err: err} + return ResultMsg{ + Diags: diags, Provenance: provs, Err: err, + Cost: costOf(before, scanned, fence(), scanFor, time.Since(renderStart)), Profile: p.done(), + } } res := ResultMsg{JSON: string(jb), Defs: len(sw.Definitions), Diags: diags, Provenance: provs} @@ -82,6 +109,11 @@ func Do(cfg codescan.Options) ResultMsg { if yb, yerr := jsonToYAML(jb); yerr == nil { res.YAML = string(yb) } + renderFor := time.Since(renderStart) + + res.Cost = costOf(before, scanned, fence(), scanFor, renderFor) + res.Profile = p.done() + return res } diff --git a/cmd/genspec-tui/internal/ux/scanflow.go b/cmd/genspec-tui/internal/ux/scanflow.go index 69872cc8..ec6c82c6 100644 --- a/cmd/genspec-tui/internal/ux/scanflow.go +++ b/cmd/genspec-tui/internal/ux/scanflow.go @@ -28,6 +28,10 @@ type ScanState struct { Spin spinner.Model Elapsed time.Duration + // What the run cost to produce, for the overlay m opens. Read from the runtime around the work itself, so it is + // carried here rather than derived: once the scan has returned, nobody can recover it. + Cost scan.Cost + NumPaths int NumDefs int @@ -127,7 +131,7 @@ type debounceMsg struct{ gen int } func (m *Model) startScan() tea.Cmd { already := m.scan.Running m.scan.Running = true - run := scan.Run(m.cfg) + run := scan.Run(m.cfg, m.profiling) if already { return run } @@ -143,13 +147,20 @@ func (m *Model) startScan() tea.Cmd { // The diagnostics cursor is clamped rather than reset - a scan that fixed one diagnostic should leave you next to the // ones it did not. func (m *Model) absorbScan(msg scan.ResultMsg) { + // Read before the assignment below drops it: a run that replaced a document was measured while BOTH were live, and + // the overlay has to say so or its retained figure reads as a leak. + replaced := m.scan.JSON != "" + m.scan.Running = false m.scan.JSON, m.scan.YAML = msg.JSON, msg.YAML m.scan.NumPaths, m.scan.NumDefs = msg.Paths, msg.Defs m.scan.Elapsed = msg.Elapsed + m.scan.Cost = msg.Cost m.scan.Diags = msg.Diags m.scan.Err = msg.Err + m.runstats.Set(msg.Cost, msg.Profile, replaced) + m.diagCursor = min(max(m.diagCursor, 0), max(len(m.scan.Diags)-1, 0)) m.srcIndex = index.BuildSourceIndex(msg.Provenance) m.retireValidation() // the findings judged the document this scan has just replaced diff --git a/cmd/genspec-tui/internal/ux/source_test.go b/cmd/genspec-tui/internal/ux/source_test.go index 46c804ba..e26680ee 100644 --- a/cmd/genspec-tui/internal/ux/source_test.go +++ b/cmd/genspec-tui/internal/ux/source_test.go @@ -503,7 +503,7 @@ func classificationScan(t *testing.T) scan.ResultMsg { classificationRes = scan.Do(codescan.Options{ WorkDir: fixturesDir(t), Packages: []string{"./goparsing/classification/..."}, - }) + }, scan.Profiling{}) }) require.NoError(t, classificationRes.Err) require.NotEmpty(t, classificationRes.Diags, "the corpus must produce diagnostics") diff --git a/cmd/genspec-tui/main.go b/cmd/genspec-tui/main.go index ed42cb2b..e33baa34 100644 --- a/cmd/genspec-tui/main.go +++ b/cmd/genspec-tui/main.go @@ -10,12 +10,14 @@ import ( "log" "os" "path/filepath" + "runtime" "strings" tea "github.com/charmbracelet/bubbletea" "github.com/go-openapi/codescan" "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux" + "github.com/go-openapi/codescan/cmd/genspec-tui/internal/ux/scan" ) // cliFlags holds the raw flag values. @@ -42,6 +44,11 @@ type cliFlags struct { excludeTags *string nameFromTags *string nameConcatBudget *float64 + + // Observation of the run rather than configuration of it, which is why these are not codescan options. + profile *bool + profileDir *string + memProfileRate *int } // registerFlags declares every flag on fs. @@ -77,7 +84,44 @@ func registerFlags(fs *flag.FlagSet) *cliFlags { `ordered struct tags a field's name derives from (default "json"; pass empty to use the Go field name)`), nameConcatBudget: fs.Float64("name-concat-budget", 0, "readability cutoff for collision-renaming by concatenation (0 = codescan's default of 0.65)"), + profile: fs.Bool("profile", false, + "profile every scan (CPU + allocations), reported under m and written for go tool pprof"), + profileDir: fs.String("profile-dir", "", + "where -profile writes its .pprof files (default: a fresh temp directory)"), + memProfileRate: fs.Int("mem-profile-rate", 0, + "with -profile, runtime.MemProfileRate: 0 samples every 512 KiB, 1 records every allocation exactly"), + } +} + +// profiling reads the profile flags, and applies the ones the runtime wants set before anything is measured. +// +// The heap sampling rate is a property of the process, not of a scan: the runtime expects it constant for the +// program's lifetime, and the profiles record the rate they were taken under. Setting it here, once, is what makes two +// runs in the same session comparable. +func (c *cliFlags) profiling() (scan.Profiling, error) { + if !*c.profile { + return scan.Profiling{}, nil + } + + if rate := *c.memProfileRate; rate > 0 { + runtime.MemProfileRate = rate + } + + dir := *c.profileDir + if dir == "" { + tmp, err := os.MkdirTemp("", "genspec-tui-profile-") + if err != nil { + return scan.Profiling{}, fmt.Errorf("cannot create a profile directory: %w", err) + } + dir = tmp } + + abs, err := filepath.Abs(dir) + if err != nil { + return scan.Profiling{}, err + } + + return scan.Profiling{Enabled: true, Dir: abs}, nil } // options assembles the scan config. workDir is passed in already absolute. @@ -163,7 +207,12 @@ func run() error { return err } - model := ux.New(cli.options(dir)) + prof, err := cli.profiling() + if err != nil { + return err + } + + model := ux.New(cli.options(dir), prof) defer model.Close() p := tea.NewProgram(model, tea.WithAltScreen(), tea.WithMouseCellMotion())