diff --git a/pkg/storage/pebble_logger_and_tracer.go b/pkg/storage/pebble_logger_and_tracer.go index 033907961be8..6e52f8978d32 100644 --- a/pkg/storage/pebble_logger_and_tracer.go +++ b/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) } diff --git a/pkg/storage/pebble_test.go b/pkg/storage/pebble_test.go index 7787a845b648..bb59c7eb4bb1 100644 --- a/pkg/storage/pebble_test.go +++ b/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) + }) } diff --git a/pkg/util/log/log.go b/pkg/util/log/log.go index c4482834839b..2b9b9650fd36 100644 --- a/pkg/util/log/log.go +++ b/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