Merge #29017

29017: util/log: Speed up vmodule support and warn about it in help text r=a-robinson a=a-robinson

It's possible that with the second commit the help text change is no longer needed, but I'm curious what you think about that. I haven't tried re-running tpc-c 10k with this, so while I'm pretty sure this is a lot better I don't know how much of a performance hit there still is.

Co-authored-by: Alex Robinson <[email protected]>

pkg/util/log/clog.go

@@ -33,6 +33,7 @@ import (
 	"runtime/debug"
 	"strconv"
 	"strings"
+	"sync"
 	"sync/atomic"
 	"time"
 
@@ -582,6 +583,11 @@ func init() {
 	logging.stderrThreshold = Severity_INFO
 	logging.fileThreshold = Severity_INFO
 
+	logging.pcsPool = sync.Pool{
+		New: func() interface{} {
+			return [1]uintptr{}
+		},
+	}
 	logging.prefix = program
 	logging.setVState(0, nil, false)
 	logging.gcNotify = make(chan struct{}, 1)
@@ -673,8 +679,9 @@ type loggingT struct {
 	file flushSyncWriter
 	// syncWrites if true calls file.Flush and file.Sync on every log write.
 	syncWrites bool
-	// pcs is used in V to avoid an allocation when computing the caller's PC.
-	pcs [1]uintptr
+	// pcsPool maintains a set of [1]uintptr buffers to be used in V to avoid
+	// allocating every time we compute the caller's PC.
+	pcsPool sync.Pool
 	// vmap is a cache of the V Level for each V() call site, identified by PC.
 	// It is wiped whenever the vmodule flag changes state.
 	vmap map[uintptr]level
@@ -1388,27 +1395,30 @@ func VDepth(l int32, depth int) bool {
 		return true
 	}
 
-	// It's off globally but it vmodule may still be set.
+	// It's off globally but vmodule may still be set.
 	// Here is another cheap but safe test to see if vmodule is enabled.
 	if atomic.LoadInt32(&logging.filterLength) > 0 {
-		// Now we need a proper lock to use the logging structure. The pcs field
-		// is shared so we must lock before accessing it. This is fairly expensive,
-		// but if V logging is enabled we're slow anyway.
-		logging.mu.Lock()
+		// Grab a buffer to use for reading the program counter. Keeping the
+		// interface{} version around to Put back into the pool rather than
+		// Put-ting the array saves an interface allocation.
+		poolObj := logging.pcsPool.Get()
+		pcs := poolObj.([1]uintptr)
 		// We prefer not to use a defer in this function, which can be used in hot
 		// paths, because a defer anywhere in the body of a function causes a call
-		// to runtime.deferreturn at the end of that function. This call has a
+		// to runtime.deferreturn at the end of that function, which has a
 		// measurable performance penalty when in a very hot path.
-		// defer logging.mu.Unlock()
-		if runtime.Callers(2+depth, logging.pcs[:]) == 0 {
-			logging.mu.Unlock()
+		// defer logging.pcsPool.Put(pcs)
+		if runtime.Callers(2+depth, pcs[:]) == 0 {
+			logging.pcsPool.Put(poolObj)
 			return false
 		}
-		v, ok := logging.vmap[logging.pcs[0]]
+		logging.mu.Lock()
+		v, ok := logging.vmap[pcs[0]]
 		if !ok {
-			v = logging.setV(logging.pcs[0])
+			v = logging.setV(pcs[0])
 		}
 		logging.mu.Unlock()
+		logging.pcsPool.Put(poolObj)
 		return v >= level(l)
 	}
 	return false

pkg/util/log/clog_test.go

@@ -812,3 +812,14 @@ func BenchmarkHeader(b *testing.B) {
 		logging.putBuffer(buf)
 	}
 }
+
+func BenchmarkVDepthWithVModule(b *testing.B) {
+	if err := SetVModule("craigthecockroach=5"); err != nil {
+		b.Fatal(err)
+	}
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			_ = VDepth(1, 1)
+		}
+	})
+}

pkg/util/log/logflags/logflags.go

@@ -84,8 +84,8 @@ func InitFlags(
 ) {
 	flag.BoolVar(nocolor, NoColorName, *nocolor, "disable standard error log colorization")
 	flag.BoolVar(noRedirectStderr, NoRedirectStderrName, *noRedirectStderr, "disable redirect of stderr to the log file")
-	flag.Var(verbosity, VerbosityName, "log level for V logs")
-	flag.Var(vmodule, VModuleName, "comma-separated list of pattern=N settings for file-filtered logging")
+	flag.Var(verbosity, VerbosityName, "log level for V logs (significantly increases log output)")
+	flag.Var(vmodule, VModuleName, "comma-separated list of pattern=N settings for file-filtered logging (significantly hurts performance)")
 	flag.Var(traceLocation, LogBacktraceAtName, "when logging hits line file:N, emit a stack trace")
 	flag.Var(logDir, LogDirName, "if non-empty, write log files in this directory")
 	flag.BoolVar(showLogs, ShowLogsName, *showLogs, "print logs instead of saving them in files")