internal/imgcache/eviction_internal_test.go

@@ -918,6 +918,89 @@ func TestPeriodicReconciliationAdoptsFileThatAppearsAfterStartup(t *testing.T) {
 	}
 }
 
+// TestReconciliationPassesAreSpacedByTenTimesTheirTime makes the hook
+// called after every read of the reconciliation pass sleep 10 ms, runs
+// the eviction loop on a 10 ms interval, and records when each of those
+// calls starts and ends. A pass starts before its first call and ends
+// after its last, so the time from the first call's start to the last
+// call's end is at most the pass's time. The next pass's first call must
+// start at least ten times that long after the last call ended.
+func TestReconciliationPassesAreSpacedByTenTimesTheirTime(t *testing.T) {
+	t.Parallel()
+
+	cache, _ := newEvictionTestCache(t, 1<<30)
+
+	// A pass made here, before the loop starts, counts the reads one
+	// pass makes on this empty cache, so the reads recorded below can be
+	// split into passes.
+	readsPerPass := 0
+	cache.reconciliationReadTestHook = func(int) { readsPerPass++ }
+
+	err := cache.reconcileAccounting(t.Context())
+	if err != nil {
+		t.Fatalf("reconcileAccounting failed: %v", err)
+	}
+
+	t.Logf("one reconciliation pass makes %d reads", readsPerPass)
+
+	if readsPerPass == 0 {
+		t.Fatal("a reconciliation pass made no read")
+	}
+
+	// The pass at startup and two after it.
+	const passes = 3
+
+	type read struct{ start, end time.Time }
+
+	// The channel holds every read the test looks at, so none of those
+	// is dropped; reads after them are, and never block the loop.
+	reads := make(chan read, passes*readsPerPass)
+
+	cache.reconciliationReadTestHook = func(int) {
+		start := time.Now()
+
+		time.Sleep(10 * time.Millisecond)
+
+		select {
+		case reads <- read{start: start, end: time.Now()}:
+		default:
+		}
+	}
+
+	cache.StartEviction(10 * time.Millisecond)
+	defer func() { _ = cache.StopEviction(t.Context()) }()
+
+	recorded := make([]read, 0, passes*readsPerPass)
+	timeout := time.After(15 * time.Second)
+
+	for len(recorded) < passes*readsPerPass {
+		select {
+		case r := <-reads:
+			recorded = append(recorded, r)
+		case <-timeout:
+			t.Fatalf("saw %d reconciliation reads in 15 s, want %d (%d passes)",
+				len(recorded), passes*readsPerPass, passes)
+		}
+	}
+
+	for pass := range passes - 1 {
+		first := recorded[pass*readsPerPass]
+		last := recorded[(pass+1)*readsPerPass-1]
+		next := recorded[(pass+1)*readsPerPass]
+
+		passTime := last.end.Sub(first.start)
+		wait := next.start.Sub(last.end)
+
+		t.Logf("pass %d took at least %v, and the next pass started %v after it",
+			pass+1, passTime, wait)
+
+		if wait < 10*passTime {
+			t.Errorf("pass %d took at least %v, and the next pass started %v "+
+				"after it, want at least %v", pass+1, passTime, wait, 10*passTime)
+		}
+	}
+}
+
 // TestStopEvictionInterruptsPassInProgress holds the test database's
 // only connection, so the startup reconciliation pass waits for it, and
 // checks that StopEviction stops that pass instead of waiting for the