cmd/go: make Script/test_regexps less flaky under load

With the command below, I was able to reproduce failures within the
first 50 or so runs:

	go test -c -o test && stress -p 32 ./test -test.run Script/test_regexp

When printing the full failure output, we'd see:

	BenchmarkX
	    BenchmarkX: x_test.go:13: LOG: X running N=1
	BenchmarkX/Y
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=100
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=10000
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1000000
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=100000000
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1000000000
	BenchmarkX/Y         	1000000000	         0.000050 ns/op
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=30
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1207
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=120700
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=12070000
	    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1000000000
	BenchmarkX/Y         	1000000000	         0.000715 ns/op

In other words, the N values aren't required to be exact. It seems like
they are cut short if the machine is under stress. That's the exact
scenario we reproduce above, since I used -p=32 on my laptop with only 4
real CPU cores.

First, don't require each line to be present. Instead, use patterns
that span multiple lines, so that we can just match the first and last
N= lines.

Second, don't require the last N= lines to be exact; simply require
them to have a reasonably large number of digits.

Fixes #36664.

Change-Id: I7a9818f1a07099fa6482a26da2ac5cbea0f8ab30
Reviewed-on: https://go-review.googlesource.com/c/go/+/215578
Run-TryBot: Bryan C. Mills <bcmills@google.com>
Reviewed-by: Bryan C. Mills <bcmills@google.com>
Reviewed-by: Daniel Martí <mvdan@mvdan.cc>
TryBot-Result: Gobot Gobot <gobot@golang.org>

diff --git a/src/cmd/go/testdata/script/test_regexps.txt b/src/cmd/go/testdata/script/test_regexps.txt
index 020b8dd579d51e731971059bead57555eec57470..39dedbf06fbbc84b5fbc291bc53182437b152183 100644 (file)
--- a/src/cmd/go/testdata/script/test_regexps.txt
+++ b/src/cmd/go/testdata/script/test_regexps.txt
@@ -2,31 +2,38 @@ go test -cpu=1 -run=X/Y -bench=X/Y -count=2 -v testregexp
 
 # Test the following:
 
-#      TestX is run, twice
+# TestX is run, twice
 stdout -count=2 '^=== RUN   TestX$'
 stdout -count=2 '^    TestX: x_test.go:6: LOG: X running$'
 
-#      TestX/Y is run, twice
+# TestX/Y is run, twice
 stdout -count=2 '^=== RUN   TestX/Y$'
 stdout -count=2 '^    TestX/Y: x_test.go:8: LOG: Y running$'
 
-#      TestXX is run, twice
+# TestXX is run, twice
 stdout -count=2 '^=== RUN   TestXX$'
 stdout -count=2 '^    TestXX: z_test.go:10: LOG: XX running'
 
-#      TestZ is not run
+# TestZ is not run
 ! stdout '^=== RUN   TestZ$'
 
-#      BenchmarkX is run but only with N=1, once
-stdout -count=1 '^    BenchmarkX: x_test.go:13: LOG: X running N=1$'
-! stdout '^    BenchmarkX: x_test.go:13: LOG: X running N=10$'
+# BenchmarkX is run with N=1 once, only to discover what sub-benchmarks it has,
+# and should not print a final summary line.
+stdout -count=1 '^\s+BenchmarkX: x_test.go:13: LOG: X running N=1$'
+! stdout '^\s+BenchmarkX: x_test.go:13: LOG: X running N=\d\d+'
+! stdout 'BenchmarkX\s+\d+'
 
-#      BenchmarkXX is run but only with N=1, once
-stdout -count=1 '^    BenchmarkXX: z_test.go:18: LOG: XX running N=1$'
-! stdout  '^    BenchmarkXX: z_test.go:18: LOG: XX running N=10$'
+# Same for BenchmarkXX.
+stdout -count=1 '^\s+BenchmarkXX: z_test.go:18: LOG: XX running N=1$'
+! stdout  '^\s+BenchmarkXX: z_test.go:18: LOG: XX running N=\d\d+'
+! stdout 'BenchmarkXX\s+\d+'
 
-#      BenchmarkX/Y is run in full, twice
-stdout -count=2 '    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1\n    BenchmarkX/Y: x_test.go:15: LOG: Y running N=100\n    BenchmarkX/Y: x_test.go:15: LOG: Y running N=10000\n    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1000000\n    BenchmarkX/Y: x_test.go:15: LOG: Y running N=100000000\n    BenchmarkX/Y: x_test.go:15: LOG: Y running N=1000000000'
+# BenchmarkX/Y is run in full twice due to -count=2.
+# "Run in full" means that it runs for approximately the default benchtime,
+# but may cap out at N=1e9.
+# We don't actually care what the final iteration count is, but it should be
+# a large number, and the last iteration count prints right before the results.
+stdout -count=2 '^\s+BenchmarkX/Y: x_test.go:15: LOG: Y running N=[1-9]\d{4,}\nBenchmarkX/Y\s+\d+'
 
 -- testregexp/x_test.go --
 package x
@@ -65,4 +72,4 @@ func BenchmarkZ(b *testing.B) {
 
 func BenchmarkXX(b *testing.B) {
        b.Logf("LOG: XX running N=%d", b.N)
-}
\ No newline at end of file
+}