From 88a36c9e9a511ec6ad218633bce1e82f25e54d35 Mon Sep 17 00:00:00 2001 From: "Bryan C. Mills" Date: Wed, 1 Feb 2023 16:44:21 -0500 Subject: [PATCH] cmd/go/internal/test: scale the WaitDelay for test subprocesses Prior to CL 456116 we had an arbitrary 5-second delay after a test times out before we kill the test. In CL 456116, I reused that arbitrary 5-second delay as the WaitDelay as well, but on slower builders it does not seem to be generous enough. Instead of hard-coding the delay, for tests with a finite timout we now use a hard-coded fraction of the overall timeout. That will probably give delays that are longer than strictly necessary for very long timeouts, but if the user is willing to wait for a very long timeout they can probably wait a little longer for I/O too. Fixes #58230. Updates #24050. Change-Id: Ifbf3e576c034c721aa00cd17bf88563474b09955 Reviewed-on: https://go-review.googlesource.com/c/go/+/464555 TryBot-Result: Gopher Robot Reviewed-by: Michael Pratt Run-TryBot: Bryan Mills Auto-Submit: Bryan Mills --- src/cmd/go/internal/test/test.go | 36 +++++++++++++++++-- .../go/testdata/script/test_timeout_stdin.txt | 4 +-- 2 files changed, 35 insertions(+), 5 deletions(-) diff --git a/src/cmd/go/internal/test/test.go b/src/cmd/go/internal/test/test.go index 48760ba914..250046104b 100644 --- a/src/cmd/go/internal/test/test.go +++ b/src/cmd/go/internal/test/test.go @@ -580,6 +580,7 @@ var ( testHelp bool // -help option passed to test via -args testKillTimeout = 100 * 365 * 24 * time.Hour // backup alarm; defaults to about a century if no timeout is set + testWaitDelay time.Duration // how long to wait for output to close after a test binary exits; zero means unlimited testCacheExpire time.Time // ignore cached test results before this time testBlockProfile, testCPUProfile, testMemProfile, testMutexProfile, testTrace string // profiling flag that limits test to one package @@ -754,7 +755,35 @@ func runTest(ctx context.Context, cmd *base.Command, args []string) { // Don't set this if fuzzing, since it should be able to run // indefinitely. if testTimeout > 0 && testFuzz == "" { - testKillTimeout = testTimeout + 1*time.Minute + // The WaitDelay for the test process depends on both the OS I/O and + // scheduling overhead and the amount of I/O generated by the test just + // before it exits. We set the minimum at 5 seconds to account for the OS + // overhead, and scale it up from there proportional to the overall test + // timeout on the assumption that the time to write and read a goroutine + // dump from a timed-out test process scales roughly with the overall + // running time of the test. + // + // This is probably too generous when the timeout is very long, but it seems + // better to hard-code a scale factor than to hard-code a constant delay. + if wd := testTimeout / 10; wd < 5*time.Second { + testWaitDelay = 5 * time.Second + } else { + testWaitDelay = wd + } + + // We expect the test binary to terminate itself (and dump stacks) after + // exactly testTimeout. We give it up to one WaitDelay or one minute, + // whichever is longer, to finish dumping stacks before we send it an + // external signal: if the process has a lot of goroutines, dumping stacks + // after the timeout can take a while. + // + // After the signal is delivered, the test process may have up to one + // additional WaitDelay to finish writing its output streams. + if testWaitDelay < 1*time.Minute { + testKillTimeout = testTimeout + 1*time.Minute + } else { + testKillTimeout = testTimeout + testWaitDelay + } } // Read testcache expiration time, if present. @@ -1336,8 +1365,7 @@ func (r *runTestActor) Act(b *work.Builder, ctx context.Context, a *work.Action) } return err } - // Give the test five seconds to exit after the signal before resorting to Kill. - cmd.WaitDelay = 5 * time.Second + cmd.WaitDelay = testWaitDelay base.StartSigHandlers() t0 := time.Now() @@ -1375,6 +1403,8 @@ func (r *runTestActor) Act(b *work.Builder, ctx context.Context, a *work.Action) fmt.Fprintf(cmd.Stdout, "*** Test killed with %v: ran too long (%v).\n", base.SignalTrace, testKillTimeout) } else if cancelKilled { fmt.Fprintf(cmd.Stdout, "*** Test killed: ran too long (%v).\n", testKillTimeout) + } else if errors.Is(err, exec.ErrWaitDelay) { + fmt.Fprintf(cmd.Stdout, "*** Test I/O incomplete %v after exiting.\n", cmd.WaitDelay) } var ee *exec.ExitError if len(out) == 0 || !errors.As(err, &ee) || !ee.Exited() { diff --git a/src/cmd/go/testdata/script/test_timeout_stdin.txt b/src/cmd/go/testdata/script/test_timeout_stdin.txt index 606ffa73f9..f2de0a67ef 100644 --- a/src/cmd/go/testdata/script/test_timeout_stdin.txt +++ b/src/cmd/go/testdata/script/test_timeout_stdin.txt @@ -1,7 +1,7 @@ # Regression test for https://go.dev/issue/24050: # a test that exits with an I/O stream held open # should fail after a reasonable delay, not wait forever. -# (As of the time of writing, that delay is 5 seconds, +# (As of the time of writing, that delay is 10% of the timeout, # but this test does not depend on its specific value.) [short] skip 'runs a test that hangs until its WaitDelay expires' @@ -18,7 +18,7 @@ # exit due to a failed write to that pipe. stdout '^--- PASS: TestOrphanCmd .*\nPASS\nstdin closed' -stdout '^exec: WaitDelay expired before I/O complete\nFAIL\s+example\s+\d+(\.\d+)?s' +stdout '^\*\*\* Test I/O incomplete \d+.* after exiting\.\nexec: WaitDelay expired before I/O complete\nFAIL\s+example\s+\d+(\.\d+)?s' -- go.mod -- module example -- 2.50.0