From 947f8add3a895fdb2f3a12563d65987874817dea Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Tue, 29 Sep 2026 00:43:19 -0300 Subject: [PATCH 1/2] mutate: say which tests the edits were asked of the longest in all Each test process runs -v, and each test's end line is counted to its package: how many times an edit was put to it, and for how long in all. A test that starts a control plane and reaches much of a change is where a run's time goes, and what to make faster. Co-Authored-By: Claude Opus 5.5 (1M context) --- cmd/mutate/main.go | 13 ++++ internal/mutate/costs.go | 113 ++++++++++++++++++++++++++++++++++ internal/mutate/costs_test.go | 57 +++++++++++++++++ internal/mutate/mutate.go | 3 +- internal/mutate/schema.go | 3 +- internal/mutate/share_test.go | 12 ++++ 6 files changed, 199 insertions(+), 2 deletions(-) diff --git a/cmd/mutate/main.go b/cmd/mutate/main.go index 511b9a8..b3b0582 100644 --- a/cmd/mutate/main.go +++ b/cmd/mutate/main.go @@ -375,6 +375,19 @@ func reportCosts(took time.Duration) { } fmt.Printf("mutate: %s, %s of CPU\n", took.Round(time.Second), cpu.Round(time.Second)) _ = tw.Flush() + + // The tests the edits were put to, where most of a run's time goes: one that takes seconds + // and reaches much of a change is asked once for each edit in it. + tests := mutate.TestCosts() + if len(tests) == 0 { + return + } + fmt.Println("mutate: the tests asked the longest in all") + tw = tabwriter.NewWriter(os.Stdout, 0, 0, 2, ' ', 0) + for _, c := range tests[:min(len(tests), 10)] { + _, _ = fmt.Fprintf(tw, " %s\t%s\t%d×\t%s\n", c.Package, c.Test, c.N, c.Took.Round(100*time.Millisecond)) + } + _ = tw.Flush() } // reportStale lists every reason over nothing this tool breaks, in the tracked Go that is not a diff --git a/internal/mutate/costs.go b/internal/mutate/costs.go index 69d6564..3ea4c95 100644 --- a/internal/mutate/costs.go +++ b/internal/mutate/costs.go @@ -1,8 +1,13 @@ package mutate import ( + "os" "os/exec" + "path/filepath" + "regexp" "sort" + "strconv" + "strings" "sync" "time" ) @@ -71,3 +76,111 @@ func account(what string, cmd *exec.Cmd, wall time.Duration) { c.Wall += wall c.CPU += cpu } + +// TestCost is what one test cost a run's asking: how many times an edit was put to it, and how +// long it ran in all. A test that starts a control plane and is asked of every edit in the code it +// reaches is where a gate's time goes, and the test, not the gate, is what to make faster. +type TestCost struct { + Package string + Test string + N int + Took time.Duration +} + +var testCosts = struct { + mu sync.Mutex + by map[[2]string]*TestCost +}{by: map[[2]string]*TestCost{}} + +// TestCosts is every test asked so far, the longest in all first. +func TestCosts() []TestCost { + testCosts.mu.Lock() + defer testCosts.mu.Unlock() + out := make([]TestCost, 0, len(testCosts.by)) + for _, c := range testCosts.by { + out = append(out, *c) + } + sort.Slice(out, func(i, j int) bool { + if out[i].Took != out[j].Took { + return out[i].Took > out[j].Took + } + return out[i].Package+" "+out[i].Test < out[j].Package+" "+out[j].Test + }) + return out +} + +var ( + // A top-level test's end, as -test.v says it; a subtest's is indented. + testEnd = regexp.MustCompile(`^--- (?:PASS|FAIL|SKIP): (Test\S*) \(([0-9.]+)s\)$`) + // go test's line for a package it ran, after its tests' lines. + packageEnd = regexp.MustCompile(`^(?:ok|FAIL)\s+(\S+)\s`) +) + +// modulePath is the import path of the module this runs in, "" outside one. +var modulePath = sync.OnceValue(func() string { + out, err := output("listing", exec.Command("go", "list", "-m", "-f", "{{.Path}}")) + if err != nil { + return "" + } + return strings.TrimSpace(string(out)) +}) + +// packageOf is how the report names a package: its directory from its module's root, whether it +// was asked by a directory, relative or not, or named by go test by its import path. +func packageOf(dirOrPath string) string { + if rel, ok := strings.CutPrefix(dirOrPath, modulePath()+"/"); ok && modulePath() != "" { + return rel + } + if info, err := os.Stat(dirOrPath); err != nil || !info.IsDir() { + return dirOrPath // an import path outside this module + } + abs, err := filepath.Abs(dirOrPath) + if err != nil { + return dirOrPath + } + root, err := moduleRoot(abs) + if err != nil { + return dirOrPath + } + rel, err := filepath.Rel(root, abs) + if err != nil { + return dirOrPath + } + return filepath.ToSlash(rel) +} + +// countTests adds the tests out says ran to their package's: pkg's, or where pkg is "" - a go test +// over several packages - the one go test's line after them names. +func countTests(pkg string, out []byte) { + var ran []TestCost + add := func(pkg string) { + pkg = packageOf(pkg) + testCosts.mu.Lock() + defer testCosts.mu.Unlock() + for _, r := range ran { + key := [2]string{pkg, r.Test} + c := testCosts.by[key] + if c == nil { + c = &TestCost{Package: pkg, Test: r.Test} + testCosts.by[key] = c + } + c.N++ + c.Took += r.Took + } + ran = nil + } + for line := range strings.Lines(string(out)) { + line = strings.TrimRight(line, "\r\n") + if m := testEnd.FindStringSubmatch(line); m != nil { + seconds, _ := strconv.ParseFloat(m[2], 64) // the pattern's digits and point + ran = append(ran, TestCost{Test: m[1], Took: time.Duration(seconds * float64(time.Second))}) + continue + } + if m := packageEnd.FindStringSubmatch(line); pkg == "" && m != nil { + add(m[1]) + } + } + if pkg != "" { + add(pkg) + } +} diff --git a/internal/mutate/costs_test.go b/internal/mutate/costs_test.go index 678c4e8..9b3dab5 100644 --- a/internal/mutate/costs_test.go +++ b/internal/mutate/costs_test.go @@ -2,6 +2,7 @@ package mutate import ( "os/exec" + "path/filepath" "testing" "time" ) @@ -55,3 +56,59 @@ func TestAProcessIsCountedUnderWhatItWasFor(t *testing.T) { } } } + +// A test's runs are added to its package's: the package asked, or, for a go test over several, +// the one go test names after them. Subtests are their test's, and a line that only looks like +// an end is not one. +func TestEachAskedTestIsCountedToItsPackage(t *testing.T) { + find := func(pkg, test string) TestCost { + for _, c := range TestCosts() { + if c.Package == pkg && c.Test == test { + return c + } + } + return TestCost{} + } + countTests("p/one", []byte("=== RUN TestSlow\n --- PASS: TestSlow/sub (0.50s)\n--- PASS: TestSlow (1.50s)\n--- FAIL: TestFast (0.25s)\nFAIL\n")) + countTests("p/one", []byte("--- PASS: TestSlow (2.00s)\r\nsaid: --- PASS: TestSlow (9.00s)\nPASS\n")) + countTests("", []byte("--- PASS: TestA (1.00s)\nok \texample.com/a\t1.2s\n--- FAIL: TestB (0.10s)\nFAIL\texample.com/b\t0.3s\n")) + + if got := find("p/one", "TestSlow"); got.N != 2 || got.Took != 3500*time.Millisecond { + t.Errorf("TestSlow: %+v, want asked twice for 3.5s", got) + } + if got := find("p/one", "TestFast"); got.N != 1 || got.Took != 250*time.Millisecond { + t.Errorf("TestFast: %+v", got) + } + if got := find("p/one", "TestSlow/sub"); got.N != 0 { + t.Errorf("a subtest was counted as a test: %+v", got) + } + if got := find("example.com/a", "TestA"); got.N != 1 || got.Took != time.Second { + t.Errorf("TestA: %+v, want example.com/a's", got) + } + if got := find("example.com/b", "TestB"); got.N != 1 || got.Took != 100*time.Millisecond { + t.Errorf("TestB: %+v, want example.com/b's", got) + } + costs := TestCosts() + for i := 1; i < len(costs); i++ { + if costs[i].Took > costs[i-1].Took { + t.Errorf("tests are not the longest first: %v", costs) + } + } +} + +// A package is named by its directory from this module's root, however it was asked: by its +// directory, relative or absolute, or by its import path. +func TestAPackageIsNamedByItsDirectory(t *testing.T) { + abs, err := filepath.Abs(".") + if err != nil { + t.Fatal(err) + } + for _, asked := range []string{".", abs, modulePath() + "/internal/mutate"} { + if got := packageOf(asked); got != "internal/mutate" { + t.Errorf("%s is named %q, want internal/mutate", asked, got) + } + } + if got := packageOf("example.com/elsewhere"); got != "example.com/elsewhere" { + t.Errorf("another module's package is named %q", got) + } +} diff --git a/internal/mutate/mutate.go b/internal/mutate/mutate.go index c055e6a..4b0b91f 100644 --- a/internal/mutate/mutate.go +++ b/internal/mutate/mutate.go @@ -710,7 +710,7 @@ func Run(m Mutation, a Asked) (Outcome, string) { } // -p 1: this run is one of the caller's budget of test processes, and go test over several // packages would otherwise run a binary per core, each with a PostgreSQL of its own. - args := append(append([]string{"test"}, set.pkgs...), "-p", "1", "-count=1", "-failfast", "-timeout", timeout) + args := append(append([]string{"test"}, set.pkgs...), "-p", "1", "-count=1", "-failfast", "-v", "-timeout", timeout) if a.Overlay != "" { args = append(args, "-overlay", a.Overlay) } @@ -721,6 +721,7 @@ func Run(m Mutation, a Asked) (Outcome, string) { cmd.Dir = set.dir cmd.Env = testEnv() out, err := combined(set.what, cmd) + countTests("", out) said.Write(out) if err == nil { continue diff --git a/internal/mutate/schema.go b/internal/mutate/schema.go index c26ce9a..44b35ab 100644 --- a/internal/mutate/schema.go +++ b/internal/mutate/schema.go @@ -372,7 +372,7 @@ func Ask(bin, dir string, id int, timeout string, only []string) (Outcome, strin if len(only) > 0 { timeout = targetedTimeout } - args := []string{"-test.count=1", "-test.failfast", "-test.timeout", timeout} + args := []string{"-test.count=1", "-test.failfast", "-test.v", "-test.timeout", timeout} if len(only) > 0 { args = append(args, "-test.run", "^("+strings.Join(only, "|")+")$") } @@ -380,6 +380,7 @@ func Ask(bin, dir string, id int, timeout string, only []string) (Outcome, strin cmd.Dir = dir cmd.Env = testEnv(switchEnv + "=" + strconv.Itoa(id)) out, err := combined("schema: run one edit", cmd) + countTests(dir, out) if err != nil { return Killed, string(out) } diff --git a/internal/mutate/share_test.go b/internal/mutate/share_test.go index d633f1f..9631706 100644 --- a/internal/mutate/share_test.go +++ b/internal/mutate/share_test.go @@ -86,4 +86,16 @@ func TestEveryTestProcessIsHeldToItsShare(t *testing.T) { if outcome, out := Run(Mutation{File: filepath.Join(dir, "code.go")}, Asked{Timeout: "1m"}); outcome != Survived { t.Errorf("an edit built alone was asked on every core: %s", out) } + + // And each says which tests it ran, under the package's directory from its module's root: + // the schema binary was asked by the directory, go test named the import path. + asked := map[string]int{} + for _, c := range TestCosts() { + if c.Test == "TestHeldToOneCore" { + asked[c.Package] = c.N + } + } + if asked["."] != 1 || asked["example.com/oneproc"] != 1 { + t.Errorf("the asked tests were not counted to their packages: %v", asked) + } } From 4bc08bd8eb52ba9fc15e5edae8609b99899ad908 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Tue, 29 Sep 2026 00:44:54 -0300 Subject: [PATCH 2/2] mutate: the test report's order and entries held by a test of their own Co-Authored-By: Claude Opus 5.5 (1M context) --- internal/mutate/costs.go | 1 + internal/mutate/costs_test.go | 24 ++++++++++++++++++++++-- 2 files changed, 23 insertions(+), 2 deletions(-) diff --git a/internal/mutate/costs.go b/internal/mutate/costs.go index 3ea4c95..17da6a7 100644 --- a/internal/mutate/costs.go +++ b/internal/mutate/costs.go @@ -172,6 +172,7 @@ func countTests(pkg string, out []byte) { for line := range strings.Lines(string(out)) { line = strings.TrimRight(line, "\r\n") if m := testEnd.FindStringSubmatch(line); m != nil { + // mutate-exempt: a bit size other than 32 is 64. seconds, _ := strconv.ParseFloat(m[2], 64) // the pattern's digits and point ran = append(ran, TestCost{Test: m[1], Took: time.Duration(seconds * float64(time.Second))}) continue diff --git a/internal/mutate/costs_test.go b/internal/mutate/costs_test.go index 9b3dab5..5b03ff3 100644 --- a/internal/mutate/costs_test.go +++ b/internal/mutate/costs_test.go @@ -88,11 +88,31 @@ func TestEachAskedTestIsCountedToItsPackage(t *testing.T) { if got := find("example.com/b", "TestB"); got.N != 1 || got.Took != 100*time.Millisecond { t.Errorf("TestB: %+v, want example.com/b's", got) } +} + +// The report is the longest first, and of two tests that took as long, in their names' order; +// no entry is of no test. +func TestTheTestsAreTheLongestFirst(t *testing.T) { + countTests("p/fast", []byte("--- PASS: TestQuick (0.01s)\n")) + countTests("p/tie", []byte("--- PASS: TestZ (4.00s)\n--- PASS: TestY (4.00s)\n")) costs := TestCosts() - for i := 1; i < len(costs); i++ { - if costs[i].Took > costs[i-1].Took { + var y, z int + for i, c := range costs { + if c.Test == "" { + t.Errorf("an entry of no test: %v", costs) + } + if i > 0 && c.Took > costs[i-1].Took { t.Errorf("tests are not the longest first: %v", costs) } + switch { + case c.Package == "p/tie" && c.Test == "TestY": + y = i + case c.Package == "p/tie" && c.Test == "TestZ": + z = i + } + } + if y > z { + t.Errorf("of two tests that took as long, TestZ came before TestY: %v", costs) } }