Repository: cockroachdb/pebble
Pull request #3772 (2024-07-17 23:23:57)

crl-release-23.2: sstable: improve slow block read log
Add the two callers to identify the code path (and implicitly what
kind of block it is).

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/3772)
<!-- Reviewable:end -->


Patch:
diff --git a/sstable/reader.go b/sstable/reader.go
index 284aa1f9..172d6c20 100644
--- a/sstable/reader.go
+++ b/sstable/reader.go
@@ -10,6 +10,8 @@ import (
 	"encoding/binary"
 	"io"
 	"os"
+	"path/filepath"
+	"runtime"
 	"sort"
 	"time"
 
@@ -570,8 +572,13 @@ func (r *Reader) readBlock(
 	// Call IsTracingEnabled to avoid the allocations of boxing integers into an
 	// interface{}, unless necessary.
 	if readDuration >= slowReadTracingThreshold && r.opts.LoggerAndTracer.IsTracingEnabled(ctx) {
-		r.opts.LoggerAndTracer.Eventf(ctx, "reading %d bytes took %s",
-			int(bh.Length+blockTrailerLen), readDuration.String())
+		_, file1, line1, _ := runtime.Caller(1)
+		_, file2, line2, _ := runtime.Caller(2)
+		r.opts.LoggerAndTracer.Eventf(ctx, "reading block of %d bytes took %s (fileNum=%s; %s/%s:%d -> %s/%s:%d)",
+			int(bh.Length+blockTrailerLen), readDuration.String(),
+			r.fileNum,
+			filepath.Base(filepath.Dir(file2)), filepath.Base(file2), line2,
+			filepath.Base(filepath.Dir(file1)), filepath.Base(file1), line1)
 	}
 	if stats != nil {
 		stats.BlockBytes += bh.Length
diff --git a/sstable/table.go b/sstable/table.go
index dc293b63..4db212b3 100644
--- a/sstable/table.go
+++ b/sstable/table.go
@@ -349,7 +349,7 @@ func readFooter(f objstorage.Readable, logger base.LoggerAndTracer) (footer, err
 	// 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",
+		logger.Eventf(context.TODO(), "reading footer of %d bytes took %s",
 			len(buf), readDuration.String())
 	}
 


Test patch:
diff --git a/db_test.go b/db_test.go
index b95ae8dd..6fe72ce9 100644
--- a/db_test.go
+++ b/db_test.go
@@ -1440,9 +1440,16 @@ func TestTracing(t *testing.T) {
 	_, closer, err := d.Get([]byte("hello"))
 	require.NoError(t, err)
 	closer.Close()
-	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())
+	readerInitRegexp := `reading footer of 53 bytes took 5ms
+reading block of 37 bytes took 5ms \([^)]*\)
+reading block of 628 bytes took 5ms \([^)]*\)
+`
+	iterTraceRegexp :=
+		`reading block of 27 bytes took 5ms \([^)]*\)
+reading block of 29 bytes took 5ms \([^)]*\)
+`
+
+	require.Regexp(t, "^"+readerInitRegexp+iterTraceRegexp+"$", tracer.buf.String())
 
 	// Get again, but since it currently uses context.Background(), no trace
 	// output is produced.
@@ -1458,14 +1465,14 @@ func TestTracing(t *testing.T) {
 	iter, _ := d.NewIterWithContext(ctx, nil)
 	iter.SeekGE([]byte("hello"))
 	iter.Close()
-	require.Equal(t, iterTraceString, tracer.buf.String())
+	require.Regexp(t, iterTraceRegexp, tracer.buf.String())
 
 	tracer.buf.Reset()
 	snap := d.NewSnapshot()
 	iter, _ = snap.NewIterWithContext(ctx, nil)
 	iter.SeekGE([]byte("hello"))
 	iter.Close()
-	require.Equal(t, iterTraceString, tracer.buf.String())
+	require.Regexp(t, iterTraceRegexp, tracer.buf.String())
 	snap.Close()
 
 	tracer.buf.Reset()
@@ -1473,7 +1480,7 @@ func TestTracing(t *testing.T) {
 	iter = b.NewIterWithContext(ctx, nil)
 	iter.SeekGE([]byte("hello"))
 	iter.Close()
-	require.Equal(t, iterTraceString, tracer.buf.String())
+	require.Regexp(t, iterTraceRegexp, tracer.buf.String())
 	b.Close()
 }