start reporting total allocs by garble in the benchmark

This is like allocs/op by testing.B.ReportAllocs,
but it combines all allocations by garble sub-processes.
As we currently generate quite a bit of garbage,
and reductions in it may only reduce time/op very slowly,
this new metric will help us visualize small improvements.

The regular ReportAllocs would not help us at all,
as the main process simply executes "garble build".

We remove user-ns/op to make space for mallocs/op,
and also since it's a bit redundant given sys-ns/op and time-ns/op.

	name      time/op
	Build-16      9.20s ± 1%

	name      bin-B
	Build-16      5.16M ± 0%

	name      cached-time/op
	Build-16      304ms ± 4%

	name      mallocs/op
	Build-16      30.7M ± 0%

	name      sys-time/op
	Build-16      4.78s ± 4%

bench_test.go

@@ -12,6 +12,7 @@ import (
 	"path/filepath"
 	"regexp"
 	"runtime"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -59,7 +60,7 @@ func BenchmarkBuild(b *testing.B) {
 	qt.Assert(b, err, qt.IsNil)
 
 	// We collect extra metrics.
-	var cachedTime, userTime, systemTime int64
+	var memoryAllocs, cachedTime, systemTime int64
 
 	outputBin := filepath.Join(b.TempDir(), "output")
 	sourceDir := filepath.Join(b.TempDir(), "src")
@@ -73,46 +74,69 @@ func BenchmarkBuild(b *testing.B) {
 	writeSourceFile("go.mod", []byte("module test/main"))
 	writeSourceFile("main.go", benchSourceMain)
 
+	rxGarbleAllocs := regexp.MustCompile(`(?m)^garble allocs: ([0-9]+)`)
+
 	b.ResetTimer()
+	b.StopTimer()
 	for i := 0; i < b.N; i++ {
 		// First we do a fresh build, using a new GOCACHE.
 		// and the second does an incremental rebuild reusing the cache.
 		gocache, err := os.MkdirTemp(b.TempDir(), "gocache-*")
 		qt.Assert(b, err, qt.IsNil)
-		env := append(os.Environ(), "GOGARBLE=*", "GOCACHE="+gocache)
+		env := append(os.Environ(),
+			"GOGARBLE=*",
+			"GOCACHE="+gocache,
+			"GARBLE_WRITE_ALLOCS=true",
+		)
 		args := []string{"build", "-v", "-o=" + outputBin, sourceDir}
 
-		cmd := exec.Command(garbleBin, args...)
-		cmd.Env = env
-		cmd.Dir = sourceDir
-
-		out, err := cmd.CombinedOutput()
-		qt.Assert(b, err, qt.IsNil, qt.Commentf("output: %s", out))
-		// Ensure that we built all packages, as expected.
-		qt.Assert(b, rxBuiltRuntime.Match(out), qt.IsTrue)
-		qt.Assert(b, rxBuiltMain.Match(out), qt.IsTrue)
-
-		// The cached rebuild will reuse all dependencies,
-		// but rebuild the main package itself.
-		cachedStart := time.Now()
-		writeSourceFile("rebuild.go", []byte(fmt.Sprintf("package main\nvar v%d int", i)))
-
-		cmd = exec.Command(garbleBin, args...)
-		cmd.Env = env
-		cmd.Dir = sourceDir
-
-		out, err = cmd.CombinedOutput()
-		qt.Assert(b, err, qt.IsNil, qt.Commentf("output: %s", out))
-		// Ensure that we only rebuilt the main package, as expected.
-		qt.Assert(b, rxBuiltRuntime.Match(out), qt.IsFalse)
-		qt.Assert(b, rxBuiltMain.Match(out), qt.IsTrue)
-
-		cachedTime += time.Since(cachedStart).Nanoseconds()
-		userTime += int64(cmd.ProcessState.UserTime())
-		systemTime += int64(cmd.ProcessState.SystemTime())
+		for _, cached := range []bool{false, true} {
+			// The cached rebuild will reuse all dependencies,
+			// but rebuild the main package itself.
+			if cached {
+				writeSourceFile("rebuild.go", []byte(fmt.Sprintf("package main\nvar v%d int", i)))
+			}
+
+			cmd := exec.Command(garbleBin, args...)
+			cmd.Env = env
+			cmd.Dir = sourceDir
+
+			cachedStart := time.Now()
+			b.StartTimer()
+			out, err := cmd.CombinedOutput()
+			b.StopTimer()
+			if cached {
+				cachedTime += time.Since(cachedStart).Nanoseconds()
+			}
+
+			qt.Assert(b, err, qt.IsNil, qt.Commentf("output: %s", out))
+			if !cached {
+				// Ensure that we built all packages, as expected.
+				qt.Assert(b, rxBuiltRuntime.Match(out), qt.IsTrue)
+			} else {
+				// Ensure that we only rebuilt the main package, as expected.
+				qt.Assert(b, rxBuiltRuntime.Match(out), qt.IsFalse)
+			}
+			qt.Assert(b, rxBuiltMain.Match(out), qt.IsTrue)
+
+			matches := rxGarbleAllocs.FindAllSubmatch(out, -1)
+			if !cached {
+				// The non-cached version should have at least a handful of
+				// sub-processes; catch if our logic breaks.
+				qt.Assert(b, len(matches) > 5, qt.IsTrue)
+			}
+			for _, match := range matches {
+				allocs, err := strconv.ParseInt(string(match[1]), 10, 64)
+				qt.Assert(b, err, qt.IsNil)
+				memoryAllocs += allocs
+			}
+
+			systemTime += int64(cmd.ProcessState.SystemTime())
+		}
 	}
+	// We can't use "allocs/op" as it's reserved for ReportAllocs.
+	b.ReportMetric(float64(memoryAllocs)/float64(b.N), "mallocs/op")
 	b.ReportMetric(float64(cachedTime)/float64(b.N), "cached-ns/op")
-	b.ReportMetric(float64(userTime)/float64(b.N), "user-ns/op")
 	b.ReportMetric(float64(systemTime)/float64(b.N), "sys-ns/op")
 	info, err := os.Stat(outputBin)
 	if err != nil {

main.go

@@ -210,6 +210,14 @@ func debugSince(start time.Time) time.Duration {
 }
 
 func main1() int {
+	defer func() {
+		if os.Getenv("GARBLE_WRITE_ALLOCS") != "true" {
+			return
+		}
+		var memStats runtime.MemStats
+		runtime.ReadMemStats(&memStats)
+		fmt.Fprintf(os.Stderr, "garble allocs: %d\n", memStats.Mallocs)
+	}()
 	if err := flagSet.Parse(os.Args[1:]); err != nil {
 		return 2
 	}