Paschalis Tsilias has uploaded this change for review.
testing: add individual timer for tests, benchmarks and fuzz targets
This CL adds an individual timer for each test function, benchmark
and fuzz target being run. The timer does not tick down while the
function is blocked on a Run or Parallel call.
The timer's timeout is configurable via a new `-testtimeout` flag on the
testing package, test binary and the go test command. The flag's value
defaults to 1 minute, or the value of the `-timeout` flag if it is set.
If the flag is set to 0, the timer is disabled. Each test, benchmark
or fuzz can use the SetTimeout method to define its own timeout. Calling
SetTimeout does not Reset the individual timer, but calculates the
deadline from the function's start. Subtests inherit the timeout value
set using this method for their own, separate timer.
Fixes #48157
Change-Id: I91ccb7dece0708ea64b96f9903e8aa6324f58490
---
A api/next/48157.txt
M src/cmd/go/alldocs.go
M src/cmd/go/internal/test/flagdefs.go
M src/cmd/go/internal/test/test.go
M src/cmd/go/internal/test/testflag.go
A src/cmd/go/testdata/script/test_testtimeout.txt
M src/testing/benchmark.go
M src/testing/fuzz.go
M src/testing/testing.go
9 files changed, 204 insertions(+), 3 deletions(-)
diff --git a/api/next/48157.txt b/api/next/48157.txt
new file mode 100644
index 0000000..5ddff00
--- /dev/null
+++ b/api/next/48157.txt
@@ -0,0 +1,4 @@
+pkg testing, method (*B) SetTimeout(time.Duration) #48157
+pkg testing, method (*F) SetTimeout(time.Duration) #48157
+pkg testing, method (*T) SetTimeout(time.Duration) #48157
+pkg testing, type TB interface, SetTimeout(time.Duration) #48157
diff --git a/src/cmd/go/alldocs.go b/src/cmd/go/alldocs.go
index 3174c6a..8cc4a63 100644
--- a/src/cmd/go/alldocs.go
+++ b/src/cmd/go/alldocs.go
@@ -3083,6 +3083,11 @@
// If d is 0, the timeout is disabled.
// The default is 10 minutes (10m).
//
+// -testtimeout d
+// If a test, benchmark or fuzz target runs longer than duration d, panic.
+// If d is 0, the per-test timeout is disabled.
+// The default is 1 minute (1m) or the value of the -timeout flag, if set.
+//
// -v
// Verbose output: log all tests as they are run. Also print all
// text from Log and Logf calls even if the test succeeds.
diff --git a/src/cmd/go/internal/test/flagdefs.go b/src/cmd/go/internal/test/flagdefs.go
index 947c27e..8b4143e 100644
--- a/src/cmd/go/internal/test/flagdefs.go
+++ b/src/cmd/go/internal/test/flagdefs.go
@@ -34,6 +34,7 @@
"short": true,
"shuffle": true,
"skip": true,
+ "testtimeout": true,
"timeout": true,
"trace": true,
"v": true,
diff --git a/src/cmd/go/internal/test/test.go b/src/cmd/go/internal/test/test.go
index 11d1aef..4494980 100644
--- a/src/cmd/go/internal/test/test.go
+++ b/src/cmd/go/internal/test/test.go
@@ -335,6 +335,11 @@
If d is 0, the timeout is disabled.
The default is 10 minutes (10m).
+ -testtimeout d
+ If a test, benchmark or fuzz target runs longer than duration d, panic.
+ If d is 0, the per-test timeout is disabled.
+ The default is 1 minute (1m) or the value of the -timeout flag, if set.
+
-v
Verbose output: log all tests as they are run. Also print all
text from Log and Logf calls even if the test succeeds.
@@ -546,6 +551,7 @@
testOutputDir outputdirFlag // -outputdir flag
testShuffle shuffleFlag // -shuffle flag
testTimeout time.Duration // -timeout flag
+ testTestTimeout time.Duration // -testtimeout flag
testV testVFlag // -v flag
testVet = vetFlag{flags: defaultVetFlags} // -vet flag
)
diff --git a/src/cmd/go/internal/test/testflag.go b/src/cmd/go/internal/test/testflag.go
index 4253788..6dcd2fe 100644
--- a/src/cmd/go/internal/test/testflag.go
+++ b/src/cmd/go/internal/test/testflag.go
@@ -62,6 +62,7 @@
cf.Bool("short", false, "")
cf.String("skip", "", "")
cf.DurationVar(&testTimeout, "timeout", 10*time.Minute, "") // known to cmd/dist
+ cf.DurationVar(&testTestTimeout, "testtimeout", 1*time.Minute, "")
cf.String("fuzztime", "", "")
cf.String("fuzzminimizetime", "", "")
cf.StringVar(&testTrace, "trace", "", "")
@@ -378,6 +379,12 @@
injectedFlags = append(injectedFlags, fmt.Sprintf("-test.timeout=%v", testTimeout))
}
+ if timeoutSet {
+ injectedFlags = append(injectedFlags, fmt.Sprintf("-test.testtimeout=%v", testTimeout))
+ } else {
+ injectedFlags = append(injectedFlags, fmt.Sprintf("-test.testtimeout=%v", testTestTimeout))
+ }
+
// Similarly, the test binary defaults -test.outputdir to its own working
// directory, but 'go test' defaults it to the working directory of the 'go'
// command. Set it explicitly if it is needed due to some other flag that
diff --git a/src/cmd/go/testdata/script/test_testtimeout.txt b/src/cmd/go/testdata/script/test_testtimeout.txt
new file mode 100644
index 0000000..e9cd841
--- /dev/null
+++ b/src/cmd/go/testdata/script/test_testtimeout.txt
@@ -0,0 +1,92 @@
+[short] skip
+env GO111MODULE=off
+cd a
+
+# If no testtimeout is set explicitly, 'go test' should set
+# -test.testtimeout to its internal default.
+go test -v -run TestTimeout . --
+stdout '1m0s'
+
+# If no testtimeout is set explicitly, but timeout is set, 'go test' should
+# default -test.testtimeout to the value of -timeout.
+go test -v -run TestTimeout -timeout 15m . --
+stdout '15m0s'
+
+# An explicit -testtimeout argument should be propagated to -test.testtimeout.
+go test -v -run TestTimeout -testtimeout 3m . --
+stdout '3m0s'
+
+# The parent timer does not tick down while blocked in t.Run or t.Parallel.
+go test -v -run TestBlockedTimer . --
+stdout '^ok a'
+
+# The test's timer can be disabled.
+go test -v -run TestDisableTimeout . --
+stdout '^ok a'
+
+# The test's timer can be enabled.
+go test -v -run TestEnableTimeout -testtimeout 0s . --
+stdout '^ok a'
+
+# Subtests inherit their parent's timeout value.
+go test -v -run TestSubtestsInheritParentTimer . --
+stdout '^ok a'
+
+-- a/timeout_test.go --
+package t
+
+import (
+ "flag"
+ "fmt"
+ "testing"
+ "time"
+)
+
+func TestTimeout(t *testing.T) {
+ fmt.Println(flag.Lookup("test.testtimeout").Value.String())
+}
+
+func TestBlockedTimer(t *testing.T) {
+ t.SetTimeout(10 * time.Millisecond)
+
+ parallel := func(t *testing.T) {
+ t.Parallel()
+ time.Sleep(8 * time.Millisecond)
+ }
+
+ t.Run("non-parallel-a", func(t *testing.T) {
+ time.Sleep(8 * time.Millisecond)
+ })
+ t.Run("non-parallel-b", func(t *testing.T) {
+ time.Sleep(8 * time.Millisecond)
+ })
+ t.Run("parallel-a", parallel)
+ t.Run("parallel-b", parallel)
+ time.Sleep(1 * time.Millisecond)
+}
+
+func TestDisableTimeout(t *testing.T) {
+ t.SetTimeout(10 * time.Millisecond)
+ time.Sleep(5 * time.Millisecond)
+
+ t.SetTimeout(0)
+ time.Sleep(10 * time.Millisecond)
+}
+
+func TestEnableTimeout(t *testing.T) {
+ time.Sleep(5 * time.Millisecond)
+ t.SetTimeout(10 * time.Millisecond)
+ time.Sleep(3 * time.Millisecond)
+}
+
+func TestSubtestsInheritParentTimer(t *testing.T) {
+ t.SetTimeout(5 * time.Second)
+ t.Run("sub-a", func(t *testing.T) {
+ t.SetTimeout(10 * time.Second)
+
+ t.Run("sub-b", func(t *testing.T) {
+ time.Sleep(7 * time.Millisecond)
+ })
+ })
+ time.Sleep(1 * time.Millisecond)
+}
diff --git a/src/testing/benchmark.go b/src/testing/benchmark.go
index c9012ea..5cbf1af 100644
--- a/src/testing/benchmark.go
+++ b/src/testing/benchmark.go
@@ -188,6 +188,7 @@
b.parallelism = 1
b.ResetTimer()
b.StartTimer()
+ b.setOwnTimer()
b.benchFunc(b)
b.StopTimer()
b.previousN = n
@@ -281,6 +282,8 @@
b.signal <- true
}()
+ defer b.stopOwnTimer()
+
// Run the benchmark for at least the specified amount of time.
if b.benchTime.n > 0 {
// We already ran a single iteration in run1.
diff --git a/src/testing/fuzz.go b/src/testing/fuzz.go
index d31a3f8..f2ff0b4 100644
--- a/src/testing/fuzz.go
+++ b/src/testing/fuzz.go
@@ -717,8 +717,10 @@
f.runCleanup(normalPanic)
}
}()
+ defer f.stopOwnTimer()
f.start = time.Now()
+ f.setOwnTimer()
fn(f)
// Code beyond this point will not be executed when FailNow or SkipNow
diff --git a/src/testing/testing.go b/src/testing/testing.go
index 1bc8aff..e0914f3 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -376,6 +376,7 @@
"internal/goexperiment"
"internal/race"
"io"
+ "math"
"math/rand"
"os"
"reflect"
@@ -437,6 +438,7 @@
panicOnExit0 = flag.Bool("test.paniconexit0", false, "panic on call to os.Exit(0)")
traceFile = flag.String("test.trace", "", "write an execution trace to `file`")
timeout = flag.Duration("test.timeout", 0, "panic test binary after duration `d` (default 0, timeout disabled)")
+ testTimeout = flag.Duration("test.testtimeout", 0, "panic test binary if a single test, benchmark or fuzz target takes more than duration `d` (defaults to 1m, or the the test.timeout value if set; set to 0 to disable)")
cpuListStr = flag.String("test.cpu", "", "comma-separated `list` of cpu counts to run each test with")
parallel = flag.Int("test.parallel", runtime.GOMAXPROCS(0), "run at most `n` tests in parallel")
testlog = flag.String("test.testlogfile", "", "write test action log to `file` (for use only by cmd/go)")
@@ -469,6 +471,7 @@
panicOnExit0 *bool
traceFile *string
timeout *time.Duration
+ testTimeout *time.Duration
cpuListStr *string
parallel *int
shuffle *string
@@ -621,9 +624,12 @@
name string // Name of test or benchmark.
start time.Time // Time test or benchmark started
duration time.Duration
- barrier chan bool // To signal parallel subtests they may start. Nil when T.Parallel is not present (B) or not usable (when fuzzing).
- signal chan bool // To signal a test is done.
- sub []*T // Queue of subtests to be run in parallel.
+ barrier chan bool // To signal parallel subtests they may start. Nil when T.Parallel is not present (B) or not usable (when fuzzing).
+ signal chan bool // To signal a test is done.
+ sub []*T // Queue of subtests to be run in parallel.
+ timeout time.Duration // The timeout for an the individual test/benchmark/fuzz.
+ paused time.Duration // The time this test spent blocked.
+ timer *time.Timer // The individual test timer.
tempDirMu sync.Mutex
tempDir string
@@ -890,6 +896,7 @@
Logf(format string, args ...any)
Name() string
Setenv(key, value string)
+ SetTimeout(d time.Duration)
Skip(args ...any)
SkipNow()
Skipf(format string, args ...any)
@@ -1300,6 +1307,53 @@
}
}
+// SetTimeout sets the maximum amount of time a test function, benchmark or
+// fuzz targets can run for. If `d` is 0, the timer is disabled.
+// The individual timer does not tick down while a parent test waits on a
+// t.Run or t.Parallel call.
+// Subsequent calls to SetTimeout do not Reset the timer, but instead set the
+// timeout as `d` from the start of the test call. In case d has already
+// elapsed the test will timeout immediately.
+func (c *common) SetTimeout(d time.Duration) {
+ if d <= 0 {
+ c.stopOwnTimer()
+ c.timeout = 0
+ return
+ }
+
+ c.timeout = d
+ c.scheduleOwnTimer()
+}
+
+func (c *common) scheduleOwnTimer() {
+ c.timer.Reset(time.Until(c.start.Add(c.paused).Add(c.timeout)))
+}
+
+func (c *common) stopOwnTimer() {
+ c.timer.Stop()
+}
+
+func (c *common) setOwnTimer() {
+ if c.timeout <= 0 {
+ c.timeout = time.Duration(math.MaxInt64)
+ }
+
+ c.timer = time.AfterFunc(c.timeout, func() {
+ debug.SetTraceback("all")
+ extra := ""
+ if list := runningList(); len(list) > 0 {
+ var b strings.Builder
+ b.WriteString("\nrunning tests:")
+ for _, name := range list {
+ b.WriteString("\n\t")
+ b.WriteString(name)
+ }
+ extra = b.String()
+ }
+ panic(fmt.Sprintf("%s timed out after %v%s", c.name, c.timeout, extra))
+ })
+}
+
// panicHanding is an argument to runCleanup.
type panicHandling int
@@ -1399,6 +1453,12 @@
}
running.Delete(t.name)
+ // We're about to block until all the parallel tests can resume execution.
+ // We stop the test's own timer from running and resume it once the tests
+ // have been released.
+ t.stopOwnTimer()
+ defer t.scheduleOwnTimer()
+
t.signal <- true // Release calling test.
<-t.parent.barrier // Wait for the parent test to complete.
t.context.waitParallel()
@@ -1589,8 +1649,10 @@
t.runCleanup(normalPanic)
}
}()
+ defer t.stopOwnTimer()
t.start = time.Now()
+ t.setOwnTimer()
t.raceErrors = -race.Errors()
fn(t)
@@ -1630,9 +1692,16 @@
level: t.level + 1,
creator: pc[:n],
chatty: t.chatty,
+ timeout: *testTimeout,
},
context: t.context,
}
+
+ // If the parent test has a timeout value set, inherit it.
+ if t.parent.timeout != 0 {
+ t.timeout = t.parent.timeout
+ }
+
t.w = indenter{&t.common}
if t.chatty != nil {
@@ -1646,6 +1715,18 @@
// without being preempted, even when their parent is a parallel test. This
// may especially reduce surprises if *parallel == 1.
go tRunner(t, f)
+
+ // After launching tRunner in a separate goroutine, we're blocking until it
+ // returns. If the parent test has a timer, stop it and resume once the
+ // child test has returned, taking the pause into account.
+ if t.parent != nil && t.parent.timer != nil {
+ t.parent.stopOwnTimer()
+ defer func() {
+ t.parent.paused += t.duration
+ t.parent.scheduleOwnTimer()
+ }()
+ }
+
if !<-t.signal {
// At this point, it is likely that FailNow was called on one of the
// parent tests by one of the subtests. Continue aborting up the chain.
To view, visit change 526355. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Bryan Mills, Michael Matloob.
3 comments:
File src/cmd/go/testdata/script/test_testtimeout.txt:
Patch Set #1, Line 50: t.SetTimeout(10 * time.Millisecond)
I'm not 100% certain about this kind of tests, they might be slow and flaky, but I'm also not sure what a better solution would look like.
File src/testing/testing.go:
Patch Set #1, Line 1325: c.scheduleOwnTimer()
Now that I think of it, we might have to descend down to `c.sub` and call the SetTimeout to parallel tests waiting to run? The t.Run subtests already inherit the latest value of the parent's timeout.
Patch Set #1, Line 1341: c.timer = time.AfterFunc(c.timeout, func() {
I stole the AfterFunc we use for the regular `-timeout` flag. Maybe we can abstract it out.
To view, visit change 526355. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Bryan Mills, Michael Matloob, Paschalis Tsilias.
Patch set 1:Commit-Queue +1
Attention is currently required from: Ian Lance Taylor, Michael Matloob, Paschalis Tsilias.
10 comments:
File src/cmd/go/internal/test/testflag.go:
Patch Set #1, Line 65: cf.DurationVar(&testTestTimeout, "testtimeout", 1*time.Minute, "")
(also commented in https://go.dev/issue/48157#issuecomment-1732003381)
Given that #48157 (per-test timeouts) was approved before #56986 (extended backwards compatibility) was filed, I wonder how the two should interact.
I suspect that the default per-test timeout should depend in some way on the `go` version in use, perhaps through a `GODEBUG` setting.
Patch Set #1, Line 382: if timeoutSet {
I think this needs to be a bit more nuanced: `-test.testtimeout` should match `testTestTimeout` if `-testtimeout` is explicitly set _or_ `-timeout` is _not_ explicitly set.
File src/cmd/go/testdata/script/test_testtimeout.txt:
Patch Set #1, Line 1: [short] skip
I think many of the behaviors exercised here should be tested in the `testing` package instead. The test can run itself as a subprocess using `testenv.Command` and pass the appropriate `-test.timeout` and `-test.testtimeout` flags to the subprocess.
(See https://go-review.git.corp.google.com/c/go/+/506955/3/src/testing/helper_test.go for an example of how to do so.)
Patch Set #1, Line 50: t.SetTimeout(10 * time.Millisecond)
I'm not 100% certain about this kind of tests, they might be slow and flaky, but I'm also not sure w […]
The tests need to target only the two extremes: either the timeout should be guaranteed to expire, or the timeout should be so long that it is basically guaranteed _not_ to expire.
For short timeouts, we can at least confirm a couple of properties of the failure:
Note that, in particular:
----
For the long timeouts, I would expect to be able to measure the effect of the call to `SetTimeout` by examining the timestamp returned by `t.Deadline()`. I don't think we can do much better than that without making the tests too long.
File src/testing/benchmark.go:
Patch Set #1, Line 191: b.setOwnTimer()
I think there are some serious questions we need to address about benchmarks vs. per-test timeouts. 😅
Patch Set #1, Line 285: defer b.stopOwnTimer()
It seems like the call to `b.setOwnTimer()` and the `defer b.stopOwnTimer()` should occur together in the same function — otherwise it's hard to confirm that they are actually paired.
(Note that I am trying to clean up a bunch of this synchronization in CL 506755; you might consider rebasing on top of that.)
File src/testing/fuzz.go:
Patch Set #1, Line 720: defer f.stopOwnTimer()
Please combine these two `defer` blocks.
In particular, the test timeout should still apply while we are running cleanup functions. (If the test hangs past its timeout in a callback registered by `t.Cleanup`, that should cause the individual test to fail.)
File src/testing/testing.go:
Patch Set #1, Line 1325: c.scheduleOwnTimer()
Now that I think of it, we might have to descend down to `c. […]
I think if a subtest has already been started, it's fine for that subtest to keep on using the timeout that was set when it was started.
Otherwise we have to deal with the possibility of races between calls to `SetTimeout` in the parent and the subtest, and I really don't want to deal with that. 😵💫
Patch Set #1, Line 1333: c.timer.Stop()
If this fails to stop the timer, it should halt the program until the panic takes effect so that it won't mask a weird failure mode.
Something like:
```go
if !c.timer.Stop() {
// The timer already fired.
// Wait for it to terminate the program.
select {}
}
```
Patch Set #1, Line 1460: defer t.scheduleOwnTimer()
This should pause the timer rather than resetting it.
If a test calls `SetTimeout(1 * time.Minute)`, then runs for 30s, then calls `t.Parallel()`, then runs for 30s more, that should arguably trigger the timeout.
That probably implies tracking the time elapsed between each start and stop of the timer.
To view, visit change 526355. To unsubscribe, or for help writing mail filters, visit settings.
Attention is currently required from: Ian Lance Taylor, Michael Matloob, Paschalis Tsilias.
1 comment:
Patchset:
Paschalis do you think you will be able to get back to this in, say, the next couple of months? I ask because I'd really like to see this go in for Go 1.23 and I might have time to work on it if you won't.
To view, visit change 526355. To unsubscribe, or for help writing mail filters, visit settings.
Paschalis do you think you will be able to get back to this in, say, the next couple of months? I ask because I'd really like to see this go in for Go 1.23 and I might have time to work on it if you won't.
I think I'll have some time for this in the next couple of weeks. If not, I'll ping you so you can take a stab.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. | Gerrit |
Paschalis TsiliasPaschalis do you think you will be able to get back to this in, say, the next couple of months? I ask because I'd really like to see this go in for Go 1.23 and I might have time to work on it if you won't.
Paschalis TsiliasI think I'll have some time for this in the next couple of weeks. If not, I'll ping you so you can take a stab.
Hey there Caleb.
Unfortunately I hadn't had the time to work for it and I don't mean to be a blocker, so if you want to pick it up in the meantime, feel free.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Mailed a new patch set to resolve some low-hanging fruit and rebase with master.
I'm marking it as draft as _it's not ready for review_.
I'll continue with amending the logic, making sure the new GODEBUG statement works as intended and write proper tests
cf.DurationVar(&testTestTimeout, "testtimeout", 1*time.Minute, "")(also commented in https://go.dev/issue/48157#issuecomment-1732003381)
Given that #48157 (per-test timeouts) was approved before #56986 (extended backwards compatibility) was filed, I wonder how the two should interact.
I suspect that the default per-test timeout should depend in some way on the `go` version in use, perhaps through a `GODEBUG` setting.
Done
I think many of the behaviors exercised here should be tested in the `testing` package instead. The test can run itself as a subprocess using `testenv.Command` and pass the appropriate `-test.timeout` and `-test.testtimeout` flags to the subprocess.
(See https://go-review.git.corp.google.com/c/go/+/506955/3/src/testing/helper_test.go for an example of how to do so.)
Ok, removing it and opting for regular tests in the `testing` package instead (thanks for the hint!)
It seems like the call to `b.setOwnTimer()` and the `defer b.stopOwnTimer()` should occur together in the same function — otherwise it's hard to confirm that they are actually paired.
(Note that I am trying to clean up a bunch of this synchronization in CL 506755; you might consider rebasing on top of that.)
Done
Please combine these two `defer` blocks.
In particular, the test timeout should still apply while we are running cleanup functions. (If the test hangs past its timeout in a callback registered by `t.Cleanup`, that should cause the individual test to fail.)
Done
If this fails to stop the timer, it should halt the program until the panic takes effect so that it won't mask a weird failure mode.
Something like:
```go
if !c.timer.Stop() {
// The timer already fired.
// Wait for it to terminate the program.
select {}
}
```
Done
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Adding adonovan and dneil from tools owners.
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |