Skip to content

Commit

Permalink
sstable: add CategoryStats.BlockReadDuration
Browse files Browse the repository at this point in the history 
This could be helpful if some categories are seeing faster reads due
to environmental effects (such as page cache or caches in virtual
block devices).
  • Loading branch information
@sumeerbhola
sumeerbhola committed Jan 12, 2024
1 parent 0b0f62a commit 0effd24
Show file tree
Hide file tree
Showing 5 changed files with 58 additions and 39 deletions.
6 changes: 1 addition & 5 deletions db_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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()
Expand Down
2 changes: 2 additions & 0 deletions metrics_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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{
Expand Down Expand Up @@ -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
Expand Down
10 changes: 9 additions & 1 deletion sstable/category_stats.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ import (
"cmp"
"slices"
"sync"
"time"

"github.com/cockroachdb/errors"
"github.com/cockroachdb/redact"
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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() {
Expand Down
21 changes: 17 additions & 4 deletions sstable/reader.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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.
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
58 changes: 29 additions & 29 deletions testdata/metrics
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
----
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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
----
Expand Down Expand Up @@ -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
----
Expand Down Expand Up @@ -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
----
Expand Down Expand Up @@ -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
----
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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}

0 comments on commit 0effd24

Please sign in to comment.