log: make use of fmt.Append functionality

Since log is already responsible for managing its own buffers
it is unfortunate that it calls fmt.Sprintf, which allocates,
only to append that intermediate string to another buffer.
Instead, use the new fmt.Append variants and avoid the allocation.

We modify Logger.Output to wrap an internal Logger.output,
which can be configured to use a particular append function.
Logger.output is called from all the other functionality instead.

This has the further advantage of simplifying the isDiscard check,
which occurs to avoid the costly fmt.Print call.
We coalesce all 6 checks as just 1 check in Logger.output.

Also, swap the declaration order of Logger.Print and Logger.Printf
to match the ordering elsewhere in the file.

Performance:
	name               old time/op    new time/op    delta
	Println            188ns ± 2%     172ns ± 4%    -8.39%  (p=0.000 n=10+10)
	PrintlnNoFlags     139ns ± 1%     116ns ± 1%   -16.71%  (p=0.000 n=9+9)

	name               old allocs/op  new allocs/op  delta
	Println             1.00 ± 0%      0.00       -100.00%  (p=0.000 n=10+10)
	PrintlnNoFlags      1.00 ± 0%      0.00       -100.00%  (p=0.000 n=10+10)

Change-Id: I79d0ee404df848beb3626fe863ccc73a3e2eb325
Reviewed-on: https://go-review.googlesource.com/c/go/+/464345
Reviewed-by: Rob Pike <[email protected]>
Reviewed-by: Ian Lance Taylor <[email protected]>
Reviewed-by: Bryan Mills <[email protected]>
Run-TryBot: Joseph Tsai <[email protected]>
TryBot-Result: Gopher Robot <[email protected]>

Author: dsnet

src/log/log.go

@@ -190,6 +190,17 @@ func putBuffer(p *[]byte) {
 // provided for generality, although at the moment on all pre-defined
 // paths it will be 2.
 func (l *Logger) Output(calldepth int, s string) error {
+	calldepth++ // +1 for this frame.
+	return l.output(calldepth, func(b []byte) []byte {
+		return append(b, s...)
+	})
+}
+
+func (l *Logger) output(calldepth int, appendOutput func([]byte) []byte) error {
+	if l.isDiscard.Load() {
+		return nil
+	}
+
 	now := time.Now() // get this early.
 
 	// Load prefix and flag once so that their value is consistent within
@@ -211,7 +222,9 @@ func (l *Logger) Output(calldepth int, s string) error {
 	buf := getBuffer()
 	defer putBuffer(buf)
 	formatHeader(buf, now, prefix, flag, file, line)
-	*buf = append(*buf, s...)
+	headerLen := len(*buf)
+	*buf = appendOutput(*buf)
+	s := (*buf)[headerLen:]
 	if len(s) == 0 || s[len(s)-1] != '\n' {
 		*buf = append(*buf, '\n')
 	}
@@ -222,31 +235,28 @@ func (l *Logger) Output(calldepth int, s string) error {
 	return err
 }
 
-// Printf calls l.Output to print to the logger.
-// Arguments are handled in the manner of fmt.Printf.
-func (l *Logger) Printf(format string, v ...any) {
-	if l.isDiscard.Load() {
-		return
-	}
-	l.Output(2, fmt.Sprintf(format, v...))
-}
-
 // Print calls l.Output to print to the logger.
 // Arguments are handled in the manner of fmt.Print.
 func (l *Logger) Print(v ...any) {
-	if l.isDiscard.Load() {
-		return
-	}
-	l.Output(2, fmt.Sprint(v...))
+	l.output(2, func(b []byte) []byte {
+		return fmt.Append(b, v...)
+	})
+}
+
+// Printf calls l.Output to print to the logger.
+// Arguments are handled in the manner of fmt.Printf.
+func (l *Logger) Printf(format string, v ...any) {
+	l.output(2, func(b []byte) []byte {
+		return fmt.Appendf(b, format, v...)
+	})
 }
 
 // Println calls l.Output to print to the logger.
 // Arguments are handled in the manner of fmt.Println.
 func (l *Logger) Println(v ...any) {
-	if l.isDiscard.Load() {
-		return
-	}
-	l.Output(2, fmt.Sprintln(v...))
+	l.output(2, func(b []byte) []byte {
+		return fmt.Appendln(b, v...)
+	})
 }
 
 // Fatal is equivalent to l.Print() followed by a call to os.Exit(1).
@@ -357,28 +367,25 @@ func Writer() io.Writer {
 // Print calls Output to print to the standard logger.
 // Arguments are handled in the manner of fmt.Print.
 func Print(v ...any) {
-	if std.isDiscard.Load() {
-		return
-	}
-	std.Output(2, fmt.Sprint(v...))
+	std.output(2, func(b []byte) []byte {
+		return fmt.Append(b, v...)
+	})
 }
 
 // Printf calls Output to print to the standard logger.
 // Arguments are handled in the manner of fmt.Printf.
 func Printf(format string, v ...any) {
-	if std.isDiscard.Load() {
-		return
-	}
-	std.Output(2, fmt.Sprintf(format, v...))
+	std.output(2, func(b []byte) []byte {
+		return fmt.Appendf(b, format, v...)
+	})
 }
 
 // Println calls Output to print to the standard logger.
 // Arguments are handled in the manner of fmt.Println.
 func Println(v ...any) {
-	if std.isDiscard.Load() {
-		return
-	}
-	std.Output(2, fmt.Sprintln(v...))
+	std.output(2, func(b []byte) []byte {
+		return fmt.Appendln(b, v...)
+	})
 }
 
 // Fatal is equivalent to Print() followed by a call to os.Exit(1).

src/log/log_test.go

@@ -217,6 +217,7 @@ func BenchmarkPrintln(b *testing.B) {
 	const testString = "test"
 	var buf bytes.Buffer
 	l := New(&buf, "", LstdFlags)
+	b.ReportAllocs()
 	for i := 0; i < b.N; i++ {
 		buf.Reset()
 		l.Println(testString)
@@ -227,6 +228,7 @@ func BenchmarkPrintlnNoFlags(b *testing.B) {
 	const testString = "test"
 	var buf bytes.Buffer
 	l := New(&buf, "", 0)
+	b.ReportAllocs()
 	for i := 0; i < b.N; i++ {
 		buf.Reset()
 		l.Println(testString)
@@ -255,3 +257,11 @@ func BenchmarkConcurrent(b *testing.B) {
 	}
 	group.Wait()
 }
+
+func BenchmarkDiscard(b *testing.B) {
+	l := New(io.Discard, "", LstdFlags|Lshortfile)
+	b.ReportAllocs()
+	for i := 0; i < b.N; i++ {
+		l.Printf("processing %d objects from bucket %q", 1234, "fizzbuzz")
+	}
+}