sweet: split benchmark results from log and/or debug output

Currently benchmark output all comes out in one big stream and ends up
in the results/<benchmark>/<toolchain-name>.results file. Recently, we
started dumping a lot more logging information from benchmarks by
default, but this has caused problems with benchmark result parsing,
since they contain lines that look naively like key-value pairs in the
benchmark format.

This change resolves this problem by splitting the benchmark result
stream from the log and/or debug output stream, placing the latter in
results/<benchmark>/toolchain-name>.log. By convention, we make it so
that all benchmark driver binaries emit benchmark results to stdout and
everything else to stderr to easily separate the streams in the harness
and redirect them to different files.

Change-Id: Iea4cc253a72db176378a6cc9f68b7f36b9ff60ae
Reviewed-on: https://go-review.googlesource.com/c/benchmarks/+/602135
Reviewed-by: Michael Pratt <[email protected]>
Auto-Submit: Michael Knyszek <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>

sweet/benchmarks/go-build/main.go

@@ -104,7 +104,7 @@ func run(pkgPath string) error {
 	baseCmd := exec.Command(cmdArgs[0], cmdArgs[1:]...)
 	baseCmd.Dir = pkgPath
 	baseCmd.Env = common.NewEnvFromEnviron().MustSet("GOROOT=" + filepath.Dir(filepath.Dir(goTool))).Collapse()
-	baseCmd.Stdout = os.Stdout
+	baseCmd.Stdout = os.Stderr // Redirect all tool output to stderr.
 	baseCmd.Stderr = os.Stderr
 	cmd, err := cgroups.WrapCommand(baseCmd, "test.scope")
 	if err != nil {
@@ -133,7 +133,8 @@ func printOtherResults(dir string) error {
 			if err != nil {
 				return err
 			}
-			if _, err := io.Copy(os.Stderr, f); err != nil {
+			// Results canonically go to stdout.
+			if _, err := io.Copy(os.Stdout, f); err != nil {
 				f.Close()
 				return err
 			}
@@ -154,6 +155,9 @@ func runToolexec() error {
 		benchmark = true
 	default:
 		cmd := exec.Command(flag.Args()[0], flag.Args()[1:]...)
+		// Passing through stdout is necessary here because the go tool needs
+		// to be able to read stdout from some of these tools. This won't appear
+		// in the final output.
 		cmd.Stdout = os.Stdout
 		cmd.Stderr = os.Stderr
 		return cmd.Run()
@@ -186,6 +190,9 @@ func runToolexec() error {
 		}
 	}
 	cmd := exec.Command(flag.Args()[0], append(extraFlags, flag.Args()[1:]...)...)
+	// Passing through stdout is necessary here because the go tool needs
+	// to be able to read stdout from some of these tools. This won't appear
+	// in the final output.
 	cmd.Stdout = os.Stdout
 	cmd.Stderr = os.Stderr
 	if benchmark {

sweet/benchmarks/internal/driver/driver.go

@@ -387,7 +387,7 @@ func (b *B) report() {
 	})
 
 	// Write out stats.
-	var out io.Writer = os.Stderr
+	var out io.Writer = os.Stdout
 	if b.resultsWriter != nil {
 		out = b.resultsWriter
 	}

sweet/cmd/sweet/benchmark.go

@@ -348,17 +348,24 @@ func (b *benchmark) execute(cfgs []*common.Config, r *runCfg) error {
 			args = append(args, dc.DriverArgs()...)
 		}
 
+		// Create log and results file.
 		results, err := os.Create(filepath.Join(resultsDir, fmt.Sprintf("%s.results", cfg.Name)))
 		if err != nil {
 			return fmt.Errorf("create %s results file for %s: %v", b.name, cfg.Name, err)
 		}
 		defer results.Close()
+		log, err := os.Create(filepath.Join(resultsDir, fmt.Sprintf("%s.log", cfg.Name)))
+		if err != nil {
+			return fmt.Errorf("create %s log file for %s: %v", b.name, cfg.Name, err)
+		}
+		defer results.Close()
 		setups = append(setups, common.RunConfig{
 			BinDir:    binDir,
 			TmpDir:    tmpDir,
 			AssetsDir: assetsDir,
 			Args:      args,
 			Results:   results,
+			Log:       log,
 			Short:     r.short,
 		})
 	}
@@ -384,11 +391,11 @@ func (b *benchmark) execute(cfgs []*common.Config, r *runCfg) error {
 			if err := b.harness.Run(cfgs[i], &setup); err != nil {
 				debug.SetGCPercent(gogc)
 				// Useful error messages are often in the log. Grab the end.
-				logTail, tailErr := readFileTail(setup.Results)
+				logTail, tailErr := readFileTail(setup.Log)
 				if tailErr != nil {
 					logTail = fmt.Sprintf("error reading log tail: %s", tailErr)
 				}
-				setup.Results.Close()
+				setup.Log.Close()
 				return fmt.Errorf("run benchmark %s for config %s: %v\nLog tail:\n%s", b.name, cfgs[i].Name, err, logTail)
 			}
 			debug.SetGCPercent(gogc)

sweet/cmd/sweet/integration_test.go

@@ -153,38 +153,44 @@ func TestSweetEndToEnd(t *testing.T) {
 		defer outputMu.Unlock()
 
 		// Poke at the results directory.
-		var matches []string
-		addMatches := func(fileName string) {
-			m1, err := filepath.Glob(filepath.Join(resultsDir, "*", fileName))
+		var resultFiles []string
+		addResultFiles := func(fileName string) {
+			matches, err := filepath.Glob(filepath.Join(resultsDir, "*", fileName))
 			if err != nil {
 				t.Errorf("failed to search results directory for %s: %v", fileName, err)
-			} else if len(m1) == 0 {
+			} else if len(matches) == 0 {
 				t.Logf("no %s results", fileName)
 			}
-			matches = append(matches, m1...)
+			resultFiles = append(resultFiles, matches...)
 		}
 		if hasPGO {
-			addMatches("go.profile.results")
+			addResultFiles("go.profile.results")
 		}
-		addMatches("go.results")
+		addResultFiles("go.results")
 
 		// Dump additional information in case of error, and
 		// check for reasonable results in the case of no error.
-		for _, match := range matches {
-			benchmark := filepath.Base(filepath.Dir(match))
+		for _, resultFile := range resultFiles {
+			benchmark := filepath.Base(filepath.Dir(resultFile))
 			if runErr != nil {
 				t.Logf("output for %s:", benchmark)
+				logFile := resultFile[:len(resultFile)-len(filepath.Ext(resultFile))] + ".log"
+				log, err := os.ReadFile(logFile)
+				if err != nil {
+					t.Errorf("failed to read log for %s: %v", benchmark, err)
+					continue
+				}
+				t.Log(string(log))
 			}
-			data, err := os.ReadFile(match)
+			data, err := os.ReadFile(resultFile)
 			if err != nil {
-				t.Errorf("failed to read results for %si: %v", benchmark, err)
+				t.Errorf("failed to read results for %s: %v", benchmark, err)
 				continue
 			}
-			if runErr != nil {
-				t.Log(string(data))
-				continue
+			// TODO(mknyszek): Do some more exhaustive checking with the benchfmt package.
+			if !strings.Contains(string(data), "Benchmark") {
+				t.Errorf("no benchmark data found in result file for %s", benchmark)
 			}
-			// TODO(mknyszek): Check to make sure the results look reasonable.
 		}
 		if runErr != nil {
 			t.Logf("command output:\n%s", string(output))

sweet/common/harness.go

@@ -69,8 +69,16 @@ type RunConfig struct {
 
 	// Results is the file to which benchmark results should be appended
 	// in the Go benchmark format.
+	//
+	// By convention, this is the benchmark binary's stdout.
 	Results *os.File
 
+	// Log contains additional information information from the benchmark,
+	// for example for debugging.
+	//
+	// By convention, this is the benchmark binary's stderr.
+	Log *os.File
+
 	// Short indicates whether or not to run a short version of the benchmarks
 	// for testing. Guaranteed to be the same as GetConfig.Short and
 	// BuildConfig.Short.

sweet/harnesses/cockroachdb.go

@@ -163,7 +163,7 @@ func (h CockroachDB) Run(cfg *common.Config, rcfg *common.RunConfig) error {
 		)
 		cmd.Env = cfg.ExecEnv.Collapse()
 		cmd.Stdout = rcfg.Results
-		cmd.Stderr = rcfg.Results
+		cmd.Stderr = rcfg.Log
 		log.TraceCommand(cmd, false)
 		if err := cmd.Start(); err != nil {
 			return err

sweet/harnesses/etcd.go

@@ -82,7 +82,7 @@ func (h Etcd) Run(cfg *common.Config, rcfg *common.RunConfig) error {
 		)
 		cmd.Env = cfg.ExecEnv.Collapse()
 		cmd.Stdout = rcfg.Results
-		cmd.Stderr = rcfg.Results
+		cmd.Stderr = rcfg.Log
 		log.TraceCommand(cmd, false)
 		if err := cmd.Run(); err != nil {
 			return err

sweet/harnesses/go-build.go

@@ -150,7 +150,7 @@ func (h GoBuild) Run(pcfg *common.Config, rcfg *common.RunConfig) error {
 		)
 		cmd.Env = cfg.ExecEnv.Collapse()
 		cmd.Stdout = rcfg.Results
-		cmd.Stderr = rcfg.Results
+		cmd.Stderr = rcfg.Log
 		log.TraceCommand(cmd, false)
 		if err := cmd.Run(); err != nil {
 			return err

sweet/harnesses/gvisor.go

@@ -74,7 +74,7 @@ func (h GVisor) Run(cfg *common.Config, rcfg *common.RunConfig) error {
 	)
 	cmd.Env = cfg.ExecEnv.Collapse()
 	cmd.Stdout = rcfg.Results
-	cmd.Stderr = rcfg.Results
+	cmd.Stderr = rcfg.Log
 	log.TraceCommand(cmd, false)
 	return cmd.Run()
 }

sweet/harnesses/local.go

@@ -16,7 +16,6 @@ type localBenchHarness struct {
 	binName   string
 	genArgs   func(cfg *common.Config, rcfg *common.RunConfig) []string
 	beforeRun func(cfg *common.Config, rcfg *common.RunConfig) error
-	noStdout  bool
 }
 
 func (h *localBenchHarness) CheckPrerequisites() error {
@@ -42,10 +41,8 @@ func (h *localBenchHarness) Run(cfg *common.Config, rcfg *common.RunConfig) erro
 		append(rcfg.Args, h.genArgs(cfg, rcfg)...)...,
 	)
 	cmd.Env = cfg.ExecEnv.Collapse()
-	if !h.noStdout {
-		cmd.Stdout = rcfg.Results
-	}
-	cmd.Stderr = rcfg.Results
+	cmd.Stdout = rcfg.Results
+	cmd.Stderr = rcfg.Log
 	log.TraceCommand(cmd, false)
 	return cmd.Run()
 }

sweet/harnesses/tile38.go

@@ -85,7 +85,7 @@ func (h Tile38) Run(cfg *common.Config, rcfg *common.RunConfig) error {
 	)
 	cmd.Env = cfg.ExecEnv.Collapse()
 	cmd.Stdout = rcfg.Results
-	cmd.Stderr = rcfg.Results
+	cmd.Stderr = rcfg.Log
 	log.TraceCommand(cmd, false)
 	return cmd.Run()
 }