diff --git a/.github/workflows/benchmark.yml b/.github/workflows/benchmark.yml index ce210f4e..6b85f927 100644 --- a/.github/workflows/benchmark.yml +++ b/.github/workflows/benchmark.yml @@ -142,24 +142,39 @@ jobs: shell: bash working-directory: base run: | - go test -run='^$' -bench=. -count=10 -benchmem -timeout 60m ./... 2>&1 | tee ../base.txt || true + go test -run='^$' -bench=. -count=10 -benchmem -timeout 60m -json ./... > ../base.json 2>&1 || true - name: Run benchmarks (head) shell: bash working-directory: head run: | - go test -run='^$' -bench=. -count=10 -benchmem -timeout 60m ./... 2>&1 | tee ../head.txt || true + go test -run='^$' -bench=. -count=10 -benchmem -timeout 60m -json ./... > ../head.json 2>&1 || true - name: "📊 Compare and check" shell: bash run: | - go -C _go-infra tool benchstat "$GITHUB_WORKSPACE/base.txt" "$GITHUB_WORKSPACE/head.txt" | tee benchstat.txt || true go build -C _go-infra/cmd/benchcheck -o "$PWD/benchcheck" . + # benchcheck reads the test2json output for structured failure + # detection and reconstructs the plain benchmark text (base.txt and + # head.txt) that the benchstat step below consumes. It runs last in + # this step, so its exit code marks the job failed on a regression or + # failure; the benchstat step still runs via if: always(). ./benchcheck check \ + -o-base-text=base.txt \ + -o-head-text=head.txt \ -o-regressions=regressions.txt \ -o-failures=failures.txt \ -o-status=status.json \ - base.txt head.txt + base.json head.json + + - name: "📈 Summarize with benchstat" + # Run even when the check step marked the job failed, so the human- + # readable diff is always produced. benchcheck writes base.txt/head.txt + # before exiting, so they are available here regardless. + if: always() + shell: bash + run: | + go -C _go-infra tool benchstat "$GITHUB_WORKSPACE/base.txt" "$GITHUB_WORKSPACE/head.txt" | tee benchstat.txt || true - name: Upload results if: always() diff --git a/cmd/benchcheck/check.go b/cmd/benchcheck/check.go index cac69e46..bf7e3943 100644 --- a/cmd/benchcheck/check.go +++ b/cmd/benchcheck/check.go @@ -4,7 +4,6 @@ package main import ( - "bufio" "encoding/json" "errors" "flag" @@ -47,15 +46,20 @@ func cmdCheck(args []string) { regressionsOut := fs.String("o-regressions", "", "output file for regression details (skipped if empty)") failuresOut := fs.String("o-failures", "", "output file for test failure details (skipped if empty)") statusOut := fs.String("o-status", "", "output file for machine-readable status JSON (skipped if empty)") + baseTextOut := fs.String("o-base-text", "", "output file for reconstructed base benchmark text, for benchstat (skipped if empty)") + headTextOut := fs.String("o-head-text", "", "output file for reconstructed head benchmark text, for benchstat (skipped if empty)") fs.Usage = func() { - fmt.Fprintf(os.Stderr, `usage: benchcheck check [flags] base.txt head.txt + fmt.Fprintf(os.Stderr, `usage: benchcheck check [flags] base.json head.json Compare base and head benchmark results, detect regressions and test failures. +The inputs are `+"`go test -json`"+` (test2json) output files. Writes the following output files (only if the corresponding flag is set): -o-regressions One-line summary per detected regression. -o-failures Extracted build errors, test failures, and crash traces. -o-status Machine-readable JSON status for the report subcommand. + -o-base-text Reconstructed plain-text base output, for benchstat. + -o-head-text Reconstructed plain-text head output, for benchstat. Exits 0 if no issues are found, 1 if regressions, failures, or write errors occur. @@ -80,29 +84,26 @@ Flags: basePath, headPath := fs.Arg(0), fs.Arg(1) - // Extract test failures from both files. - var failureLines []string - var err error - if failureLines, err = appendFailuresFromFile(failureLines, basePath, "base: "); err != nil { - fmt.Fprintf(os.Stderr, "reading %s: %v\n", basePath, err) - } - if failureLines, err = appendFailuresFromFile(failureLines, headPath, "head: "); err != nil { - fmt.Fprintf(os.Stderr, "reading %s: %v\n", headPath, err) - } - hasFailures := len(failureLines) > 0 - - // Parse benchmarks and check regressions. + // Parse the test2json inputs once each: this yields both the extracted + // failures and the reconstructed plain-text benchmark output. var benchError bool - baseValues, err := parseBenchmarksFromFile(basePath) + base, err := parseTestJSONFile(basePath, "base: ") if err != nil { fmt.Fprintf(os.Stderr, "reading %s: %v\n", basePath, err) benchError = true } - headValues, err := parseBenchmarksFromFile(headPath) + head, err := parseTestJSONFile(headPath, "head: ") if err != nil { fmt.Fprintf(os.Stderr, "reading %s: %v\n", headPath, err) benchError = true } + + failureLines := append(append([]string{}, base.Failures...), head.Failures...) + hasFailures := len(failureLines) > 0 + + // Parse benchmarks from the reconstructed text and check regressions. + baseValues := parseBenchmarks(strings.NewReader(base.BenchText), basePath) + headValues := parseBenchmarks(strings.NewReader(head.BenchText), headPath) regressions := checkRegressions(baseValues, headValues, cfg) hasRegressions := len(regressions) > 0 @@ -121,6 +122,8 @@ Flags: } } writeErr := errors.Join( + writeTextFile(*baseTextOut, base.BenchText), + writeTextFile(*headTextOut, head.BenchText), writeLines(*regressionsOut, regressionLines), writeLines(*failuresOut, failureLines), writeStatus(*statusOut, Status{ @@ -161,73 +164,6 @@ Flags: } } -func appendFailuresFromFile(lines []string, path, prefix string) ([]string, error) { - f, err := os.Open(path) - if err != nil { - return lines, err - } - defer f.Close() - result, err := extractFailures(f, prefix) - return append(lines, result...), err -} - -// extractFailures parses go test output and returns lines related to -// build errors, test failures, and crash traces. -func extractFailures(r io.Reader, prefix string) ([]string, error) { - var lines []string - scanner := bufio.NewScanner(r) - // go test output can contain very long lines (long panic frames, generated - // file paths, JSON-formatted log lines). Bump the limit well above the - // 64KiB default so Scan does not bail out partway through with ErrTooLong. - scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024) - inCrash := false - for scanner.Scan() { - line := scanner.Text() - switch { - case strings.HasPrefix(line, "# "): - lines = append(lines, prefix+line) - case strings.HasPrefix(line, "--- FAIL"): - lines = append(lines, prefix+line) - case strings.HasPrefix(line, "FAIL\t"): - lines = append(lines, prefix+line) - case !inCrash && isCrashLine(line): - inCrash = true - lines = append(lines, prefix+line) - case inCrash && line == "": - inCrash = false - lines = append(lines, "") - case inCrash: - lines = append(lines, prefix+line) - } - } - return lines, scanner.Err() -} - -// isCrashLine returns true for signal or panic lines (e.g. "SIGSEGV:", "panic:"). -func isCrashLine(line string) bool { - if strings.HasPrefix(line, "panic:") { - return true - } - if !strings.HasPrefix(line, "SIG") { - return false - } - // Match SIG followed by uppercase letters then ':'. - i := 3 - for i < len(line) && line[i] >= 'A' && line[i] <= 'Z' { - i++ - } - return i > 3 && i < len(line) && line[i] == ':' -} - -func parseBenchmarksFromFile(path string) (map[benchKey][]float64, error) { - f, err := os.Open(path) - if err != nil { - return nil, err - } - defer f.Close() - return parseBenchmarks(f, path), nil -} - func parseBenchmarks(r io.Reader, name string) map[benchKey][]float64 { result := make(map[benchKey][]float64) reader := benchfmt.NewReader(r, name) @@ -325,6 +261,14 @@ func writeLines(path string, lines []string) error { return writeFile(path, data) } +// writeTextFile writes content verbatim to path, skipping if path is empty. +func writeTextFile(path, content string) error { + if path == "" { + return nil + } + return writeFile(path, []byte(content)) +} + // Status is the machine-readable status written by check and read by report. type Status struct { Regression bool `json:"regression"` diff --git a/cmd/benchcheck/main.go b/cmd/benchcheck/main.go index 34d9bab1..44abdcc4 100644 --- a/cmd/benchcheck/main.go +++ b/cmd/benchcheck/main.go @@ -5,7 +5,7 @@ // // Commands: // -// benchcheck check [flags] base.txt head.txt +// benchcheck check [flags] base.json head.json // benchcheck report [flags] results-dir package main diff --git a/cmd/benchcheck/main_test.go b/cmd/benchcheck/main_test.go index 715ab084..19ee06b8 100644 --- a/cmd/benchcheck/main_test.go +++ b/cmd/benchcheck/main_test.go @@ -4,7 +4,9 @@ package main import ( + "encoding/json" "fmt" + "slices" "strings" "testing" ) @@ -178,103 +180,149 @@ func TestParseBenchmarks(t *testing.T) { } } -func TestExtractFailures_BuildErrors(t *testing.T) { - input := "# runtime/cgo\ncgo-gcc-prolog:3:20: error: call to undeclared function\nFAIL\tgithub.com/example [build failed]\n" - lines, err := extractFailures(strings.NewReader(input), "") +func TestParseTestJSON_TestFailure(t *testing.T) { + // A failing test: its output (minus the "=== RUN" framing) is captured; the + // package-level FAIL summary is captured too. Benchmark output from a passing + // package is not treated as a failure. + input := strings.Join([]string{ + `{"Action":"run","Package":"ex","Test":"TestFoo"}`, + `{"Action":"output","Package":"ex","Test":"TestFoo","Output":"=== RUN TestFoo\n"}`, + `{"Action":"output","Package":"ex","Test":"TestFoo","Output":" foo_test.go:42: expected 1, got 2\n"}`, + `{"Action":"output","Package":"ex","Test":"TestFoo","Output":"--- FAIL: TestFoo (0.01s)\n"}`, + `{"Action":"fail","Package":"ex","Test":"TestFoo"}`, + `{"Action":"output","Package":"ex","Output":"FAIL\tex\t0.123s\n"}`, + `{"Action":"fail","Package":"ex"}`, + }, "\n") + "\n" + + got, err := parseTestJSON(strings.NewReader(input), "head: ") if err != nil { t.Fatal(err) } - if len(lines) != 2 { - t.Fatalf("expected 2 lines, got %d: %v", len(lines), lines) - } - if !strings.HasPrefix(lines[0], "# ") { - t.Errorf("expected build error line, got: %s", lines[0]) + want := []string{ + "head: foo_test.go:42: expected 1, got 2", + "head: --- FAIL: TestFoo (0.01s)", + "head: FAIL\tex\t0.123s", } - if !strings.HasPrefix(lines[1], "FAIL\t") { - t.Errorf("expected FAIL line, got: %s", lines[1]) + if !slices.Equal(got.Failures, want) { + t.Errorf("failures = %#v, want %#v", got.Failures, want) } } -func TestExtractFailures_TestFailures(t *testing.T) { - input := "--- FAIL: TestFoo (0.01s)\n foo_test.go:42: expected 1, got 2\nFAIL\tgithub.com/example\t0.123s\n" - lines, err := extractFailures(strings.NewReader(input), "pfx: ") +func TestParseTestJSON_BuildFailure(t *testing.T) { + input := strings.Join([]string{ + `{"Action":"output","Package":"ex","Output":"# ex\n"}`, + `{"Action":"output","Package":"ex","Output":"foo.go:3:2: undefined: bar\n"}`, + `{"Action":"output","Package":"ex","Output":"FAIL\tex [build failed]\n"}`, + `{"Action":"fail","Package":"ex"}`, + }, "\n") + "\n" + + got, err := parseTestJSON(strings.NewReader(input), "") if err != nil { t.Fatal(err) } - if len(lines) != 2 { - t.Fatalf("expected 2 lines, got %d: %v", len(lines), lines) + want := []string{ + "# ex", + "foo.go:3:2: undefined: bar", + "FAIL\tex [build failed]", } - if lines[0] != "pfx: --- FAIL: TestFoo (0.01s)" { - t.Errorf("unexpected line: %s", lines[0]) + if !slices.Equal(got.Failures, want) { + t.Errorf("failures = %#v, want %#v", got.Failures, want) } - if lines[1] != "pfx: FAIL\tgithub.com/example\t0.123s" { - t.Errorf("unexpected line: %s", lines[1]) +} + +func TestParseTestJSON_Crash(t *testing.T) { + input := strings.Join([]string{ + `{"Action":"output","Package":"ex","Test":"TestFoo","Output":"panic: runtime error: index out of range\n"}`, + `{"Action":"output","Package":"ex","Test":"TestFoo","Output":"goroutine 1 [running]:\n"}`, + `{"Action":"fail","Package":"ex","Test":"TestFoo"}`, + `{"Action":"fail","Package":"ex"}`, + }, "\n") + "\n" + + got, err := parseTestJSON(strings.NewReader(input), "") + if err != nil { + t.Fatal(err) + } + if len(got.Failures) == 0 || !strings.HasPrefix(got.Failures[0], "panic:") { + t.Errorf("expected panic line first, got %#v", got.Failures) } } -func TestExtractFailures_CrashTrace(t *testing.T) { - input := "SIGSEGV: segmentation violation\nPC=0x1234\ngoroutine 1 [running]:\nmain.foo()\n\tfile.go:10\n\ngoroutine 2 [sleep]:\ntime.Sleep()\n" - lines, err := extractFailures(strings.NewReader(input), "") +func TestParseTestJSON_NoFailures(t *testing.T) { + // A passing benchmark run: reconstructed text feeds benchfmt, no failures. + input := strings.Join([]string{ + `{"Action":"run","Package":"ex","Test":"BenchmarkFoo"}`, + `{"Action":"output","Package":"ex","Output":"BenchmarkFoo-8\t1000\t1234 ns/op\t56 B/op\t3 allocs/op\n"}`, + `{"Action":"output","Package":"ex","Output":"PASS\n"}`, + `{"Action":"output","Package":"ex","Output":"ok\tex\t1.234s\n"}`, + `{"Action":"pass","Package":"ex"}`, + }, "\n") + "\n" + + got, err := parseTestJSON(strings.NewReader(input), "") if err != nil { t.Fatal(err) } - // Should capture lines up to and including the blank line, not goroutine 2. - found := false - for _, l := range lines { - if strings.Contains(l, "goroutine 2") { - t.Error("should not capture second goroutine") - } - if strings.Contains(l, "SIGSEGV") { - found = true - } + if len(got.Failures) != 0 { + t.Errorf("expected no failures, got %#v", got.Failures) } - if !found { - t.Error("expected SIGSEGV line") + want := "BenchmarkFoo-8\t1000\t1234 ns/op\t56 B/op\t3 allocs/op\nPASS\nok\tex\t1.234s\n" + if got.BenchText != want { + t.Errorf("BenchText = %q, want %q", got.BenchText, want) + } + // The reconstructed text must parse as benchmark results. + values := parse(t, got.BenchText) + if len(values[benchKey{Name: "Foo-8", Unit: "sec/op"}]) != 1 { + t.Errorf("expected 1 sec/op value, got values %v", values) } } -func TestExtractFailures_Panic(t *testing.T) { - input := "panic: runtime error: index out of range\ngoroutine 1 [running]:\nmain.foo()\n\n" - lines, err := extractFailures(strings.NewReader(input), "") +func TestParseTestJSON_NonJSONTolerated(t *testing.T) { + // Stray non-JSON lines (e.g. tool diagnostics) are skipped, not fatal. + input := "not json at all\n" + + `{"Action":"output","Package":"ex","Output":"BenchmarkFoo-8\t10\t5 ns/op\n"}` + "\n" + + "another stray line\n" + + `{"Action":"pass","Package":"ex"}` + "\n" + + got, err := parseTestJSON(strings.NewReader(input), "") if err != nil { t.Fatal(err) } - if len(lines) == 0 { - t.Fatal("expected panic lines") + if got.BenchText != "BenchmarkFoo-8\t10\t5 ns/op\n" { + t.Errorf("BenchText = %q", got.BenchText) } - if !strings.HasPrefix(lines[0], "panic:") { - t.Errorf("expected panic line, got: %s", lines[0]) + if len(got.Failures) != 0 { + t.Errorf("expected no failures, got %#v", got.Failures) } } -func TestExtractFailures_NoFailures(t *testing.T) { - input := "BenchmarkFoo-8\t1000\t1234 ns/op\t56 B/op\t3 allocs/op\nok\tgithub.com/example\t1.234s\n" - lines, err := extractFailures(strings.NewReader(input), "") +func TestParseTestJSON_LongLine(t *testing.T) { + // A single event larger than bufio.Scanner's fixed token limit must not + // abort parsing and drop the events that follow it. + huge := strings.Repeat("x", 4*1024*1024) + blob, err := json.Marshal(testEvent{Action: "output", Package: "ex", Test: "TestBig", Output: huge + "\n"}) if err != nil { t.Fatal(err) } - if len(lines) != 0 { - t.Errorf("expected no failures, got %d: %v", len(lines), lines) + input := string(blob) + "\n" + + `{"Action":"fail","Package":"ex","Test":"TestBig"}` + "\n" + + `{"Action":"output","Package":"ex","Output":"FAIL\tex\t0.10s\n"}` + "\n" + + `{"Action":"fail","Package":"ex"}` + "\n" + + got, err := parseTestJSON(strings.NewReader(input), "") + if err != nil { + t.Fatal(err) + } + // The failure after the huge line must still be captured. + if !slices.Contains(got.Failures, "FAIL\tex\t0.10s") { + t.Errorf("expected the trailing package FAIL line to be captured, got %#v", + sliceHead(got.Failures)) } } -func TestIsCrashLine(t *testing.T) { - tests := []struct { - line string - want bool - }{ - {"SIGSEGV: segmentation violation", true}, - {"SIGABRT: abort", true}, - {"panic: runtime error", true}, - {"SIGTERM", false}, // no colon - {"SIG: bad", false}, // no uppercase letters between SIG and : - {"SIGNATURE: foo", true}, // SIG + uppercase + colon - {"something else", false}, - {"", false}, - } - for _, tt := range tests { - if got := isCrashLine(tt.line); got != tt.want { - t.Errorf("isCrashLine(%q) = %v, want %v", tt.line, got, tt.want) - } +// sliceHead returns a copy of s truncated for readable test failure messages. +func sliceHead(s []string) []string { + const limit = 5 + if len(s) > limit { + return s[:limit] } + return s } diff --git a/cmd/benchcheck/testjson.go b/cmd/benchcheck/testjson.go new file mode 100644 index 00000000..ae0e9ef9 --- /dev/null +++ b/cmd/benchcheck/testjson.go @@ -0,0 +1,123 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +package main + +import ( + "bufio" + "encoding/json" + "errors" + "io" + "os" + "strings" +) + +// testEvent is a single `go test -json` (test2json) event. Only the fields +// benchcheck needs are decoded. +type testEvent struct { + Action string + Package string + Test string + Output string +} + +// testJSON holds the result of parsing a `go test -json` stream. +type testJSON struct { + // BenchText is the reconstructed plain-text test output: every output event + // concatenated in order. It is what benchstat and benchfmt consume. + BenchText string + // Failures are human-readable lines describing build errors, failed tests, + // and crashes, each prefixed with the caller-supplied prefix. + Failures []string +} + +// scopeKey identifies the package (and optionally test) an output event belongs +// to, so buffered output can be attributed to the thing that ultimately fails. +type scopeKey struct { + pkg string + test string +} + +// parseTestJSONFile opens path and parses its `go test -json` contents. +func parseTestJSONFile(path, prefix string) (testJSON, error) { + f, err := os.Open(path) + if err != nil { + return testJSON{}, err + } + defer f.Close() + return parseTestJSON(f, prefix) +} + +// parseTestJSON reads a `go test -json` stream and returns the reconstructed +// plain-text output plus any extracted failure lines. Failures are detected +// structurally from "fail" events rather than by pattern-matching text, and the +// output captured for the failing package or test is included for context. +// Non-JSON lines (e.g. stray tool output) are tolerated and skipped. +func parseTestJSON(r io.Reader, prefix string) (testJSON, error) { + var bench strings.Builder + // Buffer output per scope until we learn whether it passed or failed. + // Passing scopes are dropped to keep memory bounded; failing scopes are + // flushed into the failure list. + buffered := make(map[scopeKey][]string) + + // Read line by line with a bufio.Reader rather than a bufio.Scanner: a + // single test2json event (e.g. an Output field carrying a very long panic + // or log line) can exceed Scanner's fixed token limit, which would abort + // parsing partway through and silently drop later failures and benchmark + // output. ReadBytes grows as needed, bounded only by one line's length. + br := bufio.NewReader(r) + + var failures []string + for { + line, readErr := br.ReadBytes('\n') + if len(line) > 0 { + var e testEvent + if err := json.Unmarshal(line, &e); err == nil { + key := scopeKey{e.Package, e.Test} + switch e.Action { + case "output": + bench.WriteString(e.Output) + buffered[key] = append(buffered[key], e.Output) + case "pass", "skip": + // The scope succeeded; its output is not a failure. + delete(buffered, key) + case "fail": + for _, l := range failureContext(buffered[key]) { + failures = append(failures, prefix+l) + } + delete(buffered, key) + } + } + // A line that does not parse as a JSON event (e.g. stray tool + // output) is tolerated and skipped. + } + if readErr != nil { + if errors.Is(readErr, io.EOF) { + break + } + return testJSON{BenchText: bench.String(), Failures: failures}, readErr + } + } + return testJSON{BenchText: bench.String(), Failures: failures}, nil +} + +// failureContext turns a failing scope's raw output events into concise, +// meaningful lines: it splits on newlines, drops blank lines and the "=== " +// framing lines (RUN/PAUSE/CONT/NAME) that carry no failure information, and +// keeps everything else (build errors, "--- FAIL" details, panics, logs). +func failureContext(output []string) []string { + var lines []string + for _, chunk := range output { + for _, line := range strings.Split(chunk, "\n") { + line = strings.TrimRight(line, "\r") + if strings.TrimSpace(line) == "" { + continue + } + if strings.HasPrefix(line, "=== ") { + continue + } + lines = append(lines, line) + } + } + return lines +}