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>
This commit is contained in:
Daniel Martí 2020-01-21 10:21:17 +00:00 committed by Bryan C. Mills
parent 64378c233b
commit 8689ea6a4a
1 changed files with 20 additions and 13 deletions

View File

@ -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)
}
}