Repository: cockroachdb/pebble
Pull request #3773 (2024-07-17 23:26:13)

crl-release-23.1: 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/3773)
<!-- Reviewable:end -->

nicktrav: Despite the pending run (for macos), I'm going to merge this so we can get moving on the Pebble bump for this branch.

Patch:
diff --git a/sstable/reader.go b/sstable/reader.go
index 5b21ff96..7fbfffd6 100644
--- a/sstable/reader.go
+++ b/sstable/reader.go
@@ -11,6 +11,8 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"path/filepath"
+	"runtime"
 	"sort"
 	"sync"
 	"time"
@@ -2861,8 +2863,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",
-			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)",
+			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.BlockReadDuration += readDuration
diff --git a/sstable/table.go b/sstable/table.go
index 9819d3b6..135467ed 100644
--- a/sstable/table.go
+++ b/sstable/table.go
@@ -332,7 +332,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 0dd822af..5ef258fc 100644
--- a/db_test.go
+++ b/db_test.go
@@ -1337,9 +1337,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.
@@ -1355,14 +1362,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()
@@ -1370,7 +1377,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()
 }