diff options
author | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-16 19:23:18 +0000 |
---|---|---|
committer | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-16 19:23:18 +0000 |
commit | 43a123c1ae6613b3efeed291fa552ecd909d3acf (patch) | |
tree | fd92518b7024bc74031f78a1cf9e454b65e73665 /src/time/sleep_test.go | |
parent | Initial commit. (diff) | |
download | golang-1.20-upstream.tar.xz golang-1.20-upstream.zip |
Adding upstream version 1.20.14.upstream/1.20.14upstream
Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>
Diffstat (limited to 'src/time/sleep_test.go')
-rw-r--r-- | src/time/sleep_test.go | 821 |
1 files changed, 821 insertions, 0 deletions
diff --git a/src/time/sleep_test.go b/src/time/sleep_test.go new file mode 100644 index 0000000..8aac3b6 --- /dev/null +++ b/src/time/sleep_test.go @@ -0,0 +1,821 @@ +// Copyright 2009 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package time_test + +import ( + "errors" + "fmt" + "internal/testenv" + "math/rand" + "runtime" + "strings" + "sync" + "sync/atomic" + "testing" + . "time" +) + +// Go runtime uses different Windows timers for time.Now and sleeping. +// These can tick at different frequencies and can arrive out of sync. +// The effect can be seen, for example, as time.Sleep(100ms) is actually +// shorter then 100ms when measured as difference between time.Now before and +// after time.Sleep call. This was observed on Windows XP SP3 (windows/386). +// windowsInaccuracy is to ignore such errors. +const windowsInaccuracy = 17 * Millisecond + +func TestSleep(t *testing.T) { + const delay = 100 * Millisecond + go func() { + Sleep(delay / 2) + Interrupt() + }() + start := Now() + Sleep(delay) + delayadj := delay + if runtime.GOOS == "windows" { + delayadj -= windowsInaccuracy + } + duration := Now().Sub(start) + if duration < delayadj { + t.Fatalf("Sleep(%s) slept for only %s", delay, duration) + } +} + +// Test the basic function calling behavior. Correct queueing +// behavior is tested elsewhere, since After and AfterFunc share +// the same code. +func TestAfterFunc(t *testing.T) { + i := 10 + c := make(chan bool) + var f func() + f = func() { + i-- + if i >= 0 { + AfterFunc(0, f) + Sleep(1 * Second) + } else { + c <- true + } + } + + AfterFunc(0, f) + <-c +} + +func TestAfterStress(t *testing.T) { + var stop atomic.Bool + go func() { + for !stop.Load() { + runtime.GC() + // Yield so that the OS can wake up the timer thread, + // so that it can generate channel sends for the main goroutine, + // which will eventually set stop = 1 for us. + Sleep(Nanosecond) + } + }() + ticker := NewTicker(1) + for i := 0; i < 100; i++ { + <-ticker.C + } + ticker.Stop() + stop.Store(true) +} + +func benchmark(b *testing.B, bench func(n int)) { + + // Create equal number of garbage timers on each P before starting + // the benchmark. + var wg sync.WaitGroup + garbageAll := make([][]*Timer, runtime.GOMAXPROCS(0)) + for i := range garbageAll { + wg.Add(1) + go func(i int) { + defer wg.Done() + garbage := make([]*Timer, 1<<15) + for j := range garbage { + garbage[j] = AfterFunc(Hour, nil) + } + garbageAll[i] = garbage + }(i) + } + wg.Wait() + + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + bench(1000) + } + }) + b.StopTimer() + + for _, garbage := range garbageAll { + for _, t := range garbage { + t.Stop() + } + } +} + +func BenchmarkAfterFunc(b *testing.B) { + benchmark(b, func(n int) { + c := make(chan bool) + var f func() + f = func() { + n-- + if n >= 0 { + AfterFunc(0, f) + } else { + c <- true + } + } + + AfterFunc(0, f) + <-c + }) +} + +func BenchmarkAfter(b *testing.B) { + benchmark(b, func(n int) { + for i := 0; i < n; i++ { + <-After(1) + } + }) +} + +func BenchmarkStop(b *testing.B) { + benchmark(b, func(n int) { + for i := 0; i < n; i++ { + NewTimer(1 * Second).Stop() + } + }) +} + +func BenchmarkSimultaneousAfterFunc(b *testing.B) { + benchmark(b, func(n int) { + var wg sync.WaitGroup + wg.Add(n) + for i := 0; i < n; i++ { + AfterFunc(0, wg.Done) + } + wg.Wait() + }) +} + +func BenchmarkStartStop(b *testing.B) { + benchmark(b, func(n int) { + timers := make([]*Timer, n) + for i := 0; i < n; i++ { + timers[i] = AfterFunc(Hour, nil) + } + + for i := 0; i < n; i++ { + timers[i].Stop() + } + }) +} + +func BenchmarkReset(b *testing.B) { + benchmark(b, func(n int) { + t := NewTimer(Hour) + for i := 0; i < n; i++ { + t.Reset(Hour) + } + t.Stop() + }) +} + +func BenchmarkSleep(b *testing.B) { + benchmark(b, func(n int) { + var wg sync.WaitGroup + wg.Add(n) + for i := 0; i < n; i++ { + go func() { + Sleep(Nanosecond) + wg.Done() + }() + } + wg.Wait() + }) +} + +func TestAfter(t *testing.T) { + const delay = 100 * Millisecond + start := Now() + end := <-After(delay) + delayadj := delay + if runtime.GOOS == "windows" { + delayadj -= windowsInaccuracy + } + if duration := Now().Sub(start); duration < delayadj { + t.Fatalf("After(%s) slept for only %d ns", delay, duration) + } + if min := start.Add(delayadj); end.Before(min) { + t.Fatalf("After(%s) expect >= %s, got %s", delay, min, end) + } +} + +func TestAfterTick(t *testing.T) { + const Count = 10 + Delta := 100 * Millisecond + if testing.Short() { + Delta = 10 * Millisecond + } + t0 := Now() + for i := 0; i < Count; i++ { + <-After(Delta) + } + t1 := Now() + d := t1.Sub(t0) + target := Delta * Count + if d < target*9/10 { + t.Fatalf("%d ticks of %s too fast: took %s, expected %s", Count, Delta, d, target) + } + if !testing.Short() && d > target*30/10 { + t.Fatalf("%d ticks of %s too slow: took %s, expected %s", Count, Delta, d, target) + } +} + +func TestAfterStop(t *testing.T) { + // We want to test that we stop a timer before it runs. + // We also want to test that it didn't run after a longer timer. + // Since we don't want the test to run for too long, we don't + // want to use lengthy times. That makes the test inherently flaky. + // So only report an error if it fails five times in a row. + + var errs []string + logErrs := func() { + for _, e := range errs { + t.Log(e) + } + } + + for i := 0; i < 5; i++ { + AfterFunc(100*Millisecond, func() {}) + t0 := NewTimer(50 * Millisecond) + c1 := make(chan bool, 1) + t1 := AfterFunc(150*Millisecond, func() { c1 <- true }) + c2 := After(200 * Millisecond) + if !t0.Stop() { + errs = append(errs, "failed to stop event 0") + continue + } + if !t1.Stop() { + errs = append(errs, "failed to stop event 1") + continue + } + <-c2 + select { + case <-t0.C: + errs = append(errs, "event 0 was not stopped") + continue + case <-c1: + errs = append(errs, "event 1 was not stopped") + continue + default: + } + if t1.Stop() { + errs = append(errs, "Stop returned true twice") + continue + } + + // Test passed, so all done. + if len(errs) > 0 { + t.Logf("saw %d errors, ignoring to avoid flakiness", len(errs)) + logErrs() + } + + return + } + + t.Errorf("saw %d errors", len(errs)) + logErrs() +} + +func TestAfterQueuing(t *testing.T) { + // This test flakes out on some systems, + // so we'll try it a few times before declaring it a failure. + const attempts = 5 + err := errors.New("!=nil") + for i := 0; i < attempts && err != nil; i++ { + delta := Duration(20+i*50) * Millisecond + if err = testAfterQueuing(delta); err != nil { + t.Logf("attempt %v failed: %v", i, err) + } + } + if err != nil { + t.Fatal(err) + } +} + +var slots = []int{5, 3, 6, 6, 6, 1, 1, 2, 7, 9, 4, 8, 0} + +type afterResult struct { + slot int + t Time +} + +func await(slot int, result chan<- afterResult, ac <-chan Time) { + result <- afterResult{slot, <-ac} +} + +func testAfterQueuing(delta Duration) error { + // make the result channel buffered because we don't want + // to depend on channel queueing semantics that might + // possibly change in the future. + result := make(chan afterResult, len(slots)) + + t0 := Now() + for _, slot := range slots { + go await(slot, result, After(Duration(slot)*delta)) + } + var order []int + var times []Time + for range slots { + r := <-result + order = append(order, r.slot) + times = append(times, r.t) + } + for i := range order { + if i > 0 && order[i] < order[i-1] { + return fmt.Errorf("After calls returned out of order: %v", order) + } + } + for i, t := range times { + dt := t.Sub(t0) + target := Duration(order[i]) * delta + if dt < target-delta/2 || dt > target+delta*10 { + return fmt.Errorf("After(%s) arrived at %s, expected [%s,%s]", target, dt, target-delta/2, target+delta*10) + } + } + return nil +} + +func TestTimerStopStress(t *testing.T) { + if testing.Short() { + return + } + for i := 0; i < 100; i++ { + go func(i int) { + timer := AfterFunc(2*Second, func() { + t.Errorf("timer %d was not stopped", i) + }) + Sleep(1 * Second) + timer.Stop() + }(i) + } + Sleep(3 * Second) +} + +func TestSleepZeroDeadlock(t *testing.T) { + // Sleep(0) used to hang, the sequence of events was as follows. + // Sleep(0) sets G's status to Gwaiting, but then immediately returns leaving the status. + // Then the goroutine calls e.g. new and falls down into the scheduler due to pending GC. + // After the GC nobody wakes up the goroutine from Gwaiting status. + defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(4)) + c := make(chan bool) + go func() { + for i := 0; i < 100; i++ { + runtime.GC() + } + c <- true + }() + for i := 0; i < 100; i++ { + Sleep(0) + tmp := make(chan bool, 1) + tmp <- true + <-tmp + } + <-c +} + +func testReset(d Duration) error { + t0 := NewTimer(2 * d) + Sleep(d) + if !t0.Reset(3 * d) { + return errors.New("resetting unfired timer returned false") + } + Sleep(2 * d) + select { + case <-t0.C: + return errors.New("timer fired early") + default: + } + Sleep(2 * d) + select { + case <-t0.C: + default: + return errors.New("reset timer did not fire") + } + + if t0.Reset(50 * Millisecond) { + return errors.New("resetting expired timer returned true") + } + return nil +} + +func TestReset(t *testing.T) { + // We try to run this test with increasingly larger multiples + // until one works so slow, loaded hardware isn't as flaky, + // but without slowing down fast machines unnecessarily. + const unit = 25 * Millisecond + tries := []Duration{ + 1 * unit, + 3 * unit, + 7 * unit, + 15 * unit, + } + var err error + for _, d := range tries { + err = testReset(d) + if err == nil { + t.Logf("passed using duration %v", d) + return + } + } + t.Error(err) +} + +// Test that sleeping (via Sleep or Timer) for an interval so large it +// overflows does not result in a short sleep duration. Nor does it interfere +// with execution of other timers. If it does, timers in this or subsequent +// tests may not fire. +func TestOverflowSleep(t *testing.T) { + const big = Duration(int64(1<<63 - 1)) + + go func() { + Sleep(big) + // On failure, this may return after the test has completed, so + // we need to panic instead. + panic("big sleep returned") + }() + + select { + case <-After(big): + t.Fatalf("big timeout fired") + case <-After(25 * Millisecond): + // OK + } + + const neg = Duration(-1 << 63) + Sleep(neg) // Returns immediately. + select { + case <-After(neg): + // OK + case <-After(1 * Second): + t.Fatalf("negative timeout didn't fire") + } +} + +// Test that a panic while deleting a timer does not leave +// the timers mutex held, deadlocking a ticker.Stop in a defer. +func TestIssue5745(t *testing.T) { + ticker := NewTicker(Hour) + defer func() { + // would deadlock here before the fix due to + // lock taken before the segfault. + ticker.Stop() + + if r := recover(); r == nil { + t.Error("Expected panic, but none happened.") + } + }() + + // cause a panic due to a segfault + var timer *Timer + timer.Stop() + t.Error("Should be unreachable.") +} + +func TestOverflowPeriodRuntimeTimer(t *testing.T) { + // This may hang forever if timers are broken. See comment near + // the end of CheckRuntimeTimerOverflow in internal_test.go. + CheckRuntimeTimerPeriodOverflow() +} + +func checkZeroPanicString(t *testing.T) { + e := recover() + s, _ := e.(string) + if want := "called on uninitialized Timer"; !strings.Contains(s, want) { + t.Errorf("panic = %v; want substring %q", e, want) + } +} + +func TestZeroTimerResetPanics(t *testing.T) { + defer checkZeroPanicString(t) + var tr Timer + tr.Reset(1) +} + +func TestZeroTimerStopPanics(t *testing.T) { + defer checkZeroPanicString(t) + var tr Timer + tr.Stop() +} + +// Test that zero duration timers aren't missed by the scheduler. Regression test for issue 44868. +func TestZeroTimer(t *testing.T) { + if testing.Short() { + t.Skip("-short") + } + + for i := 0; i < 1000000; i++ { + s := Now() + ti := NewTimer(0) + <-ti.C + if diff := Since(s); diff > 2*Second { + t.Errorf("Expected time to get value from Timer channel in less than 2 sec, took %v", diff) + } + } +} + +// Test that rapidly moving a timer earlier doesn't cause it to get dropped. +// Issue 47329. +func TestTimerModifiedEarlier(t *testing.T) { + if runtime.GOOS == "plan9" && runtime.GOARCH == "arm" { + testenv.SkipFlaky(t, 50470) + } + + past := Until(Unix(0, 0)) + count := 1000 + fail := 0 + for i := 0; i < count; i++ { + timer := NewTimer(Hour) + for j := 0; j < 10; j++ { + if !timer.Stop() { + <-timer.C + } + timer.Reset(past) + } + + deadline := NewTimer(10 * Second) + defer deadline.Stop() + now := Now() + select { + case <-timer.C: + if since := Since(now); since > 8*Second { + t.Errorf("timer took too long (%v)", since) + fail++ + } + case <-deadline.C: + t.Error("deadline expired") + } + } + + if fail > 0 { + t.Errorf("%d failures", fail) + } +} + +// Test that rapidly moving timers earlier and later doesn't cause +// some of the sleep times to be lost. +// Issue 47762 +func TestAdjustTimers(t *testing.T) { + var rnd = rand.New(rand.NewSource(Now().UnixNano())) + + timers := make([]*Timer, 100) + states := make([]int, len(timers)) + indices := rnd.Perm(len(timers)) + + for len(indices) != 0 { + var ii = rnd.Intn(len(indices)) + var i = indices[ii] + + var timer = timers[i] + var state = states[i] + states[i]++ + + switch state { + case 0: + timers[i] = NewTimer(0) + case 1: + <-timer.C // Timer is now idle. + + // Reset to various long durations, which we'll cancel. + case 2: + if timer.Reset(1 * Minute) { + panic("shouldn't be active (1)") + } + case 4: + if timer.Reset(3 * Minute) { + panic("shouldn't be active (3)") + } + case 6: + if timer.Reset(2 * Minute) { + panic("shouldn't be active (2)") + } + + // Stop and drain a long-duration timer. + case 3, 5, 7: + if !timer.Stop() { + t.Logf("timer %d state %d Stop returned false", i, state) + <-timer.C + } + + // Start a short-duration timer we expect to select without blocking. + case 8: + if timer.Reset(0) { + t.Fatal("timer.Reset returned true") + } + case 9: + now := Now() + <-timer.C + dur := Since(now) + if dur > 750*Millisecond { + t.Errorf("timer %d took %v to complete", i, dur) + } + + // Timer is done. Swap with tail and remove. + case 10: + indices[ii] = indices[len(indices)-1] + indices = indices[:len(indices)-1] + } + } +} + +// Benchmark timer latency when the thread that creates the timer is busy with +// other work and the timers must be serviced by other threads. +// https://golang.org/issue/38860 +func BenchmarkParallelTimerLatency(b *testing.B) { + gmp := runtime.GOMAXPROCS(0) + if gmp < 2 || runtime.NumCPU() < gmp { + b.Skip("skipping with GOMAXPROCS < 2 or NumCPU < GOMAXPROCS") + } + + // allocate memory now to avoid GC interference later. + timerCount := gmp - 1 + stats := make([]struct { + sum float64 + max Duration + count int64 + _ [5]int64 // cache line padding + }, timerCount) + + // Ensure the time to start new threads to service timers will not pollute + // the results. + warmupScheduler(gmp) + + // Note that other than the AfterFunc calls this benchmark is measuring it + // avoids using any other timers. In particular, the main goroutine uses + // doWork to spin for some durations because up through Go 1.15 if all + // threads are idle sysmon could leave deep sleep when we wake. + + // Ensure sysmon is in deep sleep. + doWork(30 * Millisecond) + + b.ResetTimer() + + const delay = Millisecond + var wg sync.WaitGroup + var count int32 + for i := 0; i < b.N; i++ { + wg.Add(timerCount) + atomic.StoreInt32(&count, 0) + for j := 0; j < timerCount; j++ { + j := j + expectedWakeup := Now().Add(delay) + AfterFunc(delay, func() { + late := Since(expectedWakeup) + if late < 0 { + late = 0 + } + stats[j].count++ + stats[j].sum += float64(late.Nanoseconds()) + if late > stats[j].max { + stats[j].max = late + } + atomic.AddInt32(&count, 1) + for atomic.LoadInt32(&count) < int32(timerCount) { + // spin until all timers fired + } + wg.Done() + }) + } + + for atomic.LoadInt32(&count) < int32(timerCount) { + // spin until all timers fired + } + wg.Wait() + + // Spin for a bit to let the other scheduler threads go idle before the + // next round. + doWork(Millisecond) + } + var total float64 + var samples float64 + max := Duration(0) + for _, s := range stats { + if s.max > max { + max = s.max + } + total += s.sum + samples += float64(s.count) + } + b.ReportMetric(0, "ns/op") + b.ReportMetric(total/samples, "avg-late-ns") + b.ReportMetric(float64(max.Nanoseconds()), "max-late-ns") +} + +// Benchmark timer latency with staggered wakeup times and varying CPU bound +// workloads. https://golang.org/issue/38860 +func BenchmarkStaggeredTickerLatency(b *testing.B) { + gmp := runtime.GOMAXPROCS(0) + if gmp < 2 || runtime.NumCPU() < gmp { + b.Skip("skipping with GOMAXPROCS < 2 or NumCPU < GOMAXPROCS") + } + + const delay = 3 * Millisecond + + for _, dur := range []Duration{300 * Microsecond, 2 * Millisecond} { + b.Run(fmt.Sprintf("work-dur=%s", dur), func(b *testing.B) { + for tickersPerP := 1; tickersPerP < int(delay/dur)+1; tickersPerP++ { + tickerCount := gmp * tickersPerP + b.Run(fmt.Sprintf("tickers-per-P=%d", tickersPerP), func(b *testing.B) { + // allocate memory now to avoid GC interference later. + stats := make([]struct { + sum float64 + max Duration + count int64 + _ [5]int64 // cache line padding + }, tickerCount) + + // Ensure the time to start new threads to service timers + // will not pollute the results. + warmupScheduler(gmp) + + b.ResetTimer() + + var wg sync.WaitGroup + wg.Add(tickerCount) + for j := 0; j < tickerCount; j++ { + j := j + doWork(delay / Duration(gmp)) + expectedWakeup := Now().Add(delay) + ticker := NewTicker(delay) + go func(c int, ticker *Ticker, firstWake Time) { + defer ticker.Stop() + + for ; c > 0; c-- { + <-ticker.C + late := Since(expectedWakeup) + if late < 0 { + late = 0 + } + stats[j].count++ + stats[j].sum += float64(late.Nanoseconds()) + if late > stats[j].max { + stats[j].max = late + } + expectedWakeup = expectedWakeup.Add(delay) + doWork(dur) + } + wg.Done() + }(b.N, ticker, expectedWakeup) + } + wg.Wait() + + var total float64 + var samples float64 + max := Duration(0) + for _, s := range stats { + if s.max > max { + max = s.max + } + total += s.sum + samples += float64(s.count) + } + b.ReportMetric(0, "ns/op") + b.ReportMetric(total/samples, "avg-late-ns") + b.ReportMetric(float64(max.Nanoseconds()), "max-late-ns") + }) + } + }) + } +} + +// warmupScheduler ensures the scheduler has at least targetThreadCount threads +// in its thread pool. +func warmupScheduler(targetThreadCount int) { + var wg sync.WaitGroup + var count int32 + for i := 0; i < targetThreadCount; i++ { + wg.Add(1) + go func() { + atomic.AddInt32(&count, 1) + for atomic.LoadInt32(&count) < int32(targetThreadCount) { + // spin until all threads started + } + + // spin a bit more to ensure they are all running on separate CPUs. + doWork(Millisecond) + wg.Done() + }() + } + wg.Wait() +} + +func doWork(dur Duration) { + start := Now() + for Since(start) < dur { + } +} |