Repository: cockroachdb/pebble
Pull request #3752 (2024-07-12 15:56:08)

crl-release-23.2: sstable: trace/expensive log when sstable footer read is slow
backport https://github.com/cockroachdb/pebble/pull/3745

---

This is a manual backport of https://github.com/cockroachdb/pebble/pull/3745

Relates to #3728

cockroach-teamcity: 

<!-- Reviewable:start -->
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/cockroachdb/pebble/3752)
<!-- Reviewable:end -->


Patch:
diff --git a/internal/base/logger.go b/internal/base/logger.go
index e4a2f44f..5348459b 100644
--- a/internal/base/logger.go
+++ b/internal/base/logger.go
@@ -85,11 +85,13 @@ func (b *InMemLogger) Fatalf(format string, args ...interface{}) {
 type LoggerAndTracer interface {
 	Logger
 	// Eventf formats and emits a tracing log, if tracing is enabled in the
-	// current context.
+	// current context. It can also emit to a regular log, if expensive
+	// logging is enabled.
 	Eventf(ctx context.Context, format string, args ...interface{})
-	// IsTracingEnabled returns true if tracing is enabled. It can be used as an
-	// optimization to avoid calling Eventf (which will be a noop when tracing
-	// is not enabled) to avoid the overhead of boxing the args.
+	// IsTracingEnabled returns true if tracing is enabled for this context,
+	// or expensive logging is enabled. It can be used as an optimization to
+	// avoid calling Eventf (which will be a noop when tracing or expensive
+	// logging is not enabled) to avoid the overhead of boxing the args.
 	IsTracingEnabled(ctx context.Context) bool
 }
 
diff --git a/sstable/reader.go b/sstable/reader.go
index 39c7a696..284aa1f9 100644
--- a/sstable/reader.go
+++ b/sstable/reader.go
@@ -559,20 +559,14 @@ func (r *Reader) readBlock(
 		}
 	}
 
-	readStartTime := time.Now()
+	readStopwatch := makeStopwatch()
 	var err error
 	if readHandle != nil {
 		err = readHandle.ReadAt(ctx, compressed.get(), int64(bh.Offset))
 	} else {
 		err = r.readable.ReadAt(ctx, compressed.get(), int64(bh.Offset))
 	}
-	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 {
-		readDuration = slowReadTracingThreshold
-	}
+	readDuration := readStopwatch.stop()
 	// Call IsTracingEnabled to avoid the allocations of boxing integers into an
 	// interface{}, unless necessary.
 	if readDuration >= slowReadTracingThreshold && r.opts.LoggerAndTracer.IsTracingEnabled(ctx) {
@@ -1133,7 +1127,7 @@ func NewReader(f objstorage.Readable, o ReaderOptions, extraOpts ...ReaderOption
 		r.cacheID = r.opts.Cache.NewID()
 	}
 
-	footer, err := readFooter(f)
+	footer, err := readFooter(f, r.opts.LoggerAndTracer)
 	if err != nil {
 		r.err = err
 		return nil, r.Close()
@@ -1239,3 +1233,20 @@ func (s *simpleReadable) Size() int64 {
 func (s *simpleReadable) NewReadHandle(_ context.Context) objstorage.ReadHandle {
 	return &s.rh
 }
+
+type deterministicStopwatchForTesting struct {
+	startTime time.Time
+}
+
+func makeStopwatch() deterministicStopwatchForTesting {
+	return deterministicStopwatchForTesting{startTime: time.Now()}
+}
+
+func (w deterministicStopwatchForTesting) stop() time.Duration {
+	dur := time.Since(w.startTime)
+	// The invariants.Enabled path is for deterministic testing.
+	if invariants.Enabled {
+		dur = slowReadTracingThreshold
+	}
+	return dur
+}
diff --git a/sstable/table.go b/sstable/table.go
index 040efafd..dc293b63 100644
--- a/sstable/table.go
+++ b/sstable/table.go
@@ -70,6 +70,7 @@ package sstable // import "github.com/cockroachdb/pebble/sstable"
 import (
 	"context"
 	"encoding/binary"
+	"time"
 
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/pebble/internal/base"
@@ -324,7 +325,10 @@ type footer struct {
 	footerBH    BlockHandle
 }
 
-func readFooter(f objstorage.Readable) (footer, error) {
+// TODO(sumeer): should the threshold be configurable.
+const slowReadTracingThreshold = 5 * time.Millisecond
+
+func readFooter(f objstorage.Readable, logger base.LoggerAndTracer) (footer, error) {
 	var footer footer
 	size := f.Size()
 	if size < minFooterLen {
@@ -337,9 +341,17 @@ func readFooter(f objstorage.Readable) (footer, error) {
 		off = 0
 		buf = buf[:size]
 	}
+	readStopwatch := makeStopwatch()
 	if err := f.ReadAt(context.TODO(), buf, off); err != nil {
 		return footer, errors.Wrap(err, "pebble/table: invalid table (could not read footer)")
 	}
+	readDuration := readStopwatch.stop()
+	// Call IsTracingEnabled to avoid the allocations of boxing integers into an
+	// interface{}, unless necessary.
+	if readDuration >= slowReadTracingThreshold && logger.IsTracingEnabled(context.TODO()) {
+		logger.Eventf(context.TODO(), "reading %d bytes took %s",
+			len(buf), readDuration.String())
+	}
 
 	switch magic := buf[len(buf)-len(rocksDBMagic):]; string(magic) {
 	case levelDBMagic:


Test patch:
diff --git a/db_test.go b/db_test.go
index 15f2cb13..b95ae8dd 100644
--- a/db_test.go
+++ b/db_test.go
@@ -1440,7 +1440,7 @@ func TestTracing(t *testing.T) {
 	_, closer, err := d.Get([]byte("hello"))
 	require.NoError(t, err)
 	closer.Close()
-	readerInitTraceString := "reading 37 bytes took 5ms\nreading 628 bytes took 5ms\n"
+	readerInitTraceString := "reading 53 bytes took 5ms\nreading 37 bytes took 5ms\nreading 628 bytes took 5ms\n"
 	iterTraceString := "reading 27 bytes took 5ms\nreading 29 bytes took 5ms\n"
 	require.Equal(t, readerInitTraceString+iterTraceString, tracer.buf.String())
 
diff --git a/sstable/table_test.go b/sstable/table_test.go
index 2bf6b3cd..dcc20eaf 100644
--- a/sstable/table_test.go
+++ b/sstable/table_test.go
@@ -752,7 +752,7 @@ func TestFooterRoundTrip(t *testing.T) {
 							readable, err := NewSimpleReadable(f)
 							require.NoError(t, err)
 
-							result, err := readFooter(readable)
+							result, err := readFooter(readable, base.NoopLoggerAndTracer{})
 							require.NoError(t, err)
 							require.NoError(t, readable.Close())
 
@@ -805,7 +805,7 @@ func TestReadFooter(t *testing.T) {
 			readable, err := NewSimpleReadable(f)
 			require.NoError(t, err)
 
-			if _, err := readFooter(readable); err == nil {
+			if _, err := readFooter(readable, base.NoopLoggerAndTracer{}); err == nil {
 				t.Fatalf("expected %q, but found success", c.expected)
 			} else if !strings.Contains(err.Error(), c.expected) {
 				t.Fatalf("expected %q, but found %v", c.expected, err)