Source file src/time/sleep_test.go

     1  // Copyright 2009 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package time_test
     6  
     7  import (
     8  	"errors"
     9  	"fmt"
    10  	"internal/testenv"
    11  	"math/rand"
    12  	"runtime"
    13  	"slices"
    14  	"strings"
    15  	"sync"
    16  	"sync/atomic"
    17  	"testing"
    18  	. "time"
    19  	_ "unsafe" // for go:linkname
    20  )
    21  
    22  // newTimerFunc simulates NewTimer using AfterFunc,
    23  // but this version will not hit the special cases for channels
    24  // that are used when calling NewTimer.
    25  // This makes it easy to test both paths.
    26  func newTimerFunc(d Duration) *Timer {
    27  	c := make(chan Time, 1)
    28  	t := AfterFunc(d, func() { c <- Now() })
    29  	t.C = c
    30  	return t
    31  }
    32  
    33  // haveHighResSleep is true if the system supports at least ~1ms sleeps.
    34  //
    35  //go:linkname haveHighResSleep runtime.haveHighResSleep
    36  var haveHighResSleep bool
    37  
    38  // adjustDelay returns an adjusted delay based on the system sleep resolution.
    39  // Go runtime uses different Windows timers for time.Now and sleeping.
    40  // These can tick at different frequencies and can arrive out of sync.
    41  // The effect can be seen, for example, as time.Sleep(100ms) is actually
    42  // shorter then 100ms when measured as difference between time.Now before and
    43  // after time.Sleep call. This was observed on Windows XP SP3 (windows/386).
    44  func adjustDelay(t *testing.T, delay Duration) Duration {
    45  	if haveHighResSleep {
    46  		return delay
    47  	}
    48  	t.Log("adjusting delay for low resolution sleep")
    49  	switch runtime.GOOS {
    50  	case "windows":
    51  		return delay - 17*Millisecond
    52  	default:
    53  		t.Fatal("adjustDelay unimplemented on " + runtime.GOOS)
    54  		return 0
    55  	}
    56  }
    57  
    58  func TestSleep(t *testing.T) {
    59  	const delay = 100 * Millisecond
    60  	go func() {
    61  		Sleep(delay / 2)
    62  		Interrupt()
    63  	}()
    64  	start := Now()
    65  	Sleep(delay)
    66  	delayadj := adjustDelay(t, delay)
    67  	duration := Since(start)
    68  	if duration < delayadj {
    69  		t.Fatalf("Sleep(%s) slept for only %s", delay, duration)
    70  	}
    71  }
    72  
    73  // Test the basic function calling behavior. Correct queuing
    74  // behavior is tested elsewhere, since After and AfterFunc share
    75  // the same code.
    76  func TestAfterFunc(t *testing.T) {
    77  	i := 10
    78  	c := make(chan bool)
    79  	var f func()
    80  	f = func() {
    81  		i--
    82  		if i >= 0 {
    83  			AfterFunc(0, f)
    84  			Sleep(1 * Second)
    85  		} else {
    86  			c <- true
    87  		}
    88  	}
    89  
    90  	AfterFunc(0, f)
    91  	<-c
    92  }
    93  
    94  func TestTickerStress(t *testing.T) {
    95  	var stop atomic.Bool
    96  	go func() {
    97  		for !stop.Load() {
    98  			runtime.GC()
    99  			// Yield so that the OS can wake up the timer thread,
   100  			// so that it can generate channel sends for the main goroutine,
   101  			// which will eventually set stop = 1 for us.
   102  			Sleep(Nanosecond)
   103  		}
   104  	}()
   105  	ticker := NewTicker(1)
   106  	for i := 0; i < 100; i++ {
   107  		<-ticker.C
   108  	}
   109  	ticker.Stop()
   110  	stop.Store(true)
   111  }
   112  
   113  func TestTickerConcurrentStress(t *testing.T) {
   114  	var stop atomic.Bool
   115  	go func() {
   116  		for !stop.Load() {
   117  			runtime.GC()
   118  			// Yield so that the OS can wake up the timer thread,
   119  			// so that it can generate channel sends for the main goroutine,
   120  			// which will eventually set stop = 1 for us.
   121  			Sleep(Nanosecond)
   122  		}
   123  	}()
   124  	ticker := NewTicker(1)
   125  	var wg sync.WaitGroup
   126  	for i := 0; i < 10; i++ {
   127  		wg.Add(1)
   128  		go func() {
   129  			defer wg.Done()
   130  			for i := 0; i < 100; i++ {
   131  				<-ticker.C
   132  			}
   133  		}()
   134  	}
   135  	wg.Wait()
   136  	ticker.Stop()
   137  	stop.Store(true)
   138  }
   139  
   140  func TestAfterFuncStarvation(t *testing.T) {
   141  	// Start two goroutines ping-ponging on a channel send.
   142  	// At any given time, at least one of these goroutines is runnable:
   143  	// if the channel buffer is full, the receiver is runnable,
   144  	// and if it is not full, the sender is runnable.
   145  	//
   146  	// In addition, the AfterFunc callback should become runnable after
   147  	// the indicated delay.
   148  	//
   149  	// Even if GOMAXPROCS=1, we expect the runtime to eventually schedule
   150  	// the AfterFunc goroutine instead of the runnable channel goroutine.
   151  	// However, in https://go.dev/issue/65178 this was observed to live-lock
   152  	// on wasip1/wasm and js/wasm after <10000 runs.
   153  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
   154  
   155  	var (
   156  		wg   sync.WaitGroup
   157  		stop atomic.Bool
   158  		c    = make(chan bool, 1)
   159  	)
   160  
   161  	wg.Add(2)
   162  	go func() {
   163  		for !stop.Load() {
   164  			c <- true
   165  		}
   166  		close(c)
   167  		wg.Done()
   168  	}()
   169  	go func() {
   170  		for range c {
   171  		}
   172  		wg.Done()
   173  	}()
   174  
   175  	AfterFunc(1*Microsecond, func() { stop.Store(true) })
   176  	wg.Wait()
   177  }
   178  
   179  func benchmark(b *testing.B, bench func(*testing.PB)) {
   180  	// Create equal number of garbage timers on each P before starting
   181  	// the benchmark.
   182  	var wg sync.WaitGroup
   183  	garbageAll := make([][]*Timer, runtime.GOMAXPROCS(0))
   184  	for i := range garbageAll {
   185  		wg.Add(1)
   186  		go func(i int) {
   187  			defer wg.Done()
   188  			garbage := make([]*Timer, 1<<15)
   189  			for j := range garbage {
   190  				garbage[j] = AfterFunc(Hour, nil)
   191  			}
   192  			garbageAll[i] = garbage
   193  		}(i)
   194  	}
   195  	wg.Wait()
   196  
   197  	b.ResetTimer()
   198  	b.RunParallel(bench)
   199  	b.StopTimer()
   200  
   201  	for _, garbage := range garbageAll {
   202  		for _, t := range garbage {
   203  			t.Stop()
   204  		}
   205  	}
   206  }
   207  
   208  func BenchmarkAfterFunc1000(b *testing.B) {
   209  	benchmark(b, func(pb *testing.PB) {
   210  		for pb.Next() {
   211  			n := 1000
   212  			c := make(chan bool)
   213  			var f func()
   214  			f = func() {
   215  				n--
   216  				if n >= 0 {
   217  					AfterFunc(0, f)
   218  				} else {
   219  					c <- true
   220  				}
   221  			}
   222  			AfterFunc(0, f)
   223  			<-c
   224  		}
   225  	})
   226  }
   227  
   228  func BenchmarkAfter(b *testing.B) {
   229  	benchmark(b, func(pb *testing.PB) {
   230  		for pb.Next() {
   231  			<-After(1)
   232  		}
   233  	})
   234  }
   235  
   236  func BenchmarkStop(b *testing.B) {
   237  	b.Run("impl=chan", func(b *testing.B) {
   238  		benchmark(b, func(pb *testing.PB) {
   239  			for pb.Next() {
   240  				NewTimer(1 * Second).Stop()
   241  			}
   242  		})
   243  	})
   244  	b.Run("impl=func", func(b *testing.B) {
   245  		benchmark(b, func(pb *testing.PB) {
   246  			for pb.Next() {
   247  				newTimerFunc(1 * Second).Stop()
   248  			}
   249  		})
   250  	})
   251  }
   252  
   253  func BenchmarkSimultaneousAfterFunc1000(b *testing.B) {
   254  	benchmark(b, func(pb *testing.PB) {
   255  		for pb.Next() {
   256  			n := 1000
   257  			var wg sync.WaitGroup
   258  			wg.Add(n)
   259  			for range n {
   260  				AfterFunc(0, wg.Done)
   261  			}
   262  			wg.Wait()
   263  		}
   264  	})
   265  }
   266  
   267  func BenchmarkStartStop1000(b *testing.B) {
   268  	benchmark(b, func(pb *testing.PB) {
   269  		for pb.Next() {
   270  			const N = 1000
   271  			timers := make([]*Timer, N)
   272  			for i := range timers {
   273  				timers[i] = AfterFunc(Hour, nil)
   274  			}
   275  
   276  			for i := range timers {
   277  				timers[i].Stop()
   278  			}
   279  		}
   280  	})
   281  }
   282  
   283  func BenchmarkReset(b *testing.B) {
   284  	b.Run("impl=chan", func(b *testing.B) {
   285  		benchmark(b, func(pb *testing.PB) {
   286  			t := NewTimer(Hour)
   287  			for pb.Next() {
   288  				t.Reset(Hour)
   289  			}
   290  			t.Stop()
   291  		})
   292  	})
   293  	b.Run("impl=func", func(b *testing.B) {
   294  		benchmark(b, func(pb *testing.PB) {
   295  			t := newTimerFunc(Hour)
   296  			for pb.Next() {
   297  				t.Reset(Hour)
   298  			}
   299  			t.Stop()
   300  		})
   301  	})
   302  }
   303  
   304  func BenchmarkSleep1000(b *testing.B) {
   305  	benchmark(b, func(pb *testing.PB) {
   306  		for pb.Next() {
   307  			const N = 1000
   308  			var wg sync.WaitGroup
   309  			wg.Add(N)
   310  			for range N {
   311  				go func() {
   312  					Sleep(Nanosecond)
   313  					wg.Done()
   314  				}()
   315  			}
   316  			wg.Wait()
   317  		}
   318  	})
   319  }
   320  
   321  func TestAfter(t *testing.T) {
   322  	const delay = 100 * Millisecond
   323  	start := Now()
   324  	end := <-After(delay)
   325  	delayadj := adjustDelay(t, delay)
   326  	if duration := Since(start); duration < delayadj {
   327  		t.Fatalf("After(%s) slept for only %d ns", delay, duration)
   328  	}
   329  	if min := start.Add(delayadj); end.Before(min) {
   330  		t.Fatalf("After(%s) expect >= %s, got %s", delay, min, end)
   331  	}
   332  }
   333  
   334  func TestAfterTick(t *testing.T) {
   335  	t.Parallel()
   336  	const Count = 10
   337  	Delta := 100 * Millisecond
   338  	if testing.Short() {
   339  		Delta = 10 * Millisecond
   340  	}
   341  	t0 := Now()
   342  	for i := 0; i < Count; i++ {
   343  		<-After(Delta)
   344  	}
   345  	t1 := Now()
   346  	d := t1.Sub(t0)
   347  	target := Delta * Count
   348  	if d < target*9/10 {
   349  		t.Fatalf("%d ticks of %s too fast: took %s, expected %s", Count, Delta, d, target)
   350  	}
   351  	if !testing.Short() && d > target*30/10 {
   352  		t.Fatalf("%d ticks of %s too slow: took %s, expected %s", Count, Delta, d, target)
   353  	}
   354  }
   355  
   356  func TestAfterStop(t *testing.T) {
   357  	t.Run("impl=chan", func(t *testing.T) {
   358  		testAfterStop(t, NewTimer)
   359  	})
   360  	t.Run("impl=func", func(t *testing.T) {
   361  		testAfterStop(t, newTimerFunc)
   362  	})
   363  }
   364  
   365  func testAfterStop(t *testing.T, newTimer func(Duration) *Timer) {
   366  	// We want to test that we stop a timer before it runs.
   367  	// We also want to test that it didn't run after a longer timer.
   368  	// Since we don't want the test to run for too long, we don't
   369  	// want to use lengthy times. That makes the test inherently flaky.
   370  	// So only report an error if it fails five times in a row.
   371  
   372  	var errs []string
   373  	logErrs := func() {
   374  		for _, e := range errs {
   375  			t.Log(e)
   376  		}
   377  	}
   378  
   379  	for i := 0; i < 5; i++ {
   380  		AfterFunc(100*Millisecond, func() {})
   381  		t0 := newTimer(50 * Millisecond)
   382  		c1 := make(chan bool, 1)
   383  		t1 := AfterFunc(150*Millisecond, func() { c1 <- true })
   384  		c2 := After(200 * Millisecond)
   385  		if !t0.Stop() {
   386  			errs = append(errs, "failed to stop event 0")
   387  			continue
   388  		}
   389  		if !t1.Stop() {
   390  			errs = append(errs, "failed to stop event 1")
   391  			continue
   392  		}
   393  		<-c2
   394  		select {
   395  		case <-t0.C:
   396  			errs = append(errs, "event 0 was not stopped")
   397  			continue
   398  		case <-c1:
   399  			errs = append(errs, "event 1 was not stopped")
   400  			continue
   401  		default:
   402  		}
   403  		if t1.Stop() {
   404  			errs = append(errs, "Stop returned true twice")
   405  			continue
   406  		}
   407  
   408  		// Test passed, so all done.
   409  		if len(errs) > 0 {
   410  			t.Logf("saw %d errors, ignoring to avoid flakiness", len(errs))
   411  			logErrs()
   412  		}
   413  
   414  		return
   415  	}
   416  
   417  	t.Errorf("saw %d errors", len(errs))
   418  	logErrs()
   419  }
   420  
   421  // TestAfterQueuing checks that concurrent After calls are queued by deadline:
   422  // timers created in one order but with deadlines in another must fire in
   423  // deadline order, and each must fire near its deadline.
   424  func TestAfterQueuing(t *testing.T) {
   425  	t.Run("impl=chan", func(t *testing.T) {
   426  		testAfterQueuing(t, After)
   427  	})
   428  	t.Run("impl=func", func(t *testing.T) {
   429  		testAfterQueuing(t, func(d Duration) <-chan Time { return newTimerFunc(d).C })
   430  	})
   431  }
   432  
   433  func testAfterQueuing(t *testing.T, after func(Duration) <-chan Time) {
   434  	// The arrival time check below depends on the timers running roughly on
   435  	// schedule, which a loaded machine cannot promise, so try a few times with
   436  	// increasing deltas before declaring a failure. The ordering check does not
   437  	// depend on load and would not benefit from a retry.
   438  	const attempts = 5
   439  	err := errors.New("!=nil")
   440  	for i := 0; i < attempts && err != nil; i++ {
   441  		delta := Duration(20+i*50) * Millisecond
   442  		if err = testAfterQueuing1(delta, after); err != nil {
   443  			t.Logf("attempt %v failed: %v", i, err)
   444  		}
   445  	}
   446  	if err != nil {
   447  		t.Fatal(err)
   448  	}
   449  }
   450  
   451  var slots = []int{5, 3, 6, 6, 6, 1, 1, 2, 7, 9, 4, 8, 0}
   452  
   453  type afterResult struct {
   454  	slot int
   455  	t    Time
   456  }
   457  
   458  func await(slot int, result chan<- afterResult, ac <-chan Time) {
   459  	result <- afterResult{slot, <-ac}
   460  }
   461  
   462  func testAfterQueuing1(delta Duration, after func(Duration) <-chan Time) error {
   463  	// make the result channel buffered because we don't want
   464  	// to depend on channel queuing semantics that might
   465  	// possibly change in the future.
   466  	result := make(chan afterResult, len(slots))
   467  
   468  	t0 := Now()
   469  	for _, slot := range slots {
   470  		go await(slot, result, after(Duration(slot)*delta))
   471  	}
   472  	results := make([]afterResult, 0, len(slots))
   473  	for range slots {
   474  		results = append(results, <-result)
   475  	}
   476  
   477  	// Sort by the time each timer reported, which is the order the timers
   478  	// fired in. The order in which the goroutines started above manage to send
   479  	// on result is up to the scheduler, not the timers, so it says nothing
   480  	// about whether the timers were queued correctly.
   481  	slices.SortStableFunc(results, func(a, b afterResult) int {
   482  		return a.t.Compare(b.t)
   483  	})
   484  	for i := range results {
   485  		if i > 0 && results[i].slot < results[i-1].slot {
   486  			fired := make([]int, len(results))
   487  			for j, r := range results {
   488  				fired[j] = r.slot
   489  			}
   490  			return fmt.Errorf("After calls fired out of order: %v", fired)
   491  		}
   492  	}
   493  
   494  	for _, r := range results {
   495  		dt := r.t.Sub(t0)
   496  		target := Duration(r.slot) * delta
   497  		if dt < target-delta/2 || dt > target+delta*10 {
   498  			return fmt.Errorf("After(%s) arrived at %s, expected [%s,%s]", target, dt, target-delta/2, target+delta*10)
   499  		}
   500  	}
   501  	return nil
   502  }
   503  
   504  func TestTimerStopStress(t *testing.T) {
   505  	if testing.Short() {
   506  		return
   507  	}
   508  	t.Parallel()
   509  	for i := 0; i < 100; i++ {
   510  		go func(i int) {
   511  			timer := AfterFunc(2*Second, func() {
   512  				t.Errorf("timer %d was not stopped", i)
   513  			})
   514  			Sleep(1 * Second)
   515  			timer.Stop()
   516  		}(i)
   517  	}
   518  	Sleep(3 * Second)
   519  }
   520  
   521  func TestSleepZeroDeadlock(t *testing.T) {
   522  	// Sleep(0) used to hang, the sequence of events was as follows.
   523  	// Sleep(0) sets G's status to Gwaiting, but then immediately returns leaving the status.
   524  	// Then the goroutine calls e.g. new and falls down into the scheduler due to pending GC.
   525  	// After the GC nobody wakes up the goroutine from Gwaiting status.
   526  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(4))
   527  	c := make(chan bool)
   528  	go func() {
   529  		for i := 0; i < 100; i++ {
   530  			runtime.GC()
   531  		}
   532  		c <- true
   533  	}()
   534  	for i := 0; i < 100; i++ {
   535  		Sleep(0)
   536  		tmp := make(chan bool, 1)
   537  		tmp <- true
   538  		<-tmp
   539  	}
   540  	<-c
   541  }
   542  
   543  func testReset(d Duration) error {
   544  	t0 := NewTimer(2 * d)
   545  	Sleep(d)
   546  	if !t0.Reset(3 * d) {
   547  		return errors.New("resetting unfired timer returned false")
   548  	}
   549  	Sleep(2 * d)
   550  	select {
   551  	case <-t0.C:
   552  		return errors.New("timer fired early")
   553  	default:
   554  	}
   555  	Sleep(2 * d)
   556  	select {
   557  	case <-t0.C:
   558  	default:
   559  		return errors.New("reset timer did not fire")
   560  	}
   561  
   562  	if t0.Reset(50 * Millisecond) {
   563  		return errors.New("resetting expired timer returned true")
   564  	}
   565  	return nil
   566  }
   567  
   568  func TestReset(t *testing.T) {
   569  	// We try to run this test with increasingly larger multiples
   570  	// until one works so slow, loaded hardware isn't as flaky,
   571  	// but without slowing down fast machines unnecessarily.
   572  	//
   573  	// (maxDuration is several orders of magnitude longer than we
   574  	// expect this test to actually take on a fast, unloaded machine.)
   575  	d := 1 * Millisecond
   576  	const maxDuration = 10 * Second
   577  	for {
   578  		err := testReset(d)
   579  		if err == nil {
   580  			break
   581  		}
   582  		d *= 2
   583  		if d > maxDuration {
   584  			t.Error(err)
   585  		}
   586  		t.Logf("%v; trying duration %v", err, d)
   587  	}
   588  }
   589  
   590  // Test that sleeping (via Sleep or Timer) for an interval so large it
   591  // overflows does not result in a short sleep duration. Nor does it interfere
   592  // with execution of other timers. If it does, timers in this or subsequent
   593  // tests may not fire.
   594  func TestOverflowSleep(t *testing.T) {
   595  	const big = Duration(int64(1<<63 - 1))
   596  
   597  	go func() {
   598  		Sleep(big)
   599  		// On failure, this may return after the test has completed, so
   600  		// we need to panic instead.
   601  		panic("big sleep returned")
   602  	}()
   603  
   604  	select {
   605  	case <-After(big):
   606  		t.Fatalf("big timeout fired")
   607  	case <-After(25 * Millisecond):
   608  		// OK
   609  	}
   610  
   611  	const neg = Duration(-1 << 63)
   612  	Sleep(neg) // Returns immediately.
   613  	select {
   614  	case <-After(neg):
   615  		// OK
   616  	case <-After(1 * Second):
   617  		t.Fatalf("negative timeout didn't fire")
   618  	}
   619  }
   620  
   621  // Test that a panic while deleting a timer does not leave
   622  // the timers mutex held, deadlocking a ticker.Stop in a defer.
   623  func TestIssue5745(t *testing.T) {
   624  	ticker := NewTicker(Hour)
   625  	defer func() {
   626  		// would deadlock here before the fix due to
   627  		// lock taken before the segfault.
   628  		ticker.Stop()
   629  
   630  		if r := recover(); r == nil {
   631  			t.Error("Expected panic, but none happened.")
   632  		}
   633  	}()
   634  
   635  	// cause a panic due to a segfault
   636  	var timer *Timer
   637  	timer.Stop()
   638  	t.Error("Should be unreachable.")
   639  }
   640  
   641  func TestOverflowPeriodRuntimeTimer(t *testing.T) {
   642  	// This may hang forever if timers are broken. See comment near
   643  	// the end of CheckRuntimeTimerOverflow in internal_test.go.
   644  	CheckRuntimeTimerPeriodOverflow()
   645  }
   646  
   647  func checkZeroTimerPanicString(t *testing.T) {
   648  	e := recover()
   649  	s, _ := e.(string)
   650  	if want := "called on uninitialized Timer"; !strings.Contains(s, want) {
   651  		t.Errorf("panic = %v; want substring %q", e, want)
   652  	}
   653  }
   654  
   655  func TestZeroTimerResetPanics(t *testing.T) {
   656  	defer checkZeroTimerPanicString(t)
   657  	var tr Timer
   658  	tr.Reset(1)
   659  }
   660  
   661  func TestZeroTimerStopPanics(t *testing.T) {
   662  	defer checkZeroTimerPanicString(t)
   663  	var tr Timer
   664  	tr.Stop()
   665  }
   666  
   667  func checkCopiedTimerPanicString(t *testing.T) {
   668  	e := recover()
   669  	s, _ := e.(string)
   670  	if want := "called on copied Timer"; !strings.Contains(s, want) {
   671  		t.Errorf("panic = %v; want substring %q", e, want)
   672  	}
   673  }
   674  
   675  func TestCopiedTimerResetPanics(t *testing.T) {
   676  	defer checkCopiedTimerPanicString(t)
   677  	var tr Timer
   678  	tr = *NewTimer(0)
   679  	tr.Reset(1)
   680  }
   681  
   682  func TestCopiedTimerStopPanics(t *testing.T) {
   683  	defer checkCopiedTimerPanicString(t)
   684  	var tr Timer
   685  	tr = *NewTimer(0)
   686  	tr.Stop()
   687  }
   688  
   689  // Test that zero duration timers aren't missed by the scheduler. Regression test for issue 44868.
   690  func TestZeroTimer(t *testing.T) {
   691  	t.Run("impl=chan", func(t *testing.T) {
   692  		testZeroTimer(t, NewTimer)
   693  	})
   694  	t.Run("impl=func", func(t *testing.T) {
   695  		testZeroTimer(t, newTimerFunc)
   696  	})
   697  	t.Run("impl=cache", func(t *testing.T) {
   698  		timer := newTimerFunc(Hour)
   699  		testZeroTimer(t, func(d Duration) *Timer {
   700  			timer.Reset(d)
   701  			return timer
   702  		})
   703  	})
   704  }
   705  
   706  func testZeroTimer(t *testing.T, newTimer func(Duration) *Timer) {
   707  	if testing.Short() {
   708  		t.Skip("-short")
   709  	}
   710  
   711  	for i := 0; i < 1000000; i++ {
   712  		s := Now()
   713  		ti := newTimer(0)
   714  		<-ti.C
   715  		if diff := Since(s); diff > 2*Second {
   716  			t.Errorf("Expected time to get value from Timer channel in less than 2 sec, took %v", diff)
   717  		}
   718  	}
   719  }
   720  
   721  // Test that rapidly moving a timer earlier doesn't cause it to get dropped.
   722  // Issue 47329.
   723  func TestTimerModifiedEarlier(t *testing.T) {
   724  	if runtime.GOOS == "plan9" && runtime.GOARCH == "arm" {
   725  		testenv.SkipFlaky(t, 50470)
   726  	}
   727  
   728  	past := Until(Unix(0, 0))
   729  	count := 1000
   730  	fail := 0
   731  	for i := 0; i < count; i++ {
   732  		timer := newTimerFunc(Hour)
   733  		for j := 0; j < 10; j++ {
   734  			if !timer.Stop() {
   735  				<-timer.C
   736  			}
   737  			timer.Reset(past)
   738  		}
   739  
   740  		deadline := NewTimer(10 * Second)
   741  		defer deadline.Stop()
   742  		now := Now()
   743  		select {
   744  		case <-timer.C:
   745  			if since := Since(now); since > 8*Second {
   746  				t.Errorf("timer took too long (%v)", since)
   747  				fail++
   748  			}
   749  		case <-deadline.C:
   750  			t.Error("deadline expired")
   751  		}
   752  	}
   753  
   754  	if fail > 0 {
   755  		t.Errorf("%d failures", fail)
   756  	}
   757  }
   758  
   759  // Test that rapidly moving timers earlier and later doesn't cause
   760  // some of the sleep times to be lost.
   761  // Issue 47762
   762  func TestAdjustTimers(t *testing.T) {
   763  	var rnd = rand.New(rand.NewSource(Now().UnixNano()))
   764  
   765  	timers := make([]*Timer, 100)
   766  	states := make([]int, len(timers))
   767  	indices := rnd.Perm(len(timers))
   768  
   769  	for len(indices) != 0 {
   770  		var ii = rnd.Intn(len(indices))
   771  		var i = indices[ii]
   772  
   773  		var timer = timers[i]
   774  		var state = states[i]
   775  		states[i]++
   776  
   777  		switch state {
   778  		case 0:
   779  			timers[i] = newTimerFunc(0)
   780  
   781  		case 1:
   782  			<-timer.C // Timer is now idle.
   783  
   784  		// Reset to various long durations, which we'll cancel.
   785  		case 2:
   786  			if timer.Reset(1 * Minute) {
   787  				panic("shouldn't be active (1)")
   788  			}
   789  		case 4:
   790  			if timer.Reset(3 * Minute) {
   791  				panic("shouldn't be active (3)")
   792  			}
   793  		case 6:
   794  			if timer.Reset(2 * Minute) {
   795  				panic("shouldn't be active (2)")
   796  			}
   797  
   798  		// Stop and drain a long-duration timer.
   799  		case 3, 5, 7:
   800  			if !timer.Stop() {
   801  				t.Logf("timer %d state %d Stop returned false", i, state)
   802  				<-timer.C
   803  			}
   804  
   805  		// Start a short-duration timer we expect to select without blocking.
   806  		case 8:
   807  			if timer.Reset(0) {
   808  				t.Fatal("timer.Reset returned true")
   809  			}
   810  		case 9:
   811  			now := Now()
   812  			<-timer.C
   813  			dur := Since(now)
   814  			if dur > 750*Millisecond {
   815  				t.Errorf("timer %d took %v to complete", i, dur)
   816  			}
   817  
   818  		// Timer is done. Swap with tail and remove.
   819  		case 10:
   820  			indices[ii] = indices[len(indices)-1]
   821  			indices = indices[:len(indices)-1]
   822  		}
   823  	}
   824  }
   825  
   826  func TestStopResult(t *testing.T) {
   827  	testStopResetResult(t, true)
   828  }
   829  
   830  func TestResetResult(t *testing.T) {
   831  	testStopResetResult(t, false)
   832  }
   833  
   834  // Test that when racing between running a timer and stopping a timer Stop
   835  // consistently indicates whether a value can be read from the channel.
   836  // Issue #69312.
   837  func testStopResetResult(t *testing.T, testStop bool) {
   838  	stopOrReset := func(timer *Timer) bool {
   839  		if testStop {
   840  			return timer.Stop()
   841  		} else {
   842  			return timer.Reset(1 * Hour)
   843  		}
   844  	}
   845  
   846  	start := make(chan struct{})
   847  	var wg sync.WaitGroup
   848  	const N = 1000
   849  	wg.Add(N)
   850  	for range N {
   851  		go func() {
   852  			defer wg.Done()
   853  			<-start
   854  			for j := 0; j < 100; j++ {
   855  				timer1 := NewTimer(1 * Millisecond)
   856  				timer2 := NewTimer(1 * Millisecond)
   857  				select {
   858  				case <-timer1.C:
   859  					if !stopOrReset(timer2) {
   860  						// The test fails if this
   861  						// channel read times out.
   862  						<-timer2.C
   863  					}
   864  				case <-timer2.C:
   865  					if !stopOrReset(timer1) {
   866  						// The test fails if this
   867  						// channel read times out.
   868  						<-timer1.C
   869  					}
   870  				}
   871  			}
   872  		}()
   873  	}
   874  	close(start)
   875  	wg.Wait()
   876  }
   877  
   878  // Test having a large number of goroutines wake up a ticker simultaneously.
   879  // This used to trigger a crash when run under x/tools/cmd/stress.
   880  func TestMultiWakeupTicker(t *testing.T) {
   881  	if testing.Short() {
   882  		t.Skip("-short")
   883  	}
   884  
   885  	goroutines := runtime.GOMAXPROCS(0)
   886  	timer := NewTicker(Microsecond)
   887  	var wg sync.WaitGroup
   888  	wg.Add(goroutines)
   889  	for range goroutines {
   890  		go func() {
   891  			defer wg.Done()
   892  			for range 100000 {
   893  				select {
   894  				case <-timer.C:
   895  				case <-After(Millisecond):
   896  				}
   897  			}
   898  		}()
   899  	}
   900  	wg.Wait()
   901  }
   902  
   903  // Test having a large number of goroutines wake up a timer simultaneously.
   904  // This used to trigger a crash when run under x/tools/cmd/stress.
   905  func TestMultiWakeupTimer(t *testing.T) {
   906  	if testing.Short() {
   907  		t.Skip("-short")
   908  	}
   909  
   910  	goroutines := runtime.GOMAXPROCS(0)
   911  	timer := NewTimer(Nanosecond)
   912  	var wg sync.WaitGroup
   913  	wg.Add(goroutines)
   914  	for range goroutines {
   915  		go func() {
   916  			defer wg.Done()
   917  			for range 10000 {
   918  				select {
   919  				case <-timer.C:
   920  				default:
   921  				}
   922  				timer.Reset(Nanosecond)
   923  			}
   924  		}()
   925  	}
   926  	wg.Wait()
   927  }
   928  
   929  // Benchmark timer latency when the thread that creates the timer is busy with
   930  // other work and the timers must be serviced by other threads.
   931  // https://golang.org/issue/38860
   932  func BenchmarkParallelTimerLatency(b *testing.B) {
   933  	gmp := runtime.GOMAXPROCS(0)
   934  	if gmp < 2 || runtime.NumCPU() < gmp {
   935  		b.Skip("skipping with GOMAXPROCS < 2 or NumCPU < GOMAXPROCS")
   936  	}
   937  
   938  	// allocate memory now to avoid GC interference later.
   939  	timerCount := gmp - 1
   940  	stats := make([]struct {
   941  		sum   float64
   942  		max   Duration
   943  		count int64
   944  		_     [5]int64 // cache line padding
   945  	}, timerCount)
   946  
   947  	// Ensure the time to start new threads to service timers will not pollute
   948  	// the results.
   949  	warmupScheduler(gmp)
   950  
   951  	// Note that other than the AfterFunc calls this benchmark is measuring it
   952  	// avoids using any other timers. In particular, the main goroutine uses
   953  	// doWork to spin for some durations because up through Go 1.15 if all
   954  	// threads are idle sysmon could leave deep sleep when we wake.
   955  
   956  	// Ensure sysmon is in deep sleep.
   957  	doWork(30 * Millisecond)
   958  
   959  	b.ResetTimer()
   960  
   961  	const delay = Millisecond
   962  	var wg sync.WaitGroup
   963  	var count int32
   964  	for i := 0; i < b.N; i++ {
   965  		wg.Add(timerCount)
   966  		atomic.StoreInt32(&count, 0)
   967  		for j := 0; j < timerCount; j++ {
   968  			expectedWakeup := Now().Add(delay)
   969  			AfterFunc(delay, func() {
   970  				late := Since(expectedWakeup)
   971  				if late < 0 {
   972  					late = 0
   973  				}
   974  				stats[j].count++
   975  				stats[j].sum += float64(late.Nanoseconds())
   976  				if late > stats[j].max {
   977  					stats[j].max = late
   978  				}
   979  				atomic.AddInt32(&count, 1)
   980  				for atomic.LoadInt32(&count) < int32(timerCount) {
   981  					// spin until all timers fired
   982  				}
   983  				wg.Done()
   984  			})
   985  		}
   986  
   987  		for atomic.LoadInt32(&count) < int32(timerCount) {
   988  			// spin until all timers fired
   989  		}
   990  		wg.Wait()
   991  
   992  		// Spin for a bit to let the other scheduler threads go idle before the
   993  		// next round.
   994  		doWork(Millisecond)
   995  	}
   996  	var total float64
   997  	var samples float64
   998  	maximum := Duration(0)
   999  	for _, s := range stats {
  1000  		maximum = max(maximum, s.max)
  1001  		total += s.sum
  1002  		samples += float64(s.count)
  1003  	}
  1004  	b.ReportMetric(0, "ns/op")
  1005  	b.ReportMetric(total/samples, "avg-late-ns")
  1006  	b.ReportMetric(float64(maximum.Nanoseconds()), "max-late-ns")
  1007  }
  1008  
  1009  // Benchmark timer latency with staggered wakeup times and varying CPU bound
  1010  // workloads. https://golang.org/issue/38860
  1011  func BenchmarkStaggeredTickerLatency(b *testing.B) {
  1012  	gmp := runtime.GOMAXPROCS(0)
  1013  	if gmp < 2 || runtime.NumCPU() < gmp {
  1014  		b.Skip("skipping with GOMAXPROCS < 2 or NumCPU < GOMAXPROCS")
  1015  	}
  1016  
  1017  	const delay = 3 * Millisecond
  1018  
  1019  	for _, dur := range []Duration{300 * Microsecond, 2 * Millisecond} {
  1020  		b.Run(fmt.Sprintf("work-dur=%s", dur), func(b *testing.B) {
  1021  			for tickersPerP := 1; tickersPerP < int(delay/dur)+1; tickersPerP++ {
  1022  				tickerCount := gmp * tickersPerP
  1023  				b.Run(fmt.Sprintf("tickers-per-P=%d", tickersPerP), func(b *testing.B) {
  1024  					// allocate memory now to avoid GC interference later.
  1025  					stats := make([]struct {
  1026  						sum   float64
  1027  						max   Duration
  1028  						count int64
  1029  						_     [5]int64 // cache line padding
  1030  					}, tickerCount)
  1031  
  1032  					// Ensure the time to start new threads to service timers
  1033  					// will not pollute the results.
  1034  					warmupScheduler(gmp)
  1035  
  1036  					b.ResetTimer()
  1037  
  1038  					var wg sync.WaitGroup
  1039  					wg.Add(tickerCount)
  1040  					for j := 0; j < tickerCount; j++ {
  1041  						doWork(delay / Duration(gmp))
  1042  						expectedWakeup := Now().Add(delay)
  1043  						ticker := NewTicker(delay)
  1044  						go func(c int, ticker *Ticker, firstWake Time) {
  1045  							defer ticker.Stop()
  1046  
  1047  							for ; c > 0; c-- {
  1048  								<-ticker.C
  1049  								late := Since(expectedWakeup)
  1050  								if late < 0 {
  1051  									late = 0
  1052  								}
  1053  								stats[j].count++
  1054  								stats[j].sum += float64(late.Nanoseconds())
  1055  								if late > stats[j].max {
  1056  									stats[j].max = late
  1057  								}
  1058  								expectedWakeup = expectedWakeup.Add(delay)
  1059  								doWork(dur)
  1060  							}
  1061  							wg.Done()
  1062  						}(b.N, ticker, expectedWakeup)
  1063  					}
  1064  					wg.Wait()
  1065  
  1066  					var total float64
  1067  					var samples float64
  1068  					max := Duration(0)
  1069  					for _, s := range stats {
  1070  						if s.max > max {
  1071  							max = s.max
  1072  						}
  1073  						total += s.sum
  1074  						samples += float64(s.count)
  1075  					}
  1076  					b.ReportMetric(0, "ns/op")
  1077  					b.ReportMetric(total/samples, "avg-late-ns")
  1078  					b.ReportMetric(float64(max.Nanoseconds()), "max-late-ns")
  1079  				})
  1080  			}
  1081  		})
  1082  	}
  1083  }
  1084  
  1085  // warmupScheduler ensures the scheduler has at least targetThreadCount threads
  1086  // in its thread pool.
  1087  func warmupScheduler(targetThreadCount int) {
  1088  	var wg sync.WaitGroup
  1089  	var count int32
  1090  	for i := 0; i < targetThreadCount; i++ {
  1091  		wg.Add(1)
  1092  		go func() {
  1093  			atomic.AddInt32(&count, 1)
  1094  			for atomic.LoadInt32(&count) < int32(targetThreadCount) {
  1095  				// spin until all threads started
  1096  			}
  1097  
  1098  			// spin a bit more to ensure they are all running on separate CPUs.
  1099  			doWork(Millisecond)
  1100  			wg.Done()
  1101  		}()
  1102  	}
  1103  	wg.Wait()
  1104  }
  1105  
  1106  func doWork(dur Duration) {
  1107  	start := Now()
  1108  	for Since(start) < dur {
  1109  	}
  1110  }
  1111  
  1112  func BenchmarkAdjustTimers10000(b *testing.B) {
  1113  	benchmark(b, func(pb *testing.PB) {
  1114  		for pb.Next() {
  1115  			const n = 10000
  1116  			timers := make([]*Timer, 0, n)
  1117  			for range n {
  1118  				t := AfterFunc(Hour, func() {})
  1119  				timers = append(timers, t)
  1120  			}
  1121  			timers[n-1].Reset(Nanosecond)
  1122  			Sleep(Microsecond)
  1123  			for _, t := range timers {
  1124  				t.Stop()
  1125  			}
  1126  		}
  1127  	})
  1128  }
  1129  

View as plain text