context: deflake time-sensitive tests

Many of tests in this package assumed reasonable scheduling latency.
Unfortunately, scheduling latency on builders and CI systems is not
always reasonable.

Rather than expecting that a timeout is detected within a fixed short
interval, we can use (*testing.T).Deadline to portably scale the time
we're willing to wait to something appropriate to the builder.

Some of the tests also included arbitrary-duration sleeps, which are
no longer needed after CL 196521; we can remove those instead of
extending them.

Promptness of timeouts is also an important property, but testing that
property is better suited to benchmarks than to tests proper: unlike
tests, we generally expect benchmarks to be run in a quiet,
low-contention environment.

Fixes #13956

Change-Id: I0797e2267fb778c8ad94add56d797de9e2c885e5
Reviewed-on: https://go-review.googlesource.com/c/go/+/223019
Run-TryBot: Bryan C. Mills <bcmills@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

diff --git a/src/context/context_test.go b/src/context/context_test.go
index cff09fd322fcea0c9c1d518a33715d26996e360d..da29ed0c2b903ec904b442caa46b78828e7d1df7 100644 (file)
--- a/src/context/context_test.go
+++ b/src/context/context_test.go
@@ -15,6 +15,7 @@ import (
 )
 
 type testingT interface {
+       Deadline() (time.Time, bool)
        Error(args ...interface{})
        Errorf(format string, args ...interface{})
        Fail()
@@ -39,6 +40,23 @@ type otherContext struct {
        Context
 }
 
+const (
+       shortDuration    = 1 * time.Millisecond // a reasonable duration to block in a test
+       veryLongDuration = 1000 * time.Hour     // an arbitrary upper bound on the test's running time
+)
+
+// quiescent returns an arbitrary duration by which the program should have
+// completed any remaining work and reached a steady (idle) state.
+func quiescent(t testingT) time.Duration {
+       deadline, ok := t.Deadline()
+       if !ok {
+               return 5 * time.Second
+       }
+
+       const arbitraryCleanupMargin = 1 * time.Second
+       return time.Until(deadline) - arbitraryCleanupMargin
+}
+
 func XTestBackground(t testingT) {
        c := Background()
        if c == nil {
@@ -95,9 +113,7 @@ func XTestWithCancel(t testingT) {
                }
        }
 
-       cancel()
-       time.Sleep(100 * time.Millisecond) // let cancellation propagate
-
+       cancel() // Should propagate synchronously.
        for i, c := range contexts {
                select {
                case <-c.Done():
@@ -123,7 +139,7 @@ func XTestParentFinishesChild(t testingT) {
        cancelChild, stop := WithCancel(parent)
        defer stop()
        valueChild := WithValue(parent, "key", "value")
-       timerChild, stop := WithTimeout(valueChild, 10000*time.Hour)
+       timerChild, stop := WithTimeout(valueChild, veryLongDuration)
        defer stop()
 
        select {
@@ -252,11 +268,14 @@ func XTestChildFinishesFirst(t testingT) {
        }
 }
 
-func testDeadline(c Context, name string, failAfter time.Duration, t testingT) {
+func testDeadline(c Context, name string, t testingT) {
        t.Helper()
+       d := quiescent(t)
+       timer := time.NewTimer(d)
+       defer timer.Stop()
        select {
-       case <-time.After(failAfter):
-               t.Fatalf("%s: context should have timed out", name)
+       case <-timer.C:
+               t.Fatalf("%s: context not timed out after %v", name, d)
        case <-c.Done():
        }
        if e := c.Err(); e != DeadlineExceeded {
@@ -265,51 +284,50 @@ func testDeadline(c Context, name string, failAfter time.Duration, t testingT) {
 }
 
 func XTestDeadline(t testingT) {
-       c, _ := WithDeadline(Background(), time.Now().Add(50*time.Millisecond))
+       c, _ := WithDeadline(Background(), time.Now().Add(shortDuration))
        if got, prefix := fmt.Sprint(c), "context.Background.WithDeadline("; !strings.HasPrefix(got, prefix) {
                t.Errorf("c.String() = %q want prefix %q", got, prefix)
        }
-       testDeadline(c, "WithDeadline", time.Second, t)
+       testDeadline(c, "WithDeadline", t)
 
-       c, _ = WithDeadline(Background(), time.Now().Add(50*time.Millisecond))
+       c, _ = WithDeadline(Background(), time.Now().Add(shortDuration))
        o := otherContext{c}
-       testDeadline(o, "WithDeadline+otherContext", time.Second, t)
+       testDeadline(o, "WithDeadline+otherContext", t)
 
-       c, _ = WithDeadline(Background(), time.Now().Add(50*time.Millisecond))
+       c, _ = WithDeadline(Background(), time.Now().Add(shortDuration))
        o = otherContext{c}
-       c, _ = WithDeadline(o, time.Now().Add(4*time.Second))
-       testDeadline(c, "WithDeadline+otherContext+WithDeadline", 2*time.Second, t)
+       c, _ = WithDeadline(o, time.Now().Add(veryLongDuration))
+       testDeadline(c, "WithDeadline+otherContext+WithDeadline", t)
 
-       c, _ = WithDeadline(Background(), time.Now().Add(-time.Millisecond))
-       testDeadline(c, "WithDeadline+inthepast", time.Second, t)
+       c, _ = WithDeadline(Background(), time.Now().Add(-shortDuration))
+       testDeadline(c, "WithDeadline+inthepast", t)
 
        c, _ = WithDeadline(Background(), time.Now())
-       testDeadline(c, "WithDeadline+now", time.Second, t)
+       testDeadline(c, "WithDeadline+now", t)
 }
 
 func XTestTimeout(t testingT) {
-       c, _ := WithTimeout(Background(), 50*time.Millisecond)
+       c, _ := WithTimeout(Background(), shortDuration)
        if got, prefix := fmt.Sprint(c), "context.Background.WithDeadline("; !strings.HasPrefix(got, prefix) {
                t.Errorf("c.String() = %q want prefix %q", got, prefix)
        }
-       testDeadline(c, "WithTimeout", time.Second, t)
+       testDeadline(c, "WithTimeout", t)
 
-       c, _ = WithTimeout(Background(), 50*time.Millisecond)
+       c, _ = WithTimeout(Background(), shortDuration)
        o := otherContext{c}
-       testDeadline(o, "WithTimeout+otherContext", time.Second, t)
+       testDeadline(o, "WithTimeout+otherContext", t)
 
-       c, _ = WithTimeout(Background(), 50*time.Millisecond)
+       c, _ = WithTimeout(Background(), shortDuration)
        o = otherContext{c}
-       c, _ = WithTimeout(o, 3*time.Second)
-       testDeadline(c, "WithTimeout+otherContext+WithTimeout", 2*time.Second, t)
+       c, _ = WithTimeout(o, veryLongDuration)
+       testDeadline(c, "WithTimeout+otherContext+WithTimeout", t)
 }
 
 func XTestCanceledTimeout(t testingT) {
        c, _ := WithTimeout(Background(), time.Second)
        o := otherContext{c}
-       c, cancel := WithTimeout(o, 2*time.Second)
-       cancel()
-       time.Sleep(100 * time.Millisecond) // let cancellation propagate
+       c, cancel := WithTimeout(o, veryLongDuration)
+       cancel() // Should propagate synchronously.
        select {
        case <-c.Done():
        default:
@@ -467,14 +485,20 @@ func XTestSimultaneousCancels(t testingT) {
                        wg.Done()
                }(cancel)
        }
+
+       d := quiescent(t)
+       stuck := make(chan struct{})
+       timer := time.AfterFunc(d, func() { close(stuck) })
+       defer timer.Stop()
+
        // Wait on all the contexts in a random order.
        for ctx := range m {
                select {
                case <-ctx.Done():
-               case <-time.After(1 * time.Second):
+               case <-stuck:
                        buf := make([]byte, 10<<10)
                        n := runtime.Stack(buf, true)
-                       t.Fatalf("timed out waiting for <-ctx.Done(); stacks:\n%s", buf[:n])
+                       t.Fatalf("timed out after %v waiting for <-ctx.Done(); stacks:\n%s", d, buf[:n])
                }
        }
        // Wait for all the cancel functions to return.
@@ -485,10 +509,10 @@ func XTestSimultaneousCancels(t testingT) {
        }()
        select {
        case <-done:
-       case <-time.After(1 * time.Second):
+       case <-stuck:
                buf := make([]byte, 10<<10)
                n := runtime.Stack(buf, true)
-               t.Fatalf("timed out waiting for cancel functions; stacks:\n%s", buf[:n])
+               t.Fatalf("timed out after %v waiting for cancel functions; stacks:\n%s", d, buf[:n])
        }
 }
 
@@ -500,12 +524,15 @@ func XTestInterlockedCancels(t testingT) {
                cancelChild()
        }()
        cancelParent()
+       d := quiescent(t)
+       timer := time.NewTimer(d)
+       defer timer.Stop()
        select {
        case <-child.Done():
-       case <-time.After(1 * time.Second):
+       case <-timer.C:
                buf := make([]byte, 10<<10)
                n := runtime.Stack(buf, true)
-               t.Fatalf("timed out waiting for child.Done(); stacks:\n%s", buf[:n])
+               t.Fatalf("timed out after %v waiting for child.Done(); stacks:\n%s", d, buf[:n])
        }
 }
 
@@ -523,7 +550,6 @@ func testLayers(t testingT, seed int64, testTimeout bool) {
                t.Errorf(fmt.Sprintf("seed=%d: %s", seed, format), a...)
        }
        const (
-               timeout   = 200 * time.Millisecond
                minLayers = 30
        )
        type value int
@@ -545,7 +571,11 @@ func testLayers(t testingT, seed int64, testTimeout bool) {
                        cancels = append(cancels, cancel)
                case 2:
                        var cancel CancelFunc
-                       ctx, cancel = WithTimeout(ctx, timeout)
+                       d := veryLongDuration
+                       if testTimeout {
+                               d = shortDuration
+                       }
+                       ctx, cancel = WithTimeout(ctx, d)
                        cancels = append(cancels, cancel)
                        numTimers++
                }
@@ -568,10 +598,13 @@ func testLayers(t testingT, seed int64, testTimeout bool) {
        t.Log(ctx)
        checkValues("before cancel")
        if testTimeout {
+               d := quiescent(t)
+               timer := time.NewTimer(d)
+               defer timer.Stop()
                select {
                case <-ctx.Done():
-               case <-time.After(timeout + time.Second):
-                       errorf("ctx should have timed out")
+               case <-timer.C:
+                       errorf("ctx should have timed out after %v", d)
                }
                checkValues("after timeout")
        } else {
@@ -615,8 +648,8 @@ func XTestWithCancelCanceledParent(t testingT) {
        c, _ := WithCancel(parent)
        select {
        case <-c.Done():
-       case <-time.After(5 * time.Second):
-               t.Fatal("timeout waiting for Done")
+       default:
+               t.Errorf("child not done immediately upon construction")
        }
        if got, want := c.Err(), Canceled; got != want {
                t.Errorf("child not cancelled; got = %v, want = %v", got, want)
@@ -687,7 +720,7 @@ func XTestCustomContextGoroutines(t testingT) {
        cancel0()
        checkCreatedGoroutine()
 
-       _, cancel0 = WithTimeout(&myDoneCtx{Background()}, 1*time.Hour)
+       _, cancel0 = WithTimeout(&myDoneCtx{Background()}, veryLongDuration)
        cancel0()
        checkCreatedGoroutine()
 
@@ -707,7 +740,7 @@ func XTestCustomContextGoroutines(t testingT) {
        defer cancel3b()
        checkCreatedGoroutine() // ctx1 is not providing Done, must not be used
 
-       ctx4, cancel4 := WithTimeout(ctx3, 1*time.Hour)
+       ctx4, cancel4 := WithTimeout(ctx3, veryLongDuration)
        defer cancel4()
        checkNoGoroutine()
 
@@ -718,7 +751,7 @@ func XTestCustomContextGoroutines(t testingT) {
        cancel5()
        checkNoGoroutine()
 
-       _, cancel6 := WithTimeout(ctx5, 1*time.Hour)
+       _, cancel6 := WithTimeout(ctx5, veryLongDuration)
        defer cancel6()
        checkNoGoroutine()