log: reduce lock contention

Logger.Log methods are called in a highly concurrent manner in many servers.
Acquiring a lock in each method call results in high lock contention,
especially since each lock covers a non-trivial amount of work
(e.g., formatting the header and outputting to the writer).

Changes made:
* Modify the Logger to use atomics so that the header formatting
  can be moved out of the critical lock section.
  Acquiring the flags does not occur in the same critical section
  as outputting to the underlying writer, so this introduces
  a very slight consistency instability where concurrently calling
  multiple Logger.Output along with Logger.SetFlags may cause
  the older flags to be used by some ongoing Logger.Output calls
  even after Logger.SetFlags has returned.
* Use a sync.Pool to buffer the intermediate buffer.
  This approach is identical to how fmt does it,
  with the same max cap mitigation for golang#23199.
* Only protect outputting to the underlying writer with a lock
  to ensure serialized ordering of output.

Performance:
	name           old time/op  new time/op  delta
	Concurrent-24  19.9µs ± 2%   8.3µs ± 1%  -58.37%  (p=0.000 n=10+10)

Updates golang#19438

Change-Id: I091beb7431d8661976a6c01cdb0d145e37fe3d22
Reviewed-on: https://go-review.googlesource.com/c/go/+/464344
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Joseph Tsai <joetsai@digital-static.net>
Reviewed-by: Ian Lance Taylor <iant@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>

src/log/log.go

