From 91d4a8b6afb5df4793b496e1b7199eff93c9b17d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Mart=C3=AD?= Date: Sat, 12 Feb 2022 18:30:26 +0000 Subject: [PATCH] start reporting total allocs by garble in the benchmark MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 86 ++++++++++++++++++++++++++++++++------------------- main.go | 8 +++++ 2 files changed, 63 insertions(+), 31 deletions(-) diff --git a/bench_test.go b/bench_test.go index 7af8ec2..ed8f544 100644 --- a/bench_test.go +++ b/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 { diff --git a/main.go b/main.go index bac374c..5e8263d 100644 --- a/main.go +++ b/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 }