diff --git a/db_test.go b/db_test.go index 7d541c0a87..15a7c113c7 100644 --- a/db_test.go +++ b/db_test.go @@ -20,7 +20,6 @@ import ( "github.com/cockroachdb/errors" "github.com/cockroachdb/pebble/internal/base" "github.com/cockroachdb/pebble/internal/cache" - "github.com/cockroachdb/pebble/internal/invariants" "github.com/cockroachdb/pebble/objstorage/objstorageprovider" "github.com/cockroachdb/pebble/sstable" "github.com/cockroachdb/pebble/vfs" @@ -1412,10 +1411,7 @@ func (t *testTracer) IsTracingEnabled(ctx context.Context) bool { } func TestTracing(t *testing.T) { - if !invariants.Enabled { - // The test relies on timing behavior injected when invariants.Enabled. - return - } + defer sstable.DeterministicReadBlockDurationForTesting()() var tracer testTracer c := NewCache(0) defer c.Unref() diff --git a/metrics_test.go b/metrics_test.go index f3226b8cfb..c080e09733 100644 --- a/metrics_test.go +++ b/metrics_test.go @@ -97,6 +97,7 @@ func TestMetrics(t *testing.T) { if runtime.GOARCH == "386" { t.Skip("skipped on 32-bit due to slightly varied output") } + defer sstable.DeterministicReadBlockDurationForTesting()() c := cache.New(cacheDefaultSize) defer c.Unref() opts := &Options{ @@ -267,6 +268,7 @@ func TestMetrics(t *testing.T) { d.mu.Unlock() m := d.Metrics() + // Some subset of cases show non-determinism in cache hits/misses. if td.HasArg("zero-cache-hits-misses") { // Avoid non-determinism. m.TableCache.Hits = 0 diff --git a/sstable/category_stats.go b/sstable/category_stats.go index bb2154d0e6..178f88455f 100644 --- a/sstable/category_stats.go +++ b/sstable/category_stats.go @@ -8,6 +8,7 @@ import ( "cmp" "slices" "sync" + "time" "github.com/cockroachdb/errors" "github.com/cockroachdb/redact" @@ -77,11 +78,15 @@ type CategoryStats struct { // BlockBytesInCache is the subset of BlockBytes that were in the block // cache. BlockBytesInCache uint64 + // BlockReadDuration is the total duration to read the bytes not in the + // cache, i.e., BlockBytes-BlockBytesInCache. + BlockReadDuration time.Duration } func (s *CategoryStats) aggregate(a CategoryStats) { s.BlockBytes += a.BlockBytes s.BlockBytesInCache += a.BlockBytesInCache + s.BlockReadDuration += a.BlockReadDuration } // CategoryStatsAggregate is the aggregate for the given category. @@ -160,9 +165,12 @@ func (accum *iterStatsAccumulator) init( accum.collector = collector } -func (accum *iterStatsAccumulator) reportStats(blockBytes, blockBytesInCache uint64) { +func (accum *iterStatsAccumulator) reportStats( + blockBytes, blockBytesInCache uint64, blockReadDuration time.Duration, +) { accum.stats.BlockBytes += blockBytes accum.stats.BlockBytesInCache += blockBytesInCache + accum.stats.BlockReadDuration += blockReadDuration } func (accum *iterStatsAccumulator) close() { diff --git a/sstable/reader.go b/sstable/reader.go index 97059eef23..ce8f1dac76 100644 --- a/sstable/reader.go +++ b/sstable/reader.go @@ -558,6 +558,19 @@ func (b cacheValueOrBuf) truncate(n int) { } } +// DeterministicReadBlockDurationForTesting is for tests that want a +// deterministic value of the time to read a block (that is not in the cache). +// The return value is a function that must be called before the test exits. +func DeterministicReadBlockDurationForTesting() func() { + drbdForTesting := deterministicReadBlockDurationForTesting + deterministicReadBlockDurationForTesting = true + return func() { + deterministicReadBlockDurationForTesting = drbdForTesting + } +} + +var deterministicReadBlockDurationForTesting = false + func (r *Reader) readBlock( ctx context.Context, bh BlockHandle, @@ -577,7 +590,7 @@ func (r *Reader) readBlock( stats.BlockBytesInCache += bh.Length } if iterStats != nil { - iterStats.reportStats(bh.Length, bh.Length) + iterStats.reportStats(bh.Length, bh.Length, 0) } // This block is already in the cache; return a handle to existing vlaue // in the cache. @@ -606,8 +619,8 @@ func (r *Reader) readBlock( readDuration := time.Since(readStartTime) // TODO(sumeer): should the threshold be configurable. const slowReadTracingThreshold = 5 * time.Millisecond - // The invariants.Enabled path is for deterministic testing. - if invariants.Enabled { + // For deterministic testing. + if deterministicReadBlockDurationForTesting { readDuration = slowReadTracingThreshold } // Call IsTracingEnabled to avoid the allocations of boxing integers into an @@ -678,7 +691,7 @@ func (r *Reader) readBlock( stats.BlockBytes += bh.Length } if iterStats != nil { - iterStats.reportStats(bh.Length, 0) + iterStats.reportStats(bh.Length, 0, readDuration) } if decompressed.buf.Valid() { return bufferHandle{b: decompressed.buf}, nil diff --git a/testdata/metrics b/testdata/metrics index e2ddd5ea10..55a1beacc1 100644 --- a/testdata/metrics +++ b/testdata/metrics @@ -129,7 +129,7 @@ Table iters: 2 Filter utility: 0.0% Ingestions: 0 as flushable: 0 (0B in 0 tables) Iter category stats: - pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88} + pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88 BlockReadDuration:10ms} disk-usage ---- @@ -170,7 +170,7 @@ Table iters: 2 Filter utility: 0.0% Ingestions: 0 as flushable: 0 (0B in 0 tables) Iter category stats: - pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88} + pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88 BlockReadDuration:10ms} # Closing iter c will release one of the zombie sstables. The other # zombie sstable is still referenced by iter b. @@ -208,8 +208,8 @@ Table iters: 1 Filter utility: 0.0% Ingestions: 0 as flushable: 0 (0B in 0 tables) Iter category stats: - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88 BlockReadDuration:10ms} disk-usage ---- @@ -250,9 +250,9 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 0 as flushable: 0 (0B in 0 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88 BlockReadDuration:10ms} disk-usage ---- @@ -319,9 +319,9 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 0 as flushable: 0 (0B in 0 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:132 BlockBytesInCache:88 BlockReadDuration:10ms} additional-metrics ---- @@ -372,9 +372,9 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 0 as flushable: 0 (0B in 0 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154 BlockReadDuration:60ms} additional-metrics ---- @@ -474,10 +474,10 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 0 as flushable: 2 (2.1KB in 3 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154} - pebble-ingest, latency: {BlockBytes:192 BlockBytesInCache:128} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154 BlockReadDuration:60ms} + pebble-ingest, latency: {BlockBytes:192 BlockBytesInCache:128 BlockReadDuration:10ms} batch set g g @@ -535,10 +535,10 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 0 as flushable: 2 (2.1KB in 3 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154} - pebble-ingest, latency: {BlockBytes:192 BlockBytesInCache:128} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154 BlockReadDuration:60ms} + pebble-ingest, latency: {BlockBytes:192 BlockBytesInCache:128 BlockReadDuration:10ms} build ext1 set z z @@ -610,10 +610,10 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 1 as flushable: 2 (2.1KB in 3 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154} - pebble-ingest, latency: {BlockBytes:328 BlockBytesInCache:128} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:411 BlockBytesInCache:154 BlockReadDuration:60ms} + pebble-ingest, latency: {BlockBytes:328 BlockBytesInCache:128 BlockReadDuration:30ms} # Virtualize a virtual sstable. build ext1 @@ -710,7 +710,7 @@ Table iters: 0 Filter utility: 0.0% Ingestions: 2 as flushable: 2 (2.1KB in 3 tables) Iter category stats: - b, latency: {BlockBytes:44 BlockBytesInCache:0} - c, non-latency: {BlockBytes:44 BlockBytesInCache:44} - pebble-compaction, non-latency: {BlockBytes:941 BlockBytesInCache:640} - pebble-ingest, latency: {BlockBytes:400 BlockBytesInCache:200} + b, latency: {BlockBytes:44 BlockBytesInCache:0 BlockReadDuration:10ms} + c, non-latency: {BlockBytes:44 BlockBytesInCache:44 BlockReadDuration:0s} + pebble-compaction, non-latency: {BlockBytes:941 BlockBytesInCache:640 BlockReadDuration:70ms} + pebble-ingest, latency: {BlockBytes:400 BlockBytesInCache:200 BlockReadDuration:30ms}