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 <r@golang.org>
Reviewed-by: Ian Lance Taylor <iant@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>
Run-TryBot: Joseph Tsai <joetsai@digital-static.net>
TryBot-Result: Gopher Robot <gobot@golang.org>

diff --git a/src/log/log.go b/src/log/log.go
index 9e38b6ed6968e77945fbac02236dd7975012c946..78458c19f394d26c7467d7c0d77f7e7c774883a7 100644 (file)
--- a/src/log/log.go
+++ b/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).

diff --git a/src/log/log_test.go b/src/log/log_test.go
index c212b60554feef44c0e9a08cfa4adc8c0be72a2a..ea7e7917b8380a0338bd7cd8edcfd2b90213e205 100644 (file)
--- a/src/log/log_test.go
+++ b/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")
+       }
+}