Source file src/time/tick_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  	"fmt"
     9  	"runtime"
    10  	"sync"
    11  	"testing"
    12  	. "time"
    13  )
    14  
    15  func TestTicker(t *testing.T) {
    16  	t.Parallel()
    17  
    18  	// We want to test that a ticker takes as much time as expected.
    19  	// Since we don't want the test to run for too long, we don't
    20  	// want to use lengthy times. This makes the test inherently flaky.
    21  	// Start with a short time, but try again with a long one if the
    22  	// first test fails.
    23  
    24  	baseCount := 10
    25  	baseDelta := 20 * Millisecond
    26  
    27  	// On Darwin ARM64 the tick frequency seems limited. Issue 35692.
    28  	if (runtime.GOOS == "darwin" || runtime.GOOS == "ios") && runtime.GOARCH == "arm64" {
    29  		// The following test will run ticker count/2 times then reset
    30  		// the ticker to double the duration for the rest of count/2.
    31  		// Since tick frequency is limited on Darwin ARM64, use even
    32  		// number to give the ticks more time to let the test pass.
    33  		// See CL 220638.
    34  		baseCount = 6
    35  		baseDelta = 100 * Millisecond
    36  	}
    37  
    38  	var errs []string
    39  	logErrs := func() {
    40  		for _, e := range errs {
    41  			t.Log(e)
    42  		}
    43  	}
    44  
    45  	for _, test := range []struct {
    46  		count int
    47  		delta Duration
    48  	}{{
    49  		count: baseCount,
    50  		delta: baseDelta,
    51  	}, {
    52  		count: 8,
    53  		delta: 1 * Second,
    54  	}} {
    55  		count, delta := test.count, test.delta
    56  		ticker := NewTicker(delta)
    57  		t0 := Now()
    58  		for range count / 2 {
    59  			<-ticker.C
    60  		}
    61  		ticker.Reset(delta * 2)
    62  		for range count - count/2 {
    63  			<-ticker.C
    64  		}
    65  		ticker.Stop()
    66  		t1 := Now()
    67  		dt := t1.Sub(t0)
    68  		target := 3 * delta * Duration(count/2)
    69  		slop := target * 3 / 10
    70  		if dt < target-slop || dt > target+slop {
    71  			errs = append(errs, fmt.Sprintf("%d %s ticks then %d %s ticks took %s, expected [%s,%s]", count/2, delta, count/2, delta*2, dt, target-slop, target+slop))
    72  			if dt > target+slop {
    73  				// System may be overloaded; sleep a bit
    74  				// in the hopes it will recover.
    75  				Sleep(Second / 2)
    76  			}
    77  			continue
    78  		}
    79  		// Now test that the ticker stopped.
    80  		Sleep(2 * delta)
    81  		select {
    82  		case <-ticker.C:
    83  			errs = append(errs, "Ticker did not shut down")
    84  			continue
    85  		default:
    86  			// ok
    87  		}
    88  
    89  		// Test passed, so all done.
    90  		if len(errs) > 0 {
    91  			t.Logf("saw %d errors, ignoring to avoid flakiness", len(errs))
    92  			logErrs()
    93  		}
    94  
    95  		return
    96  	}
    97  
    98  	t.Errorf("saw %d errors", len(errs))
    99  	logErrs()
   100  }
   101  
   102  // Issue 21874
   103  func TestTickerStopWithDirectInitialization(t *testing.T) {
   104  	c := make(chan Time)
   105  	tk := &Ticker{C: c}
   106  	tk.Stop()
   107  }
   108  
   109  // Test that a bug tearing down a ticker has been fixed. This routine should not deadlock.
   110  func TestTeardown(t *testing.T) {
   111  	t.Parallel()
   112  
   113  	Delta := 100 * Millisecond
   114  	if testing.Short() {
   115  		Delta = 20 * Millisecond
   116  	}
   117  	for range 3 {
   118  		ticker := NewTicker(Delta)
   119  		<-ticker.C
   120  		ticker.Stop()
   121  	}
   122  }
   123  
   124  // Test the Tick convenience wrapper.
   125  func TestTick(t *testing.T) {
   126  	// Test that giving a negative duration returns nil.
   127  	if got := Tick(-1); got != nil {
   128  		t.Errorf("Tick(-1) = %v; want nil", got)
   129  	}
   130  }
   131  
   132  // Test that NewTicker panics when given a duration less than zero.
   133  func TestNewTickerLtZeroDuration(t *testing.T) {
   134  	defer func() {
   135  		if err := recover(); err == nil {
   136  			t.Errorf("NewTicker(-1) should have panicked")
   137  		}
   138  	}()
   139  	NewTicker(-1)
   140  }
   141  
   142  // Test that Ticker.Reset panics when given a duration less than zero.
   143  func TestTickerResetLtZeroDuration(t *testing.T) {
   144  	defer func() {
   145  		if err := recover(); err == nil {
   146  			t.Errorf("Ticker.Reset(0) should have panicked")
   147  		}
   148  	}()
   149  	tk := NewTicker(Second)
   150  	tk.Reset(0)
   151  }
   152  
   153  func TestLongAdjustTimers(t *testing.T) {
   154  	if runtime.GOOS == "android" || runtime.GOOS == "ios" || runtime.GOOS == "plan9" {
   155  		t.Skipf("skipping on %s - too slow", runtime.GOOS)
   156  	}
   157  	if testing.Short() && runtime.NumCPU() < 2 {
   158  		t.Skipf("skipping in short mode, insufficient CPUs")
   159  	}
   160  
   161  	t.Parallel()
   162  	var wg sync.WaitGroup
   163  	defer wg.Wait()
   164  
   165  	// Build up the timer heap.
   166  	const count = 5000
   167  	wg.Add(count)
   168  	for range count {
   169  		go func() {
   170  			defer wg.Done()
   171  			Sleep(10 * Microsecond)
   172  		}()
   173  	}
   174  	for range count {
   175  		Sleep(1 * Microsecond)
   176  	}
   177  
   178  	// Give ourselves 60 seconds to complete.
   179  	// This used to reliably fail on a Mac M3 laptop,
   180  	// which needed 77 seconds.
   181  	// Trybots are slower, so it will fail even more reliably there.
   182  	// With the fix, the code runs in under a second.
   183  	done := make(chan bool)
   184  	AfterFunc(60*Second, func() { close(done) })
   185  
   186  	// Set up a queuing goroutine to ping pong through the scheduler.
   187  	inQ := make(chan func())
   188  	outQ := make(chan func())
   189  
   190  	defer close(inQ)
   191  
   192  	wg.Add(1)
   193  	go func() {
   194  		defer wg.Done()
   195  		defer close(outQ)
   196  		var q []func()
   197  		for {
   198  			var sendTo chan func()
   199  			var send func()
   200  			if len(q) > 0 {
   201  				sendTo = outQ
   202  				send = q[0]
   203  			}
   204  			select {
   205  			case sendTo <- send:
   206  				q = q[1:]
   207  			case f, ok := <-inQ:
   208  				if !ok {
   209  					return
   210  				}
   211  				q = append(q, f)
   212  			case <-done:
   213  				return
   214  			}
   215  		}
   216  	}()
   217  
   218  	for i := range 50000 {
   219  		const try = 20
   220  		for range try {
   221  			inQ <- func() {}
   222  		}
   223  		for range try {
   224  			select {
   225  			case _, ok := <-outQ:
   226  				if !ok {
   227  					t.Fatal("output channel is closed")
   228  				}
   229  			case <-After(5 * Second):
   230  				t.Fatalf("failed to read work, iteration %d", i)
   231  			case <-done:
   232  				t.Fatal("timer expired")
   233  			}
   234  		}
   235  	}
   236  }
   237  func BenchmarkTicker(b *testing.B) {
   238  	benchmark(b, func(pb *testing.PB) {
   239  		ticker := NewTicker(Nanosecond)
   240  		for pb.Next() {
   241  			<-ticker.C
   242  		}
   243  		ticker.Stop()
   244  	})
   245  }
   246  
   247  func BenchmarkTickerReset(b *testing.B) {
   248  	benchmark(b, func(pb *testing.PB) {
   249  		ticker := NewTicker(Nanosecond)
   250  		for pb.Next() {
   251  			ticker.Reset(Nanosecond * 2)
   252  		}
   253  		ticker.Stop()
   254  	})
   255  }
   256  
   257  func BenchmarkTickerResetNaive(b *testing.B) {
   258  	benchmark(b, func(pb *testing.PB) {
   259  		ticker := NewTicker(Nanosecond)
   260  		for pb.Next() {
   261  			ticker.Stop()
   262  			ticker = NewTicker(Nanosecond * 2)
   263  		}
   264  		ticker.Stop()
   265  	})
   266  }
   267  
   268  func TestTimerGC(t *testing.T) {
   269  	if AsynctimerChan.Value() == "1" {
   270  		t.Skip("skipping TestTimerGC with asynctimerchan=1")
   271  	}
   272  
   273  	run := func(t *testing.T, what string, f func()) {
   274  		t.Helper()
   275  		t.Run(what, func(t *testing.T) {
   276  			t.Helper()
   277  			const N = 1e4
   278  			var stats runtime.MemStats
   279  			runtime.GC()
   280  			runtime.GC()
   281  			runtime.GC()
   282  			runtime.ReadMemStats(&stats)
   283  			before := int64(stats.Mallocs - stats.Frees)
   284  
   285  			for j := 0; j < N; j++ {
   286  				f()
   287  			}
   288  
   289  			runtime.GC()
   290  			runtime.GC()
   291  			runtime.GC()
   292  			runtime.ReadMemStats(&stats)
   293  			after := int64(stats.Mallocs - stats.Frees)
   294  
   295  			// Allow some slack, but inuse >= N means at least 1 allocation per iteration.
   296  			inuse := after - before
   297  			if inuse >= N {
   298  				t.Errorf("%s did not get GC'ed: %d allocations", what, inuse)
   299  
   300  				Sleep(1 * Second)
   301  				runtime.ReadMemStats(&stats)
   302  				after := int64(stats.Mallocs - stats.Frees)
   303  				inuse = after - before
   304  				t.Errorf("after a sleep: %d allocations", inuse)
   305  			}
   306  		})
   307  	}
   308  
   309  	run(t, "After", func() { After(Hour) })
   310  	run(t, "Tick", func() { Tick(Hour) })
   311  	run(t, "NewTimer", func() { NewTimer(Hour) })
   312  	run(t, "NewTicker", func() { NewTicker(Hour) })
   313  	run(t, "NewTimerStop", func() { NewTimer(Hour).Stop() })
   314  	run(t, "NewTickerStop", func() { NewTicker(Hour).Stop() })
   315  }
   316  
   317  func TestChan(t *testing.T) {
   318  	for _, name := range []string{"0", "1", "2"} {
   319  		t.Run("asynctimerchan="+name, func(t *testing.T) {
   320  			t.Setenv("GODEBUG", "asynctimerchan="+name)
   321  			t.Run("Timer", func(t *testing.T) {
   322  				tim := NewTimer(10000 * Second)
   323  				testTimerChan(t, tim, tim.C, name == "0")
   324  			})
   325  			t.Run("Ticker", func(t *testing.T) {
   326  				tim := &tickerTimer{Ticker: NewTicker(10000 * Second)}
   327  				testTimerChan(t, tim, tim.C, name == "0")
   328  			})
   329  		})
   330  	}
   331  }
   332  
   333  type timer interface {
   334  	Stop() bool
   335  	Reset(Duration) bool
   336  }
   337  
   338  // tickerTimer is a Timer with Reset and Stop methods that return bools,
   339  // to have the same signatures as Timer.
   340  type tickerTimer struct {
   341  	*Ticker
   342  	stopped bool
   343  }
   344  
   345  func (t *tickerTimer) Stop() bool {
   346  	pending := !t.stopped
   347  	t.stopped = true
   348  	t.Ticker.Stop()
   349  	return pending
   350  }
   351  
   352  func (t *tickerTimer) Reset(d Duration) bool {
   353  	pending := !t.stopped
   354  	t.stopped = false
   355  	t.Ticker.Reset(d)
   356  	return pending
   357  }
   358  
   359  func testTimerChan(t *testing.T, tim timer, C <-chan Time, synctimerchan bool) {
   360  	_, isTimer := tim.(*Timer)
   361  	isTicker := !isTimer
   362  
   363  	// Retry parameters. Enough to deflake even on slow machines.
   364  	// Windows in particular has very coarse timers so we have to
   365  	// wait 10ms just to make a timer go off.
   366  	const (
   367  		sched      = 10 * Millisecond
   368  		tries      = 100
   369  		drainTries = 5
   370  	)
   371  
   372  	// drain1 removes one potential stale time value
   373  	// from the timer/ticker channel after Reset.
   374  	// When using Go 1.23 sync timers/tickers, draining is never needed
   375  	// (that's the whole point of the sync timer/ticker change).
   376  	drain1 := func() {
   377  		for range drainTries {
   378  			select {
   379  			case <-C:
   380  				return
   381  			default:
   382  			}
   383  			Sleep(sched)
   384  		}
   385  	}
   386  
   387  	// drainAsync removes potential stale time values after Stop/Reset.
   388  	// When using Go 1 async timers, draining one or two values
   389  	// may be needed after Reset or Stop (see comments in body for details).
   390  	drainAsync := func() {
   391  		if synctimerchan {
   392  			// sync timers must have the right semantics without draining:
   393  			// there are no stale values.
   394  			return
   395  		}
   396  
   397  		// async timers can send one stale value (then the timer is disabled).
   398  		drain1()
   399  		if isTicker {
   400  			// async tickers can send two stale values: there may be one
   401  			// sitting in the channel buffer, and there may also be one
   402  			// send racing with the Reset/Stop+drain that arrives after
   403  			// the first drain1 has pulled the value out.
   404  			// This is rare, but it does happen on overloaded builder machines.
   405  			// It can also be reproduced on an M3 MacBook Pro using:
   406  			//
   407  			//	go test -c strings
   408  			//	stress ./strings.test &   # chew up CPU
   409  			//	go test -c -race time
   410  			//	stress -p 48 ./time.test -test.count=10 -test.run=TestChan/asynctimerchan=1/Ticker
   411  			drain1()
   412  		}
   413  	}
   414  	noTick := func() {
   415  		t.Helper()
   416  		select {
   417  		default:
   418  		case <-C:
   419  			t.Errorf("extra tick")
   420  		}
   421  	}
   422  	assertTick := func() {
   423  		t.Helper()
   424  		select {
   425  		default:
   426  		case <-C:
   427  			return
   428  		}
   429  		for range tries {
   430  			Sleep(sched)
   431  			select {
   432  			default:
   433  			case <-C:
   434  				return
   435  			}
   436  		}
   437  		t.Errorf("missing tick")
   438  	}
   439  	assertLen := func() {
   440  		t.Helper()
   441  		if synctimerchan {
   442  			if n := len(C); n != 0 {
   443  				t.Errorf("synctimer has len(C) = %d, want 0 (always)", n)
   444  			}
   445  			return
   446  		}
   447  		var n int
   448  		if n = len(C); n == 1 {
   449  			return
   450  		}
   451  		for range tries {
   452  			Sleep(sched)
   453  			if n = len(C); n == 1 {
   454  				return
   455  			}
   456  		}
   457  		t.Errorf("len(C) = %d, want 1", n)
   458  	}
   459  
   460  	// Test simple stop; timer never in heap.
   461  	tim.Stop()
   462  	noTick()
   463  
   464  	// Test modify of timer not in heap.
   465  	tim.Reset(10000 * Second)
   466  	noTick()
   467  
   468  	if synctimerchan {
   469  		// Test modify of timer in heap.
   470  		tim.Reset(1)
   471  		Sleep(sched)
   472  		if l, c := len(C), cap(C); l != 0 || c != 0 {
   473  			// t.Fatalf("len(C), cap(C) = %d, %d, want 0, 0", l, c)
   474  		}
   475  		assertTick()
   476  	} else {
   477  		// Test modify of timer in heap.
   478  		tim.Reset(1)
   479  		assertTick()
   480  		Sleep(sched)
   481  		tim.Reset(10000 * Second)
   482  		drainAsync()
   483  		noTick()
   484  
   485  		// Test that len sees an immediate tick arrive
   486  		// for Reset of timer in heap.
   487  		tim.Reset(1)
   488  		assertLen()
   489  		assertTick()
   490  
   491  		// Test that len sees an immediate tick arrive
   492  		// for Reset of timer NOT in heap.
   493  		tim.Stop()
   494  		drainAsync()
   495  		tim.Reset(1)
   496  		assertLen()
   497  		assertTick()
   498  	}
   499  
   500  	// Sleep long enough that a second tick must happen if this is a ticker.
   501  	// Test that Reset does not lose the tick that should have happened.
   502  	Sleep(sched)
   503  	tim.Reset(10000 * Second)
   504  	drainAsync()
   505  	noTick()
   506  
   507  	notDone := func(done chan bool) {
   508  		t.Helper()
   509  		select {
   510  		default:
   511  		case <-done:
   512  			t.Fatalf("early done")
   513  		}
   514  	}
   515  
   516  	waitDone := func(done chan bool) {
   517  		t.Helper()
   518  		for range tries {
   519  			Sleep(sched)
   520  			select {
   521  			case <-done:
   522  				return
   523  			default:
   524  			}
   525  		}
   526  		t.Fatalf("never got done")
   527  	}
   528  
   529  	// Reset timer in heap (already reset above, but just in case).
   530  	tim.Reset(10000 * Second)
   531  	drainAsync()
   532  
   533  	// Test stop while timer in heap (because goroutine is blocked on <-C).
   534  	done := make(chan bool)
   535  	notDone(done)
   536  	go func() {
   537  		<-C
   538  		close(done)
   539  	}()
   540  	Sleep(sched)
   541  	notDone(done)
   542  
   543  	// Test reset far away while timer in heap.
   544  	tim.Reset(20000 * Second)
   545  	Sleep(sched)
   546  	notDone(done)
   547  
   548  	// Test imminent reset while in heap.
   549  	tim.Reset(1)
   550  	waitDone(done)
   551  
   552  	// If this is a ticker, another tick should have come in already
   553  	// (they are 1ns apart). If a timer, it should have stopped.
   554  	if isTicker {
   555  		assertTick()
   556  	} else {
   557  		noTick()
   558  	}
   559  
   560  	tim.Stop()
   561  	drainAsync()
   562  	noTick()
   563  
   564  	// Again using select and with two goroutines waiting.
   565  	tim.Reset(10000 * Second)
   566  	drainAsync()
   567  	done = make(chan bool, 2)
   568  	done1 := make(chan bool)
   569  	done2 := make(chan bool)
   570  	stop := make(chan bool)
   571  	go func() {
   572  		select {
   573  		case <-C:
   574  			done <- true
   575  		case <-stop:
   576  		}
   577  		close(done1)
   578  	}()
   579  	go func() {
   580  		select {
   581  		case <-C:
   582  			done <- true
   583  		case <-stop:
   584  		}
   585  		close(done2)
   586  	}()
   587  	Sleep(sched)
   588  	notDone(done)
   589  	tim.Reset(sched / 2)
   590  	Sleep(sched)
   591  	waitDone(done)
   592  	tim.Stop()
   593  	close(stop)
   594  	waitDone(done1)
   595  	waitDone(done2)
   596  	if isTicker {
   597  		// extra send might have sent done again
   598  		// (handled by buffering done above).
   599  		select {
   600  		default:
   601  		case <-done:
   602  		}
   603  		// extra send after that might have filled C.
   604  		select {
   605  		default:
   606  		case <-C:
   607  		}
   608  	}
   609  	notDone(done)
   610  
   611  	// Test enqueueTimerChan when timer is stopped.
   612  	stop = make(chan bool)
   613  	done = make(chan bool, 2)
   614  	for range 2 {
   615  		go func() {
   616  			select {
   617  			case <-C:
   618  				panic("unexpected data")
   619  			case <-stop:
   620  			}
   621  			done <- true
   622  		}()
   623  	}
   624  	Sleep(sched)
   625  	close(stop)
   626  	waitDone(done)
   627  	waitDone(done)
   628  
   629  	// Test that Stop and Reset block old values from being received.
   630  	// (Proposal go.dev/issue/37196.)
   631  	if synctimerchan {
   632  		tim.Reset(1)
   633  		Sleep(10 * Millisecond)
   634  		if pending := tim.Stop(); pending != true {
   635  			t.Errorf("tim.Stop() = %v, want true", pending)
   636  		}
   637  		noTick()
   638  
   639  		tim.Reset(Hour)
   640  		noTick()
   641  		if pending := tim.Reset(1); pending != true {
   642  			t.Errorf("tim.Stop() = %v, want true", pending)
   643  		}
   644  		assertTick()
   645  		Sleep(10 * Millisecond)
   646  		if isTicker {
   647  			assertTick()
   648  			Sleep(10 * Millisecond)
   649  		} else {
   650  			noTick()
   651  		}
   652  		if pending, want := tim.Reset(Hour), isTicker; pending != want {
   653  			t.Errorf("tim.Stop() = %v, want %v", pending, want)
   654  		}
   655  		noTick()
   656  	}
   657  }
   658  
   659  func TestManualTicker(t *testing.T) {
   660  	// Code should not do this, but some old code dating to Go 1.9 does.
   661  	// Make sure this doesn't crash.
   662  	// See go.dev/issue/21874.
   663  	c := make(chan Time)
   664  	tick := &Ticker{C: c}
   665  	tick.Stop()
   666  }
   667  
   668  func TestAfterTimes(t *testing.T) {
   669  	t.Parallel()
   670  	// Using After(10ms) but waiting for 500ms to read the channel
   671  	// should produce a time from start+10ms, not start+500ms.
   672  	// Make sure it does.
   673  	// To avoid flakes due to very long scheduling delays,
   674  	// require 10 failures in a row before deciding something is wrong.
   675  	for range 10 {
   676  		start := Now()
   677  		c := After(10 * Millisecond)
   678  		Sleep(500 * Millisecond)
   679  		dt := (<-c).Sub(start)
   680  		if dt < 400*Millisecond {
   681  			return
   682  		}
   683  		t.Logf("After(10ms) time is +%v, want <400ms", dt)
   684  	}
   685  	t.Errorf("not working")
   686  }
   687  
   688  func TestTickTimes(t *testing.T) {
   689  	t.Parallel()
   690  	// See comment in TestAfterTimes
   691  	for range 10 {
   692  		start := Now()
   693  		c := Tick(10 * Millisecond)
   694  		Sleep(500 * Millisecond)
   695  		dt := (<-c).Sub(start)
   696  		if dt < 400*Millisecond {
   697  			return
   698  		}
   699  		t.Logf("Tick(10ms) time is +%v, want <400ms", dt)
   700  	}
   701  	t.Errorf("not working")
   702  }
   703  

View as plain text