diff --git a/internal/imgcache/eviction_internal_test.go b/internal/imgcache/eviction_internal_test.go index 7d54df1..d1ddf31 100644 --- a/internal/imgcache/eviction_internal_test.go +++ b/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