metamorphic: bound time spent level checking

The metamorphic test runs with the level checker validating every new
readState. This level checking happens while holding the database mutex,
preventing the test from making forward progress. Some configurations can
create pathological LSMs with tens of thousands of sstables, which are slow to
validate with the level checker.

This commit addresses this issue by tracking the test wall time and the
cumulative wall time spent in the level checker. It avoids running the level
checker if the cumulative time spent in the level checker exceeds 25% of the
overall run's run time.

Additionally, regardless of the cumulative time budget, it skips the level
checker half the time. This is intended to ensure that inserting artifical
latency during read-state installation through level checking doesn't obscure
subtle races.

Fix #4517.
Fix #4338.
Fix #4202.

Author: jbowens

metamorphic/options.go

@@ -322,8 +322,7 @@ func defaultOptions(kf KeyFormat) *pebble.Options {
 	opts := &pebble.Options{
 		// Use an archive cleaner to ease post-mortem debugging.
 		Cleaner: base.ArchiveCleaner{},
-		// Always use our custom comparer which provides a Split method,
-		// splitting keys at the trailing '@'.
+		// Always use our custom comparer which provides a Split method.
 		Comparer:           kf.Comparer,
 		KeySchema:          kf.KeySchema.Name,
 		KeySchemas:         sstable.MakeKeySchemas(kf.KeySchema),
@@ -336,27 +335,34 @@ func defaultOptions(kf KeyFormat) *pebble.Options {
 	}
 	opts.Experimental.EnableColumnarBlocks = func() bool { return true }
 
-	// We don't want to run the level checker every time because it can slow down
-	// downloads and background compactions too much.
+	// The level checker runs every time a new read state is installed: every
+	// compaction, flush, ingest completion, etc. It runs while the database
+	// mutex DB.mu is held, preventing the scheduling of new compactions or
+	// flushes.
 	//
-	// We aim to run it once every 500ms (on average). To do this with some
-	// randomization, each time we get a callback we see how much time passed
-	// since the last call and run the check with a proportional probability.
-	const meanTimeBetweenChecks = 500 * time.Millisecond
+	// We only consider running the level checker 50% of the time (to ensure
+	// we're not obscuring races post-read state installation).
+	//
+	// Additionally, some option configurations can create pathological numbers
+	// of sstables, causing the level checker to consume an excessive amount of
+	// time. To prevent pathological cases, we limit the cumulative time spent
+	// in the level checker to 25% of the test's runtime. If DebugCheck is
+	// invoked but we've spent more than 25% of our total test time wihtin the
+	// level checker, we skip invoking DebugCheckLevels.
 	startTime := time.Now()
-	// lastCallTime stores the time of the last DebugCheck call, as the duration
-	// since startTime.
-	var lastCallTime atomic.Uint64
+	var cumulativeTime atomic.Int64
 	opts.DebugCheck = func(db *pebble.DB) error {
-		now := time.Since(startTime)
-		last := time.Duration(lastCallTime.Swap(uint64(now)))
-		// Run the check with probability equal to the time (as a fraction of
-		// meanTimeBetweenChecks) passed since the last time we had a chance, as a
-		// fraction of meanTimeBetweenChecks.
-		if rand.Float64() < float64(now-last)/float64(meanTimeBetweenChecks) {
-			return pebble.DebugCheckLevels(db)
+		if rand.Float64() < 0.50 {
+			return nil
+		}
+		now := time.Now()
+		testDur := now.Sub(startTime)
+		if checkerDur := time.Duration(cumulativeTime.Load()); checkerDur > testDur/4 {
+			return nil
 		}
-		return nil
+		err := pebble.DebugCheckLevels(db)
+		cumulativeTime.Add(int64(time.Since(now)))
+		return err
 	}
 
 	return opts