storage: make pebbleLogger.Eventf also log

This is useful when tracing is not enabled, but verbosity of logging can be increased. Also, we currently have gaps in context propagation in tracing which this can help mitigate for scenarios where slowness is reproducible.

Relates to cockroachdb/pebble#3728

Epic: none

Release note: None

pkg/storage/BUILD.bazel

@@ -28,6 +28,7 @@ go_library(
         "pebble_batch.go",
         "pebble_file_registry.go",
         "pebble_iterator.go",
+        "pebble_logger_and_tracer.go",
         "pebble_merge.go",
         "pebble_mvcc_scanner.go",
         "read_as_of_iterator.go",

pkg/storage/pebble.go

@@ -857,29 +857,6 @@ func wrapFilesystemMiddleware(opts *pebble.Options) (vfs.FS, io.Closer) {
 	return fs, closer
 }
 
-type pebbleLogger struct {
-	ctx   context.Context
-	depth int
-}
-
-var _ pebble.LoggerAndTracer = pebbleLogger{}
-
-func (l pebbleLogger) Infof(format string, args ...interface{}) {
-	log.Storage.InfofDepth(l.ctx, l.depth, format, args...)
-}
-
-func (l pebbleLogger) Fatalf(format string, args ...interface{}) {
-	log.Storage.FatalfDepth(l.ctx, l.depth, format, args...)
-}
-
-func (l pebbleLogger) Eventf(ctx context.Context, format string, args ...interface{}) {
-	log.Eventf(ctx, format, args...)
-}
-
-func (l pebbleLogger) IsTracingEnabled(ctx context.Context) bool {
-	return log.HasSpanOrEvent(ctx)
-}
-
 // PebbleConfig holds all configuration parameters and knobs used in setting up
 // a new Pebble instance.
 type PebbleConfig struct {

pkg/storage/pebble_logger_and_tracer.go

@@ -0,0 +1,50 @@
+// Copyright 2024 The Cockroach Authors.
+//
+// Use of this software is governed by the Business Source License
+// included in the file licenses/BSL.txt.
+//
+// As of the Change Date specified in that file, in accordance with
+// the Business Source License, use of this software will be governed
+// by the Apache License, Version 2.0, included in the file
+// licenses/APL.txt.
+
+package storage
+
+import (
+	"context"
+
+	"github.com/cockroachdb/cockroach/pkg/util/log"
+	"github.com/cockroachdb/pebble"
+)
+
+type pebbleLogger struct {
+	ctx   context.Context
+	depth int
+}
+
+var _ pebble.LoggerAndTracer = pebbleLogger{}
+
+func (l pebbleLogger) Infof(format string, args ...interface{}) {
+	log.Storage.InfofDepth(l.ctx, l.depth, format, args...)
+}
+
+func (l pebbleLogger) Fatalf(format string, args ...interface{}) {
+	log.Storage.FatalfDepth(l.ctx, l.depth, format, args...)
+}
+
+// pebble.LoggerAndTracer does not expose verbosity levels in its logging
+// interface, and Pebble logs go to a separate STORAGE channel.
+//
+// The tracing part of the interface is meant for user-facing activities, so
+// in addition to outputting the event when tracing is enabled, we also log.
+// The eventAlsoLogVerbosityLevel of 2 is chosen semi-arbitrarily since this
+// is the only verbosity level in this file.
+const eventAlsoLogVerbosityLevel = 2
+
+func (l pebbleLogger) Eventf(ctx context.Context, format string, args ...interface{}) {
+	log.VEventf(ctx, eventAlsoLogVerbosityLevel, format, args...)
+}
+
+func (l pebbleLogger) IsTracingEnabled(ctx context.Context) bool {
+	return log.HasSpanOrEvent(ctx) || log.ExpensiveLogEnabled(ctx, eventAlsoLogVerbosityLevel)
+}

pkg/storage/pebble_test.go

@@ -13,8 +13,10 @@ package storage
 import (
 	"context"
 	"fmt"
+	"math"
 	"math/rand"
 	"path/filepath"
+	"regexp"
 	"runtime"
 	"strings"
 	"sync/atomic"
@@ -1597,3 +1599,81 @@ func TestCompactionConcurrencyEnvVars(t *testing.T) {
 			})
 	}
 }
