lib/sync: Make some tests not depend on real clock

GitHub-Pull-Request: https://github.com/syncthing/syncthing/pull/4065

lib/sync/sync.go

@@ -19,6 +19,12 @@ import (
 	"github.com/sasha-s/go-deadlock"
 )
 
+type clock interface {
+	Now() time.Time
+}
+
+var defaultClock clock = (*standardClock)(nil)
+
 type Mutex interface {
 	Lock()
 	Unlock()
@@ -80,7 +86,7 @@ func (h holder) String() string {
 	if h.at == "" {
 		return "not held"
 	}
-	return fmt.Sprintf("at %s goid: %d for %s", h.at, h.goid, time.Since(h.time))
+	return fmt.Sprintf("at %s goid: %d for %s", h.at, h.goid, defaultClock.Now().Sub(h.time))
 }
 
 type loggedMutex struct {
@@ -95,7 +101,7 @@ func (m *loggedMutex) Lock() {
 
 func (m *loggedMutex) Unlock() {
 	currentHolder := m.holder.Load().(holder)
-	duration := time.Since(currentHolder.time)
+	duration := defaultClock.Now().Sub(currentHolder.time)
 	if duration >= threshold {
 		l.Debugf("Mutex held for %v. Locked at %s unlocked at %s", duration, currentHolder.at, getHolder().at)
 	}
@@ -119,7 +125,7 @@ type loggedRWMutex struct {
 }
 
 func (m *loggedRWMutex) Lock() {
-	start := time.Now()
+	start := defaultClock.Now()
 
 	atomic.StoreInt32(&m.logUnlockers, 1)
 	m.RWMutex.Lock()
@@ -147,7 +153,7 @@ func (m *loggedRWMutex) Lock() {
 
 func (m *loggedRWMutex) Unlock() {
 	currentHolder := m.holder.Load().(holder)
-	duration := time.Since(currentHolder.time)
+	duration := defaultClock.Now().Sub(currentHolder.time)
 	if duration >= threshold {
 		l.Debugf("RWMutex held for %v. Locked at %s unlocked at %s", duration, currentHolder.at, getHolder().at)
 	}
@@ -199,9 +205,9 @@ type loggedWaitGroup struct {
 }
 
 func (wg *loggedWaitGroup) Wait() {
-	start := time.Now()
+	start := defaultClock.Now()
 	wg.WaitGroup.Wait()
-	duration := time.Since(start)
+	duration := defaultClock.Now().Sub(start)
 	if duration >= threshold {
 		l.Debugf("WaitGroup took %v at %s", duration, getHolder())
 	}
@@ -213,7 +219,7 @@ func getHolder() holder {
 	return holder{
 		at:   fmt.Sprintf("%s:%d", file, line),
 		goid: goid(),
-		time: time.Now(),
+		time: defaultClock.Now(),
 	}
 }
 
@@ -294,3 +300,9 @@ func (w *TimeoutCondWaiter) Wait() bool {
 func (w *TimeoutCondWaiter) Stop() {
 	w.timer.Stop()
 }
+
+type standardClock struct{}
+
+func (*standardClock) Now() time.Time {
+	return time.Now()
+}

lib/sync/sync_test.go

@@ -21,23 +21,6 @@ const (
 	longWait     = 125 * time.Millisecond
 )
 
-var skipTimingTests = false
-
-func init() {
-	// Check a few times that a short sleep does not in fact overrun the log
-	// threshold. If it does, the timer accuracy is crap or the host is
-	// overloaded and we can't reliably run the tests in here. In the normal
-	// case this takes just 25*5 = 125 ms.
-	for i := 0; i < 25; i++ {
-		t0 := time.Now()
-		time.Sleep(shortWait)
-		if time.Since(t0) > logThreshold {
-			skipTimingTests = true
-			return
-		}
-	}
-}
-
 func TestTypes(t *testing.T) {
 	debug = false
 	l.SetDebug("sync", false)
@@ -74,10 +57,10 @@ func TestTypes(t *testing.T) {
 }
 
 func TestMutex(t *testing.T) {
-	if skipTimingTests {
+	oldClock := defaultClock
-		t.Skip("insufficient timer accuracy")
+	clock := newTestClock()
-		return
+	defaultClock = clock
-	}
+	defer func() { defaultClock = oldClock }()
 
 	debug = true
 	l.SetDebug("sync", true)
@@ -94,7 +77,7 @@ func TestMutex(t *testing.T) {
 
 	mut := NewMutex()
 	mut.Lock()
-	time.Sleep(shortWait)
+	clock.wind(shortWait)
 	mut.Unlock()
 
 	if len(messages) > 0 {
@@ -102,7 +85,7 @@ func TestMutex(t *testing.T) {
 	}
 
 	mut.Lock()
-	time.Sleep(longWait)
+	clock.wind(longWait)
 	mut.Unlock()
 
 	if len(messages) != 1 {
@@ -114,10 +97,10 @@ func TestMutex(t *testing.T) {
 }
 
 func TestRWMutex(t *testing.T) {
-	if skipTimingTests {
+	oldClock := defaultClock
-		t.Skip("insufficient timer accuracy")
+	clock := newTestClock()
-		return
+	defaultClock = clock
-	}
+	defer func() { defaultClock = oldClock }()
 
 	debug = true
 	l.SetDebug("sync", true)
@@ -134,7 +117,7 @@ func TestRWMutex(t *testing.T) {
 
 	mut := NewRWMutex()
 	mut.Lock()
-	time.Sleep(shortWait)
+	clock.wind(shortWait)
 	mut.Unlock()
 
 	if len(messages) > 0 {
@@ -142,7 +125,7 @@ func TestRWMutex(t *testing.T) {
 	}
 
 	mut.Lock()
-	time.Sleep(longWait)
+	clock.wind(longWait)
 	mut.Unlock()
 
 	if len(messages) != 1 {
@@ -150,14 +133,21 @@ func TestRWMutex(t *testing.T) {
 	}
 
 	// Testing rlocker logging
+	wait := make(chan struct{})
+	locking := make(chan struct{})
+
 	mut.RLock()
 	go func() {
-		time.Sleep(longWait)
+		close(locking)
-		mut.RUnlock()
+		mut.Lock()
+		close(wait)
 	}()
 
-	mut.Lock()
+	<-locking
-	_ = 1 // skip empty critical section check
+	clock.wind(longWait)
+	mut.RUnlock()
+	<-wait
+
 	mut.Unlock()
 
 	if len(messages) != 2 {
@@ -181,10 +171,10 @@ func TestRWMutex(t *testing.T) {
 }
 
 func TestWaitGroup(t *testing.T) {
-	if skipTimingTests {
+	oldClock := defaultClock
-		t.Skip("insufficient timer accuracy")
+	clock := newTestClock()
-		return
+	defaultClock = clock
-	}
+	defer func() { defaultClock = oldClock }()
 
 	debug = true
 	l.SetDebug("sync", true)
@@ -201,10 +191,15 @@ func TestWaitGroup(t *testing.T) {
 
 	wg := NewWaitGroup()
 	wg.Add(1)
+	waiting := make(chan struct{})
+
 	go func() {
-		time.Sleep(shortWait)
+		<-waiting
+		clock.wind(shortWait)
 		wg.Done()
 	}()
+
+	close(waiting)
 	wg.Wait()
 
 	if len(messages) > 0 {
@@ -212,11 +207,16 @@ func TestWaitGroup(t *testing.T) {
 	}
 
 	wg = NewWaitGroup()
+	waiting = make(chan struct{})
+
 	wg.Add(1)
 	go func() {
-		time.Sleep(longWait)
+		<-waiting
+		clock.wind(longWait)
 		wg.Done()
 	}()
+
+	close(waiting)
 	wg.Wait()
 
 	if len(messages) != 1 {
@@ -323,3 +323,28 @@ func runLocks(t *testing.T, iterations int, c *TimeoutCond, d time.Duration) (su
 	}
 	return
 }
+
+type testClock struct {
+	time time.Time
+	mut  sync.Mutex
+}
+
+func newTestClock() *testClock {
+	return &testClock{
+		time: time.Now(),
+	}
+}
+
+func (t *testClock) Now() time.Time {
+	t.mut.Lock()
+	now := t.time
+	t.time = t.time.Add(time.Nanosecond)
+	t.mut.Unlock()
+	return now
+}
+
+func (t *testClock) wind(d time.Duration) {
+	t.mut.Lock()
+	t.time = t.time.Add(d)
+	t.mut.Unlock()
+}