@@ -54,12 +54,12 @@ const (
 // the Writer's Write method. A Logger can be used simultaneously from
 // multiple goroutines; it guarantees to serialize access to the Writer.
 type Logger struct {
-	mu        sync.Mutex  // ensures atomic writes; protects the following fields
-	prefix    string      // prefix on each line to identify the logger (but see Lmsgprefix)
-	flag      int         // properties
-	out       io.Writer   // destination for output
-	buf       []byte      // for accumulating text to write
-	isDiscard atomic.Bool // whether out == io.Discard
+	outMu sync.Mutex
+	out   io.Writer // destination for output
+
+	prefix    atomic.Pointer[string] // prefix on each line to identify the logger (but see Lmsgprefix)
+	flag      atomic.Int32           // properties
+	isDiscard atomic.Bool
 }
 
 // New creates a new Logger. The out variable sets the
@@ -68,17 +68,17 @@ type Logger struct {
 // after the log header if the Lmsgprefix flag is provided.
 // The flag argument defines the logging properties.
 func New(out io.Writer, prefix string, flag int) *Logger {
-	l := &Logger{out: out, prefix: prefix, flag: flag}
-	if out == io.Discard {
-		l.isDiscard.Store(true)
-	}
+	l := new(Logger)
+	l.SetOutput(out)
+	l.SetPrefix(prefix)
+	l.SetFlags(flag)
 	return l
 }
 
 // SetOutput sets the output destination for the logger.
 func (l *Logger) SetOutput(w io.Writer) {
-	l.mu.Lock()
-	defer l.mu.Unlock()
+	l.outMu.Lock()
+	defer l.outMu.Unlock()
 	l.out = w
 	l.isDiscard.Store(w == io.Discard)
 }
@@ -110,15 +110,15 @@ func itoa(buf *[]byte, i int, wid int) {
 //   - date and/or time (if corresponding flags are provided),
 //   - file and line number (if corresponding flags are provided),
 //   - l.prefix (if it's not blank and Lmsgprefix is set).
-func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
-	if l.flag&Lmsgprefix == 0 {
-		*buf = append(*buf, l.prefix...)
+func formatHeader(buf *[]byte, t time.Time, prefix string, flag int, file string, line int) {
+	if flag&Lmsgprefix == 0 {
+		*buf = append(*buf, prefix...)
 	}
-	if l.flag&(Ldate|Ltime|Lmicroseconds) != 0 {
-		if l.flag&LUTC != 0 {
+	if flag&(Ldate|Ltime|Lmicroseconds) != 0 {
+		if flag&LUTC != 0 {
 			t = t.UTC()
 		}
-		if l.flag&Ldate != 0 {
+		if flag&Ldate != 0 {
 			year, month, day := t.Date()
 			itoa(buf, year, 4)
 			*buf = append(*buf, '/')
@@ -127,22 +127,22 @@ func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
 			itoa(buf, day, 2)
 			*buf = append(*buf, ' ')
 		}
-		if l.flag&(Ltime|Lmicroseconds) != 0 {
+		if flag&(Ltime|Lmicroseconds) != 0 {
 			hour, min, sec := t.Clock()
 			itoa(buf, hour, 2)
 			*buf = append(*buf, ':')
 			itoa(buf, min, 2)
 			*buf = append(*buf, ':')
 			itoa(buf, sec, 2)
-			if l.flag&Lmicroseconds != 0 {
+			if flag&Lmicroseconds != 0 {
 				*buf = append(*buf, '.')
 				itoa(buf, t.Nanosecond()/1e3, 6)
 			}
 			*buf = append(*buf, ' ')
 		}
 	}
-	if l.flag&(Lshortfile|Llongfile) != 0 {
-		if l.flag&Lshortfile != 0 {
+	if flag&(Lshortfile|Llongfile) != 0 {
+		if flag&Lshortfile != 0 {
 			short := file
 			for i := len(file) - 1; i > 0; i-- {
 				if file[i] == '/' {
@@ -157,11 +157,32 @@ func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
 		itoa(buf, line, -1)
 		*buf = append(*buf, ": "...)
 	}
-	if l.flag&Lmsgprefix != 0 {
-		*buf = append(*buf, l.prefix...)
+	if flag&Lmsgprefix != 0 {
+		*buf = append(*buf, prefix...)
 	}
 }
 
+var bufferPool = sync.Pool{New: func() any { return new([]byte) }}
+
+func getBuffer() *[]byte {
+	p := bufferPool.Get().(*[]byte)
+	*p = (*p)[:0]
+	return p
+}
+
+func putBuffer(p *[]byte) {
+	// Proper usage of a sync.Pool requires each entry to have approximately
+	// the same memory cost. To obtain this property when the stored type
+	// contains a variably-sized buffer, we add a hard limit on the maximum buffer
+	// to place back in the pool.
+	//
+	// See https://go.dev/issue/23199
+	if cap(*p) > 64<<10 {
+		*p = nil
+	}
+	bufferPool.Put(p)
+}
+
 // Output writes the output for a logging event. The string s contains
 // the text to print after the prefix specified by the flags of the
 // Logger. A newline is appended if the last character of s is not
@@ -170,28 +191,34 @@ func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
 // paths it will be 2.
 func (l *Logger) Output(calldepth int, s string) error {
 	now := time.Now() // get this early.
+
+	// Load prefix and flag once so that their value is consistent within
+	// this call regardless of any concurrent changes to their value.
+	prefix := l.Prefix()
+	flag := l.Flags()
+
 	var file string
 	var line int
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	if l.flag&(Lshortfile|Llongfile) != 0 {
-		// Release lock while getting caller info - it's expensive.
-		l.mu.Unlock()
+	if flag&(Lshortfile|Llongfile) != 0 {
 		var ok bool
 		_, file, line, ok = runtime.Caller(calldepth)
 		if !ok {
 			file = "???"
 			line = 0
 		}
-		l.mu.Lock()
 	}
-	l.buf = l.buf[:0]
-	l.formatHeader(&l.buf, now, file, line)
-	l.buf = append(l.buf, s...)
+
+	buf := getBuffer()
+	defer putBuffer(buf)
+	formatHeader(buf, now, prefix, flag, file, line)
+	*buf = append(*buf, s...)
 	if len(s) == 0 || s[len(s)-1] != '\n' {
-		l.buf = append(l.buf, '\n')
+		*buf = append(*buf, '\n')
 	}
-	_, err := l.out.Write(l.buf)
+
+	l.outMu.Lock()
+	defer l.outMu.Unlock()
+	_, err := l.out.Write(*buf)
 	return err
 }
 
@@ -264,37 +291,32 @@ func (l *Logger) Panicln(v ...any) {
 // Flags returns the output flags for the logger.
 // The flag bits are Ldate, Ltime, and so on.
 func (l *Logger) Flags() int {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	return l.flag
+	return int(l.flag.Load())
 }
 
 // SetFlags sets the output flags for the logger.
 // The flag bits are Ldate, Ltime, and so on.
 func (l *Logger) SetFlags(flag int) {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	l.flag = flag
+	l.flag.Store(int32(flag))
 }
 
 // Prefix returns the output prefix for the logger.
 func (l *Logger) Prefix() string {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	return l.prefix
+	if p := l.prefix.Load(); p != nil {
+		return *p
+	}
+	return ""
 }
 
 // SetPrefix sets the output prefix for the logger.
 func (l *Logger) SetPrefix(prefix string) {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	l.prefix = prefix
+	l.prefix.Store(&prefix)
 }
 
 // Writer returns the output destination for the logger.
 func (l *Logger) Writer() io.Writer {
-	l.mu.Lock()
-	defer l.mu.Unlock()
+	l.outMu.Lock()
+	defer l.outMu.Unlock()
 	return l.out
 }
 

src/log/log_test.go

@@ -12,7 +12,9 @@ import (
 	"io"
 	"os"
 	"regexp"
+	"runtime"
 	"strings"
+	"sync"
 	"testing"
 	"time"
 )
@@ -21,7 +23,7 @@ const (
 	Rdate         = `[0-9][0-9][0-9][0-9]/[0-9][0-9]/[0-9][0-9]`
 	Rtime         = `[0-9][0-9]:[0-9][0-9]:[0-9][0-9]`
 	Rmicroseconds = `\.[0-9][0-9][0-9][0-9][0-9][0-9]`
-	Rline         = `(61|63):` // must update if the calls to l.Printf / l.Print below move
+	Rline         = `(63|65):` // must update if the calls to l.Printf / l.Print below move
 	Rlongfile     = `.*/[A-Za-z0-9_\-]+\.go:` + Rline
 	Rshortfile    = `[A-Za-z0-9_\-]+\.go:` + Rline
 )
@@ -98,14 +100,20 @@ func TestOutput(t *testing.T) {
 	}
 }
 
+func TestNonNewLogger(t *testing.T) {
+	var l Logger
+	l.SetOutput(new(bytes.Buffer)) // minimal work to initialize a Logger
+	l.Print("hello")
+}
+
 func TestOutputRace(t *testing.T) {
 	var b bytes.Buffer
 	l := New(&b, "", 0)
 	for i := 0; i < 100; i++ {
 		go func() {
 			l.SetFlags(0)
+			l.Output(0, "")
 		}()
-		l.Output(0, "")
 	}
 }
 
@@ -224,3 +232,26 @@ func BenchmarkPrintlnNoFlags(b *testing.B) {
 		l.Println(testString)
 	}
 }
+
+// discard is identical to io.Discard,
+// but copied here to avoid the io.Discard optimization in Logger.
+type discard struct{}
+
+func (discard) Write(p []byte) (int, error) {
+	return len(p), nil
+}
+
+func BenchmarkConcurrent(b *testing.B) {
+	l := New(discard{}, "prefix: ", Ldate|Ltime|Lmicroseconds|Llongfile|Lmsgprefix)
+	var group sync.WaitGroup
+	for i := runtime.NumCPU(); i > 0; i-- {
+		group.Add(1)
+		go func() {
+			for i := 0; i < b.N; i++ {
+				l.Output(0, "hello, world!")
+			}
+			defer group.Done()
+		}()
+	}
+	group.Wait()
+}