Test that reconciliation passes are spaced by ten times their time

The new test makes every read of the reconciliation pass sleep 10 ms
through reconciliationReadTestHook, runs the eviction loop on a 10 ms
interval, and checks that each pass starts at least ten times as long
after the previous one ended as that one took. It fails while the pass
runs on every eviction tick, since a slow pass is then followed by the
next one at once.

Model: opus-5-5

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