From 1a182dce18592745ea47988765663c2fd183e452 Mon Sep 17 00:00:00 2001 From: Frederic BIDON Date: Fri, 14 Aug 2026 11:15:28 +0200 Subject: [PATCH 1/2] feat(genspec-tui): report what a scan cost in time and memory m opens a card describing the run that just finished: what it allocated, what it left live, how many objects and collections that took, and how much the process holds from the OS. A modal rather than another status-line field, since that line already carries the pane hints, the follow badge and the search prompt. The run is fenced three times - before the scan, after it, and once the document has been rendered as JSON and YAML - so the card separates what codescan spent from what serializing its result spent on top. Two things the figures are not, stated on the card where they are read: the window is process-wide, because the redraw loop and the file watcher allocate on other goroutines meanwhile; and a rescan is measured while the document it replaces is still live, so its retained figure reads high by about one spec. Duration formatting moves to a humanize package alongside the new byte and count forms, so the header line and the card cannot drift into two spellings of the same measurement. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: Frederic BIDON --- cmd/genspec-tui/README.md | 1 + cmd/genspec-tui/internal/ux/chrome.go | 22 +-- cmd/genspec-tui/internal/ux/help/help.go | 1 + cmd/genspec-tui/internal/ux/humanize/doc.go | 8 + .../internal/ux/humanize/humanize.go | 86 +++++++++ .../internal/ux/humanize/humanize_test.go | 83 +++++++++ cmd/genspec-tui/internal/ux/key/bindings.go | 1 + cmd/genspec-tui/internal/ux/keys.go | 3 + cmd/genspec-tui/internal/ux/model.go | 3 + cmd/genspec-tui/internal/ux/overlay.go | 2 +- cmd/genspec-tui/internal/ux/render_test.go | 18 -- cmd/genspec-tui/internal/ux/runstats/doc.go | 9 + .../internal/ux/runstats/runstats.go | 172 ++++++++++++++++++ .../internal/ux/runstats/runstats_test.go | 144 +++++++++++++++ cmd/genspec-tui/internal/ux/runstats_test.go | 90 +++++++++ cmd/genspec-tui/internal/ux/scan/cost.go | 119 ++++++++++++ cmd/genspec-tui/internal/ux/scan/cost_test.go | 79 ++++++++ cmd/genspec-tui/internal/ux/scan/scan.go | 31 +++- cmd/genspec-tui/internal/ux/scanflow.go | 11 ++ 19 files changed, 840 insertions(+), 43 deletions(-) create mode 100644 cmd/genspec-tui/internal/ux/humanize/doc.go create mode 100644 cmd/genspec-tui/internal/ux/humanize/humanize.go create mode 100644 cmd/genspec-tui/internal/ux/humanize/humanize_test.go create mode 100644 cmd/genspec-tui/internal/ux/runstats/doc.go create mode 100644 cmd/genspec-tui/internal/ux/runstats/runstats.go create mode 100644 cmd/genspec-tui/internal/ux/runstats/runstats_test.go create mode 100644 cmd/genspec-tui/internal/ux/runstats_test.go create mode 100644 cmd/genspec-tui/internal/ux/scan/cost.go create mode 100644 cmd/genspec-tui/internal/ux/scan/cost_test.go diff --git a/cmd/genspec-tui/README.md b/cmd/genspec-tui/README.md index 5ef3a6c8..b075fffd 100644 --- a/cmd/genspec-tui/README.md +++ b/cmd/genspec-tui/README.md @@ -137,6 +137,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 | | `ctrl+q` / `ctrl+c` | quit | ### Spec pane 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/help/help.go b/cmd/genspec-tui/internal/ux/help/help.go index 612c6ba9..e22e28d3 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 and memory)"}, {"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/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..a685d8b2 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" ) @@ -83,6 +84,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 @@ -157,6 +159,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..e19b797d --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats/runstats.go @@ -0,0 +1,172 @@ +// SPDX-FileCopyrightText: Copyright 2015-2025 go-swagger maintainers +// SPDX-License-Identifier: Apache-2.0 + +package runstats + +import ( + "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 + + cost scan.Cost + 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, rescan bool) { + o.cost = c + o.rescan = rescan +} + +// 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. +func (o *Overlay) Open() { o.isOpen = true } + +// Close hides it. +func (o *Overlay) Close() { o.isOpen = false } + +// HandleKey dismisses the overlay, and swallows everything else. +// +// The card is a single screen with nothing to navigate, so - unlike the keymap - there is nothing here for a movement +// key to do. 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 { + 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" + + 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 +) + +// View renders the card. +func (o *Overlay) View() string { + lines := o.lines() + + body := strings.Join(lines, "\n") + + return theme.ModalAt(o.contentWidth(lines)).Render( + theme.Accent().Render(title) + "\n\n" + + body + "\n\n" + + theme.Status().Render(footer), + ) +} + +// contentWidth pins the frame to the widest line it can show, so the box does not resize as the figures change. +func (o *Overlay) contentWidth(lines []string) int { + return max(lipgloss.Width(strings.Join(lines, "\n")), lipgloss.Width(title), lipgloss.Width(footer)) +} + +// 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{ + 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"), + "", + theme.Status().Render(noteWindow), + } + if o.rescan { + lines = append(lines, theme.Status().Render(noteRescan)) + } + + return lines +} + +// 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..b6cf4bac --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats/runstats_test.go @@ -0,0 +1,144 @@ +// 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(), 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 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(), 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(), 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") +} + +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(), false) + narrow := width(view(t, &o)) + + big := aRun() + big.AllocScan = 3 * 1024 * mb + o.Set(big, 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..991e8157 --- /dev/null +++ b/cmd/genspec-tui/internal/ux/runstats_test.go @@ -0,0 +1,90 @@ +// 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/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") +} + +// 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/scan.go b/cmd/genspec-tui/internal/ux/scan/scan.go index 7b4b7ce8..77913138 100644 --- a/cmd/genspec-tui/internal/ux/scan/scan.go +++ b/cmd/genspec-tui/internal/ux/scan/scan.go @@ -17,14 +17,15 @@ 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 Diags []grammar.Diagnostic Provenance []scanner.Provenance Err error @@ -47,6 +48,10 @@ 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. +// // It is exposed by this package to allow for e2e tests. func Do(cfg codescan.Options) ResultMsg { // OnDiagnostic fires synchronously inside codescan.Run, on this same goroutine, so a plain append is race-free. @@ -65,14 +70,28 @@ func Do(cfg codescan.Options) ResultMsg { provs = append(provs, p) } + 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), + } } + 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)), + } } res := ResultMsg{JSON: string(jb), Defs: len(sw.Definitions), Diags: diags, Provenance: provs} @@ -82,6 +101,10 @@ 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) + return res } diff --git a/cmd/genspec-tui/internal/ux/scanflow.go b/cmd/genspec-tui/internal/ux/scanflow.go index 69872cc8..007d6dfa 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 @@ -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, 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 From 463e5aa1789d40601c720096e4f5ba3d5f06d999 Mon Sep 17 00:00:00 2001 From: Frederic BIDON Date: Fri, 14 Aug 2026 15:05:36 +0200 Subject: [PATCH 2/2] feat(genspec-tui): profile a scan and name where its cost went MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The run-cost card reports process-wide scalars, and a scalar cannot say who spent it: while a scan runs, the redraw loop and the file watcher allocate on other goroutines, and no arithmetic separates them out afterwards. Start with -profile and each scan is profiled as well, so the same noise arrives named — a row to discount rather than a confound. The card then reports, per phase, where the CPU went and what allocated the memory, by function; a split line at the top recaps the run as ratios (time, memory, and sampled CPU) so the phase to look at is the first thing read. It scrolls once it outgrows the terminal. Both phases are bracketed the same way: a CPU profile each, and an allocation profile differenced across the fences the cost figures already use. Rendering is often shorter than the sampler's 10 ms interval and catches nothing, which the card states — an absent section reads as an oversight, "nothing sampled" is a measurement. Flags rather than options-popup rows: runtime.MemProfileRate is meant to be set once and held for the life of the process, so a mid-session toggle would make consecutive readings incomparable. -profile-dir says where the five artifacts land, and the card carries the go tool pprof commands that open them, -base included so either phase reproduces in the real tool. What the mode costs itself is disclosed rather than hidden: it collects at each fence to keep the allocation profile current, so the summary figures are worse than the same run unprofiled. The profiler's own allocations — flushing one phase's profile through a compressor, allocating the next one's buffers — are dropped from the tables, where in the short phase they would otherwise crowd out its real sites. github.com/google/pprof/profile reads the profiles back. It is a self-contained package with no transitive requirements, and it joins this module rather than the library. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: Frederic BIDON --- cmd/genspec-tui/README.md | 96 +++- cmd/genspec-tui/go.mod | 1 + cmd/genspec-tui/go.sum | 2 + .../internal/ux/diagnostics_test.go | 2 +- cmd/genspec-tui/internal/ux/fixtures_test.go | 3 +- cmd/genspec-tui/internal/ux/help/help.go | 2 +- .../internal/ux/integration_test.go | 2 +- cmd/genspec-tui/internal/ux/model.go | 10 +- .../internal/ux/runstats/runstats.go | 289 +++++++++- .../internal/ux/runstats/runstats_test.go | 155 +++++- cmd/genspec-tui/internal/ux/runstats_test.go | 37 ++ cmd/genspec-tui/internal/ux/scan/profile.go | 521 ++++++++++++++++++ .../internal/ux/scan/profile_test.go | 236 ++++++++ cmd/genspec-tui/internal/ux/scan/scan.go | 19 +- cmd/genspec-tui/internal/ux/scanflow.go | 4 +- cmd/genspec-tui/internal/ux/source_test.go | 2 +- cmd/genspec-tui/main.go | 51 +- 17 files changed, 1393 insertions(+), 39 deletions(-) create mode 100644 cmd/genspec-tui/internal/ux/scan/profile.go create mode 100644 cmd/genspec-tui/internal/ux/scan/profile_test.go diff --git a/cmd/genspec-tui/README.md b/cmd/genspec-tui/README.md index b075fffd..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,7 +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 | +| `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 @@ -214,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/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 e22e28d3..8bf38972 100644 --- a/cmd/genspec-tui/internal/ux/help/help.go +++ b/cmd/genspec-tui/internal/ux/help/help.go @@ -63,7 +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 and memory)"}, + {"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/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/model.go b/cmd/genspec-tui/internal/ux/model.go index a685d8b2..cd89888b 100644 --- a/cmd/genspec-tui/internal/ux/model.go +++ b/cmd/genspec-tui/internal/ux/model.go @@ -26,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 @@ -143,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, diff --git a/cmd/genspec-tui/internal/ux/runstats/runstats.go b/cmd/genspec-tui/internal/ux/runstats/runstats.go index e19b797d..bef3c37d 100644 --- a/cmd/genspec-tui/internal/ux/runstats/runstats.go +++ b/cmd/genspec-tui/internal/ux/runstats/runstats.go @@ -4,6 +4,7 @@ package runstats import ( + "fmt" "strconv" "strings" @@ -27,9 +28,11 @@ type Overlay struct { width, height int isOpen bool + scroll int - cost scan.Cost - rescan bool + cost scan.Cost + profile *scan.ProfileReport + rescan bool } // New builds a closed overlay. @@ -42,9 +45,11 @@ func New() Overlay { // 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, rescan bool) { +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. @@ -56,17 +61,30 @@ func (o *Overlay) SetSize(w, h int) { // IsOpen reports whether the overlay is currently covering the UI. func (o *Overlay) IsOpen() bool { return o.isOpen } -// Open shows the card. -func (o *Overlay) Open() { o.isOpen = true } +// 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 } +func (o *Overlay) Close() { + o.isOpen = false + o.scroll = 0 +} -// HandleKey dismisses the overlay, and swallows everything else. +// HandleKey scrolls or dismisses the overlay, and swallows everything else. // -// The card is a single screen with nothing to navigate, so - unlike the keymap - there is nothing here for a movement -// key to do. Quitting belongs to the root model, which checks for it before the overlay ever sees the key. +// 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() @@ -85,6 +103,11 @@ const ( 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" ) @@ -95,22 +118,67 @@ const ( valueW = 11 ) -// View renders the card. +// 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 { - lines := o.lines() + all := o.lines() + visible := o.visibleRows() - body := strings.Join(lines, "\n") + 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(lines)).Render( - theme.Accent().Render(title) + "\n\n" + - body + "\n\n" + - theme.Status().Render(footer), + 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))), ) } -// contentWidth pins the frame to the widest line it can show, so the box does not resize as the figures change. +// 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), lipgloss.Width(footer)) + 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. @@ -121,6 +189,8 @@ func (o *Overlay) lines() []string { 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)), "", @@ -137,15 +207,196 @@ func (o *Overlay) lines() []string { 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"), "", - theme.Status().Render(noteWindow), + } + + // 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) diff --git a/cmd/genspec-tui/internal/ux/runstats/runstats_test.go b/cmd/genspec-tui/internal/ux/runstats/runstats_test.go index b6cf4bac..bbdcda16 100644 --- a/cmd/genspec-tui/internal/ux/runstats/runstats_test.go +++ b/cmd/genspec-tui/internal/ux/runstats/runstats_test.go @@ -52,7 +52,7 @@ func view(t *testing.T, o *runstats.Overlay) string { func TestOverlayReportsTheRun(t *testing.T) { o := runstats.New() - o.Set(aRun(), false) + o.Set(aRun(), nil, false) got := view(t, &o) @@ -71,16 +71,53 @@ func TestOverlayReportsTheRun(t *testing.T) { 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(), false) + 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(), true) + 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") } @@ -94,6 +131,114 @@ func TestOverlayBeforeAnyRun(t *testing.T) { 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}, @@ -124,12 +269,12 @@ func TestOverlaySwallowsOtherKeys(t *testing.T) { // 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(), false) + o.Set(aRun(), nil, false) narrow := width(view(t, &o)) big := aRun() big.AllocScan = 3 * 1024 * mb - o.Set(big, true) + o.Set(big, nil, true) assert.GreaterOrEqual(t, width(view(t, &o)), narrow, "a wider figure widens the frame rather than clipping") } diff --git a/cmd/genspec-tui/internal/ux/runstats_test.go b/cmd/genspec-tui/internal/ux/runstats_test.go index 991e8157..f4e77caa 100644 --- a/cmd/genspec-tui/internal/ux/runstats_test.go +++ b/cmd/genspec-tui/internal/ux/runstats_test.go @@ -14,6 +14,7 @@ import ( "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" ) @@ -79,6 +80,42 @@ func TestRunStats_TakesTheCostFromTheScan(t *testing.T) { "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)) 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 77913138..98cdc3d3 100644 --- a/cmd/genspec-tui/internal/ux/scan/scan.go +++ b/cmd/genspec-tui/internal/ux/scan/scan.go @@ -26,6 +26,7 @@ type ResultMsg struct { Defs int Elapsed time.Duration Cost Cost + Profile *ProfileReport // nil unless the run was profiled Diags []grammar.Diagnostic Provenance []scanner.Provenance Err error @@ -37,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 } @@ -52,8 +53,11 @@ func Run(cfg codescan.Options) tea.Cmd { // 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. @@ -70,6 +74,9 @@ 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() @@ -80,9 +87,10 @@ func Do(cfg codescan.Options) ResultMsg { if err != nil { return ResultMsg{ Diags: diags, Provenance: provs, Err: err, - Cost: costOf(before, scanned, scanned, scanFor, 0), + Cost: costOf(before, scanned, scanned, scanFor, 0), Profile: p.done(), } } + p.scanDone() renderStart := time.Now() @@ -90,7 +98,7 @@ func Do(cfg codescan.Options) ResultMsg { if err != nil { return ResultMsg{ Diags: diags, Provenance: provs, Err: err, - Cost: costOf(before, scanned, fence(), scanFor, time.Since(renderStart)), + Cost: costOf(before, scanned, fence(), scanFor, time.Since(renderStart)), Profile: p.done(), } } @@ -104,6 +112,7 @@ func Do(cfg codescan.Options) ResultMsg { 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 007d6dfa..ec6c82c6 100644 --- a/cmd/genspec-tui/internal/ux/scanflow.go +++ b/cmd/genspec-tui/internal/ux/scanflow.go @@ -131,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 } @@ -159,7 +159,7 @@ func (m *Model) absorbScan(msg scan.ResultMsg) { m.scan.Diags = msg.Diags m.scan.Err = msg.Err - m.runstats.Set(msg.Cost, replaced) + 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) 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())