pkg/log: restore lazy formatting

For a while we eagerly format log messages even if they are discarded.
This may be expensive. If the fuzzer does not deserialize programs,
logging consumes 8.7% of CPU and constantly generates garbage.
Restore lazy formatting and don't lock the mutex if caching is not enabled.

2 files changed, 58 insertions, 38 deletions

diff --git a/pkg/log/log.go b/pkg/log/log.go
index 95cdb7fc8..dc0bb4ceb 100644
--- a/pkg/log/log.go
+++ b/pkg/log/log.go
@@ -15,18 +15,20 @@ import (
 	golog "log"
 	"strings"
 	"sync"
+	"sync/atomic"
 	"time"
 )
 
 var (
-	flagV        = flag.Int("vv", 0, "verbosity")
-	mu           sync.Mutex
-	cacheMem     int
-	cacheMaxMem  int
-	cachePos     int
-	cacheEntries []string
-	instanceName string
-	prependTime  = true // for testing
+	flagV          = flag.Int("vv", 0, "verbosity")
+	mu             sync.Mutex
+	cacheMem       int
+	cacheMaxMem    int
+	cachePos       int
+	cacheEntries   []string
+	cachingEnabled atomic.Bool
+	instanceName   string
+	prependTime    = true // for testing
 )
 
 // EnableLogCaching enables in memory caching of log output.
@@ -43,6 +45,7 @@ func EnableLogCaching(maxLines, maxMem int) {
 	}
 	cacheMaxMem = maxMem
 	cacheEntries = make([]string, maxLines)
+	cachingEnabled.Store(true)
 }
 
 // Retrieves cached log output.
@@ -73,11 +76,11 @@ func V(level int) bool {
 }
 
 func Logf(v int, msg string, args ...interface{}) {
-	writeMessage(v, message("", msg, args...))
+	writeMessage(v, "", msg, args...)
 }
 
 func Errorf(msg string, args ...interface{}) {
-	writeMessage(0, message("ERROR", msg, args...))
+	writeMessage(0, "ERROR", msg, args...)
 }
 
 func Fatal(err error) {
@@ -105,36 +108,41 @@ func message(severity, msg string, args ...interface{}) string {
 	return sb.String()
 }
 
-func writeMessage(v int, msg string) {
-	mu.Lock()
-	if cacheEntries != nil && v <= 1 {
-		cacheMem -= len(cacheEntries[cachePos])
-		if cacheMem < 0 {
-			panic("log cache size underflow")
-		}
-		timeStr := ""
-		if prependTime {
-			timeStr = time.Now().Format("2006/01/02 15:04:05 ")
-		}
-		cacheEntries[cachePos] = timeStr + msg
-		cacheMem += len(cacheEntries[cachePos])
-		cachePos++
-		if cachePos == len(cacheEntries) {
-			cachePos = 0
-		}
-		for i := 0; i < len(cacheEntries)-1 && cacheMem > cacheMaxMem; i++ {
-			pos := (cachePos + i) % len(cacheEntries)
-			cacheMem -= len(cacheEntries[pos])
-			cacheEntries[pos] = ""
-		}
-		if cacheMem < 0 {
-			panic("log cache size underflow")
-		}
+func writeMessage(v int, severity, msg string, args ...interface{}) {
+	cache := v <= 1 && cachingEnabled.Load()
+	if !V(v) && !cache {
+		return
 	}
-	mu.Unlock()
-
+	text := message(severity, msg, args...)
 	if V(v) {
-		golog.Print(msg)
+		golog.Print(text)
+	}
+	if !cache {
+		return
+	}
+	mu.Lock()
+	defer mu.Unlock()
+	cacheMem -= len(cacheEntries[cachePos])
+	if cacheMem < 0 {
+		panic("log cache size underflow")
+	}
+	timeStr := ""
+	if prependTime {
+		timeStr = time.Now().Format("2006/01/02 15:04:05 ")
+	}
+	cacheEntries[cachePos] = timeStr + text
+	cacheMem += len(cacheEntries[cachePos])
+	cachePos++
+	if cachePos == len(cacheEntries) {
+		cachePos = 0
+	}
+	for i := 0; i < len(cacheEntries)-1 && cacheMem > cacheMaxMem; i++ {
+		pos := (cachePos + i) % len(cacheEntries)
+		cacheMem -= len(cacheEntries[pos])
+		cacheEntries[pos] = ""
+	}
+	if cacheMem < 0 {
+		panic("log cache size underflow")
 	}
 }
 
diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go
index 3cbbfc655..c1be24a9f 100644
--- a/pkg/log/log_test.go
+++ b/pkg/log/log_test.go
@@ -33,3 +33,15 @@ func TestCaching(t *testing.T) {
 		}
 	}
 }
+
+func TestLazy(t *testing.T) {
+	// Ensure that the format message is formatted lazily only when logging enabled.
+	Logf(1e6, "%v", noFormat{t})
+}
+
+type noFormat struct{ *testing.T }
+
+func (nf noFormat) String() string {
+	nf.T.Fatalf("must not be formatted")
+	return ""
+}