log,storage: add ExpensiveLogEnabledVDepth for use in pebbleLogger

Relates to cockroachdb/pebble#3728

Epic: none

Release note (ops change): Verbose logging of slow pebble reads is no
longer enabled via --vmodule=pebble_logger_and_tracer=2, where
pebble_logger_and_tracer contains the CockroachDB implementation of the
logger needed by Pebble, and instead requires listing the Pebble files
containing the log statements, specifically --vmodule=reader=2,table=2.

pkg/storage/pebble_logger_and_tracer.go

@@ -46,9 +46,9 @@ func (l pebbleLogger) Errorf(format string, args ...interface{}) {
 const eventAlsoLogVerbosityLevel = 2
 
 func (l pebbleLogger) Eventf(ctx context.Context, format string, args ...interface{}) {
-	log.VEventf(ctx, eventAlsoLogVerbosityLevel, format, args...)
+	log.VEventfDepth(ctx, l.depth, eventAlsoLogVerbosityLevel, format, args...)
 }
 
 func (l pebbleLogger) IsTracingEnabled(ctx context.Context) bool {
-	return log.HasSpan(ctx) || log.ExpensiveLogEnabled(ctx, eventAlsoLogVerbosityLevel)
+	return log.HasSpan(ctx) || log.ExpensiveLogEnabledVDepth(ctx, l.depth, eventAlsoLogVerbosityLevel)
 }

pkg/storage/pebble_test.go

@@ -1548,55 +1548,66 @@ func (f delayFile) ReadAt(p []byte, off int64) (n int, err error) {
 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}
-	e, err := fs.InitEnv(context.Background(), dFS, "" /* dir */, fs.EnvConfig{}, nil /* statsCollector */)
-	require.NoError(t, err)
-	// No block cache, so all reads go to FS.
-	db, err := Open(ctx, e, 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(ctx, roachpb.Key("a"), roachpb.Key("b"), MVCCKeyIterKind, IterKeyTypePointsOnly,
-		fs.UnknownReadCategory, func(MVCCKeyValue, MVCCRangeKeyStack) error {
+	testFunc := func(t *testing.T, fileStr string) int {
+		s := log.ScopeWithoutShowLogs(t)
+		prevVModule := log.GetVModule()
+		_ = log.SetVModule(fileStr + "=2")
+		defer func() { _ = log.SetVModule(prevVModule) }()
+		defer s.Close(t)
+
+		ctx := context.Background()
+		testStartTs := timeutil.Now()
+
+		memFS := vfs.NewMem()
+		dFS := delayFS{FS: memFS}
+		e, err := fs.InitEnv(context.Background(), dFS, "" /* dir */, fs.EnvConfig{}, nil /* statsCollector */)
+		require.NoError(t, err)
+		// No block cache, so all reads go to FS.
+		db, err := Open(ctx, e, cluster.MakeClusterSettings(), func(cfg *engineConfig) error {
+			cfg.cacheSize = nil
 			return nil
-		}))
-
-	// Grab the logs and count the slow read entries.
-	log.FlushFiles()
-	entries, err := log.FetchEntriesFromFiles(testStartTs.UnixNano(),
-		math.MaxInt64, 2000,
-		regexp.MustCompile(`pebble_logger_and_tracer\.go`),
-		log.WithMarkedSensitiveData)
-	require.NoError(t, err)
+		})
+		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(ctx, roachpb.Key("a"), roachpb.Key("b"), MVCCKeyIterKind, IterKeyTypePointsOnly,
+			fs.UnknownReadCategory, func(MVCCKeyValue, MVCCRangeKeyStack) error {
+				return nil
+			}))
+
+		// Grab the logs and count the slow read entries.
+		log.FlushFiles()
+		entries, err := log.FetchEntriesFromFiles(testStartTs.UnixNano(),
+			math.MaxInt64, 2000,
+			regexp.MustCompile(fileStr+`\.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++
+		// Looking for entries like the following (when fileStr is "pebble_logger_and_tracer"):
+		// 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++
+			}
+			t.Logf("%d: %s", i, entries[i].Message)
 		}
+		return slowCount
 	}
-	require.Less(t, 0, slowCount)
+	t.Run("pebble_logger_and_tracer", func(t *testing.T) {
+		slowCount := testFunc(t, "pebble_logger_and_tracer")
+		require.Equal(t, 0, slowCount)
+	})
+	t.Run("reader", func(t *testing.T) {
+		slowCount := testFunc(t, "reader")
+		require.Less(t, 0, slowCount)
+	})
 }

pkg/util/log/log.go

@@ -60,12 +60,18 @@ func V(level Level) bool {
 //	  log.VEventf(ctx, 2, msg)
 //	}
 func ExpensiveLogEnabled(ctx context.Context, level Level) bool {
+	return ExpensiveLogEnabledVDepth(ctx, 1 /* depth */, level)
+}
+
+// ExpensiveLogEnabledVDepth is like ExpensiveLogEnabled, and additionally
+// accepts a depth parameter for determining the caller's verbosity.
+func ExpensiveLogEnabledVDepth(ctx context.Context, depth int, level Level) bool {
 	if sp := tracing.SpanFromContext(ctx); sp != nil {
 		if sp.IsVerbose() || sp.Tracer().HasExternalSink() {
 			return true
 		}
 	}
-	if VDepth(level, 1 /* depth */) {
+	if VDepth(level, depth+1) {
 		return true
 	}
 	return false