+
+// delayFS injects a delay on each read.
+type delayFS struct {
+	vfs.FS
+}
+
+func (fs delayFS) Open(name string, opts ...vfs.OpenOption) (vfs.File, error) {
+	f, err := fs.FS.Open(name, opts...)
+	if err != nil {
+		return nil, err
+	}
+	return delayFile{File: f}, nil
+}
+
+type delayFile struct {
+	vfs.File
+}
+
+func (f delayFile) ReadAt(p []byte, off int64) (n int, err error) {
+	time.Sleep(10 * time.Millisecond)
+	return f.File.ReadAt(p, off)
+}
+
+func TestPebbleLoggingSlowReads(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+
+	s := log.ScopeWithoutShowLogs(t)
+	prevVModule := log.GetVModule()
+	_ = log.SetVModule("pebble_logger_and_tracer=2")
+	defer func() { _ = log.SetVModule(prevVModule) }()
+	defer s.Close(t)
+
+	ctx := context.Background()
+	testStartTs := timeutil.Now()
+
+	memFS := vfs.NewMem()
+	dFS := delayFS{FS: memFS}
+	loc := MakeLocation("", dFS)
+	// No block cache, so all reads go to FS.
+	db, err := Open(ctx, loc, cluster.MakeClusterSettings(), func(cfg *engineConfig) error {
+		cfg.cacheSize = nil
+		return nil
+	})
+	require.NoError(t, err)
+	defer db.Close()
+	// Write some data and flush to disk.
+	ts1 := hlc.Timestamp{WallTime: 1}
+	k1 := MVCCKey{Key: []byte("a"), Timestamp: ts1}
+	v1 := MVCCValue{Value: roachpb.MakeValueFromString("a1")}
+	require.NoError(t, db.PutMVCC(k1, v1))
+	require.NoError(t, db.Flush())
+	// Read the data.
+	require.NoError(t, db.MVCCIterate(roachpb.Key("a"), roachpb.Key("b"),
+		MVCCKeyIterKind, IterKeyTypePointsOnly,
+		func(MVCCKeyValue, MVCCRangeKeyStack) error {
+			return nil
+		}))
+
+	// Grab the logs and count the slow read entries.
+	log.FlushFiles()
+	entries, err := log.FetchEntriesFromFiles(testStartTs.UnixNano(),
+		math.MaxInt, 2000,
+		regexp.MustCompile(`pebble_logger_and_tracer\.go`),
+		log.WithMarkedSensitiveData)
+	require.NoError(t, err)
+
+	// There should be some entries like the following:
+	// I240708 14:47:54.610060 12 storage/pebble_logger_and_tracer.go:49  [-] 15  reading 32 bytes took 11.246041ms
+	slowReadRegexp, err := regexp.Compile("reading .* bytes took .*")
+	require.NoError(t, err)
+	slowCount := 0
+	for i := range entries {
+		if slowReadRegexp.MatchString(entries[i].Message) {
+			slowCount++
+		}
+	}
+	require.Less(t, 0, slowCount)
+}

pkg/storage/pebbleiter/crdb_test_on.go

@@ -132,7 +132,7 @@ func (i *assertionIter) RangeBounds() ([]byte, []byte) {
 		panic(errors.AssertionFailedf("RangeBounds() called on !Valid() pebble.Iterator"))
 	}
 	if _, hasRange := i.Iterator.HasPointAndRange(); !hasRange {
-		panic(errors.AssertionFailedf("RangeBounds() called on pebble.Iterator without range keys"))
+		return nil, nil
 	}
 	// See maybeSaveAndMangleRangeKeyBufs for where these are saved.
 	j := i.rangeKeyBufs.idx