From: Bryan C. Mills Date: Thu, 18 Nov 2021 21:07:13 +0000 (-0500) Subject: net: simplify deadline fluctuation tests X-Git-Tag: go1.18beta1~233 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=5e774b0f5c9e9d5a0dab94620d2e0030226148c2;p=gostls13.git net: simplify deadline fluctuation tests These tests were checking for fairly narrow timing windows, but were running in parallel and heavily dependent on timer and goroutine scheduling. This change eliminates unnecessary goroutines, runs the tests sequentially (dramatically shortening the timeouts to reduce the penalty of doing so), and uses timestamp comparison instead of background timers to hopefully gain some robustness from monotonic timestamps. Many of the other tests from this package would benefit from similar simplifications, which we can apply if and when we notice flaky failures or want to improve the latency of running the test. Fixes #36108 Change-Id: I17d8af7d2eefb1ec14fe0d9d891142a39599a562 Reviewed-on: https://go-review.googlesource.com/c/go/+/365334 Trust: Bryan C. Mills Run-TryBot: Bryan C. Mills Reviewed-by: Ian Lance Taylor TryBot-Result: Go Bot --- diff --git a/src/net/mockserver_test.go b/src/net/mockserver_test.go index 43b11a7218..70ecc69f66 100644 --- a/src/net/mockserver_test.go +++ b/src/net/mockserver_test.go @@ -11,7 +11,6 @@ import ( "fmt" "os" "sync" - "testing" "time" ) @@ -287,54 +286,6 @@ func transceiver(c Conn, wb []byte, ch chan<- error) { } } -func timeoutReceiver(c Conn, d, min, max time.Duration, ch chan<- error) { - var err error - defer func() { ch <- err }() - - t0 := time.Now() - if err = c.SetReadDeadline(time.Now().Add(d)); err != nil { - return - } - b := make([]byte, 256) - var n int - n, err = c.Read(b) - t1 := time.Now() - if n != 0 || err == nil || !err.(Error).Timeout() { - err = fmt.Errorf("Read did not return (0, timeout): (%d, %v)", n, err) - return - } - if dt := t1.Sub(t0); min > dt || dt > max && !testing.Short() { - err = fmt.Errorf("Read took %s; expected %s", dt, d) - return - } -} - -func timeoutTransmitter(c Conn, d, min, max time.Duration, ch chan<- error) { - var err error - defer func() { ch <- err }() - - t0 := time.Now() - if err = c.SetWriteDeadline(time.Now().Add(d)); err != nil { - return - } - var n int - for { - n, err = c.Write([]byte("TIMEOUT TRANSMITTER")) - if err != nil { - break - } - } - t1 := time.Now() - if err == nil || !err.(Error).Timeout() { - err = fmt.Errorf("Write did not return (any, timeout): (%d, %v)", n, err) - return - } - if dt := t1.Sub(t0); min > dt || dt > max && !testing.Short() { - err = fmt.Errorf("Write took %s; expected %s", dt, d) - return - } -} - func newLocalPacketListener(network string) (PacketConn, error) { switch network { case "udp": @@ -504,25 +455,3 @@ func packetTransceiver(c PacketConn, wb []byte, dst Addr, ch chan<- error) { ch <- fmt.Errorf("read %d; want %d", n, len(wb)) } } - -func timeoutPacketReceiver(c PacketConn, d, min, max time.Duration, ch chan<- error) { - var err error - defer func() { ch <- err }() - - t0 := time.Now() - if err = c.SetReadDeadline(time.Now().Add(d)); err != nil { - return - } - b := make([]byte, 256) - var n int - n, _, err = c.ReadFrom(b) - t1 := time.Now() - if n != 0 || err == nil || !err.(Error).Timeout() { - err = fmt.Errorf("ReadFrom did not return (0, timeout): (%d, %v)", n, err) - return - } - if dt := t1.Sub(t0); min > dt || dt > max && !testing.Short() { - err = fmt.Errorf("ReadFrom took %s; expected %s", dt, d) - return - } -} diff --git a/src/net/timeout_test.go b/src/net/timeout_test.go index 82069b347a..d345bf85ac 100644 --- a/src/net/timeout_test.go +++ b/src/net/timeout_test.go @@ -643,9 +643,24 @@ func TestWriteToTimeout(t *testing.T) { } } -func TestReadTimeoutFluctuation(t *testing.T) { - t.Parallel() +const ( + // minDynamicTimeout is the minimum timeout to attempt for + // tests that automatically increase timeouts until success. + // + // Lower values may allow tests to succeed more quickly if the value is close + // to the true minimum, but may require more iterations (and waste more time + // and CPU power on failed attempts) if the timeout is too low. + minDynamicTimeout = 1 * time.Millisecond + + // maxDynamicTimeout is the maximum timeout to attempt for + // tests that automatically increase timeouts until succeess. + // + // This should be a strict upper bound on the latency of the timeout: if a + // test would increase the timeout beyond this value, the test fails. + maxDynamicTimeout = 1 * time.Second +) +func TestReadTimeoutFluctuation(t *testing.T) { ln, err := newLocalListener("tcp") if err != nil { t.Fatal(err) @@ -658,27 +673,52 @@ func TestReadTimeoutFluctuation(t *testing.T) { } defer c.Close() - max := time.NewTimer(time.Second) - defer max.Stop() - ch := make(chan error) - go timeoutReceiver(c, 100*time.Millisecond, 50*time.Millisecond, 250*time.Millisecond, ch) + d := minDynamicTimeout + b := make([]byte, 256) + for { + t.Logf("SetReadDeadline(+%v)", d) + t0 := time.Now() + deadline := t0.Add(d) + if err = c.SetReadDeadline(deadline); err != nil { + t.Fatalf("SetReadDeadline(%v): %v", deadline, err) + } + var n int + n, err = c.Read(b) + t1 := time.Now() - select { - case <-max.C: - t.Fatal("Read took over 1s; expected 0.1s") - case err := <-ch: + if n != 0 || err == nil || !err.(Error).Timeout() { + t.Errorf("Read did not return (0, timeout): (%d, %v)", n, err) + } if perr := parseReadError(err); perr != nil { t.Error(perr) } if !isDeadlineExceeded(err) { - t.Fatal(err) + t.Errorf("Read error is not DeadlineExceeded: %v", err) + } + + actual := t1.Sub(t0) + if t1.Before(deadline) { + t.Errorf("Read took %s; expected at least %s", actual, d) } + if t.Failed() { + return + } + if actual > d*11/10 { + if actual > maxDynamicTimeout || d > maxDynamicTimeout/2 { + t.Fatalf("Read took %s; expected %v", actual, d) + } + // Maybe this machine is too slow to reliably schedule goroutines within + // the requested duration. Increase the timeout and try again. + t.Logf("Read took %s (expected %s); trying with longer timeout", actual, d) + d *= 2 + continue + } + + break } } func TestReadFromTimeoutFluctuation(t *testing.T) { - t.Parallel() - c1, err := newLocalPacketListener("udp") if err != nil { t.Fatal(err) @@ -691,27 +731,52 @@ func TestReadFromTimeoutFluctuation(t *testing.T) { } defer c2.Close() - max := time.NewTimer(time.Second) - defer max.Stop() - ch := make(chan error) - go timeoutPacketReceiver(c2.(PacketConn), 100*time.Millisecond, 50*time.Millisecond, 250*time.Millisecond, ch) + d := minDynamicTimeout + b := make([]byte, 256) + for { + t.Logf("SetReadDeadline(+%v)", d) + t0 := time.Now() + deadline := t0.Add(d) + if err = c2.SetReadDeadline(deadline); err != nil { + t.Fatalf("SetReadDeadline(%v): %v", deadline, err) + } + var n int + n, _, err = c2.(PacketConn).ReadFrom(b) + t1 := time.Now() - select { - case <-max.C: - t.Fatal("ReadFrom took over 1s; expected 0.1s") - case err := <-ch: + if n != 0 || err == nil || !err.(Error).Timeout() { + t.Errorf("ReadFrom did not return (0, timeout): (%d, %v)", n, err) + } if perr := parseReadError(err); perr != nil { t.Error(perr) } if !isDeadlineExceeded(err) { - t.Fatal(err) + t.Errorf("ReadFrom error is not DeadlineExceeded: %v", err) } + + actual := t1.Sub(t0) + if t1.Before(deadline) { + t.Errorf("ReadFrom took %s; expected at least %s", actual, d) + } + if t.Failed() { + return + } + if actual > d*11/10 { + if actual > maxDynamicTimeout || d > maxDynamicTimeout/2 { + t.Fatalf("ReadFrom took %s; expected %s", actual, d) + } + // Maybe this machine is too slow to reliably schedule goroutines within + // the requested duration. Increase the timeout and try again. + t.Logf("ReadFrom took %s (expected %s); trying with longer timeout", actual, d) + d *= 2 + continue + } + + break } } func TestWriteTimeoutFluctuation(t *testing.T) { - t.Parallel() - switch runtime.GOOS { case "plan9": t.Skipf("not supported on %s", runtime.GOOS) @@ -729,25 +794,64 @@ func TestWriteTimeoutFluctuation(t *testing.T) { } defer c.Close() - d := time.Second - if iOS() { - d = 3 * time.Second // see golang.org/issue/10775 - } - max := time.NewTimer(d) - defer max.Stop() - ch := make(chan error) - go timeoutTransmitter(c, 100*time.Millisecond, 50*time.Millisecond, 250*time.Millisecond, ch) + d := minDynamicTimeout + for { + t.Logf("SetWriteDeadline(+%v)", d) + t0 := time.Now() + deadline := t0.Add(d) + if err = c.SetWriteDeadline(deadline); err != nil { + t.Fatalf("SetWriteDeadline(%v): %v", deadline, err) + } + var n int64 + for { + var dn int + dn, err = c.Write([]byte("TIMEOUT TRANSMITTER")) + n += int64(dn) + if err != nil { + break + } + } + t1 := time.Now() - select { - case <-max.C: - t.Fatalf("Write took over %v; expected 0.1s", d) - case err := <-ch: + if err == nil || !err.(Error).Timeout() { + t.Fatalf("Write did not return (any, timeout): (%d, %v)", n, err) + } if perr := parseWriteError(err); perr != nil { t.Error(perr) } if !isDeadlineExceeded(err) { - t.Fatal(err) + t.Errorf("Write error is not DeadlineExceeded: %v", err) } + + actual := t1.Sub(t0) + if t1.Before(deadline) { + t.Errorf("Write took %s; expected at least %s", actual, d) + } + if t.Failed() { + return + } + if actual > d*11/10 { + if n > 0 { + // SetWriteDeadline specifies a time “after which I/O operations fail + // instead of blocking”. However, the kernel's send buffer is not yet + // full, we may be able to write some arbitrary (but finite) number of + // bytes to it without blocking. + t.Logf("Wrote %d bytes into send buffer; retrying until buffer is full", n) + if d <= maxDynamicTimeout/2 { + d *= 2 + } + } else if actual > maxDynamicTimeout || d > maxDynamicTimeout/2 { + t.Fatalf("Write took %s; expected %s", actual, d) + } else { + // Maybe this machine is too slow to reliably schedule goroutines within + // the requested duration. Increase the timeout and try again. + t.Logf("Write took %s (expected %s); trying with longer timeout", actual, d) + d *= 2 + } + continue + } + + break } }