mutate: say which tests the edits were asked of the longest in all

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

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,112 @@ 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 {
+			// 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
+		}
+		if m := packageEnd.FindStringSubmatch(line); pkg == "" && m != nil {
+			add(m[1])
+		}
+	}
+	if pkg != "" {
+		add(pkg)
+	}
+}

internal/mutate/costs_test.go

@@ -2,6 +2,7 @@ package mutate
 
 import (
 	"os/exec"
+	"path/filepath"
 	"testing"
 	"time"
 )
@@ -55,3 +56,79 @@ 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)
+	}
+}
+
+// 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()
+	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)
+	}
+}
+
+// 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)
+	}
+}

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

internal/mutate/schema.go

@@ -372,14 +372,15 @@ 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, "|")+")$")
 	}
 	cmd := exec.Command(bin, args...) //nolint:gosec // a test binary this run built
 	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)
 	}

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)
+	}
 }