log: reduce allocations

Use a bytes.Buffer in log writing instead of string concatenation.
Should reduce the number of allocations significantly.

R=rsc, r2
CC=golang-dev
https://golang.org/cl/2417042

diff --git a/src/pkg/log/log.go b/src/pkg/log/log.go
index 1978358c2844ba4686e170990c84eced2b355f80..74602d93c69b5a75dd6dba79521debe470d7bc9a 100644 (file)
--- a/src/pkg/log/log.go
+++ b/src/pkg/log/log.go
@@ -14,6 +14,7 @@
 package log
 
 import (
+       "bytes"
        "fmt"
        "io"
        "runtime"
@@ -32,7 +33,6 @@ const (
        Lmicroseconds             // microsecond resolution: 01:23:23.123123.  assumes Ltime.
        Llongfile                 // full file name and line number: /a/b/c/d.go:23
        Lshortfile                // final file name element and line number: d.go:23. overrides Llongfile
-       lallBits      = Ldate | Ltime | Lmicroseconds | Llongfile | Lshortfile
 )
 
 // Logger represents an active logging object.
@@ -55,11 +55,13 @@ var (
        stdout = New(os.Stdout, "", Ldate|Ltime) // Deprecated.
 )
 
-// Cheap integer to fixed-width decimal ASCII.  Use a negative width to avoid zero-padding
-func itoa(i int, wid int) string {
+// Cheap integer to fixed-width decimal ASCII.  Give a negative width to avoid zero-padding.
+// Knows the buffer has capacity.
+func itoa(buf *bytes.Buffer, i int, wid int) {
        var u uint = uint(i)
        if u == 0 && wid <= 1 {
-               return "0"
+               buf.WriteByte('0')
+               return
        }
 
        // Assemble decimal in reverse order.
@@ -71,22 +73,36 @@ func itoa(i int, wid int) string {
                b[bp] = byte(u%10) + '0'
        }
 
-       return string(b[bp:])
+       // avoid slicing b to avoid an allocation.
+       for bp < len(b) {
+               buf.WriteByte(b[bp])
+               bp++
+       }
 }
 
-func (l *Logger) formatHeader(ns int64, calldepth int) string {
-       h := l.prefix
+func (l *Logger) formatHeader(buf *bytes.Buffer, ns int64, calldepth int) {
+       buf.WriteString(l.prefix)
        if l.flag&(Ldate|Ltime|Lmicroseconds) != 0 {
                t := time.SecondsToLocalTime(ns / 1e9)
-               if l.flag&(Ldate) != 0 {
-                       h += itoa(int(t.Year), 4) + "/" + itoa(t.Month, 2) + "/" + itoa(t.Day, 2) + " "
+               if l.flag&Ldate != 0 {
+                       itoa(buf, int(t.Year), 4)
+                       buf.WriteByte('/')
+                       itoa(buf, int(t.Month), 2)
+                       buf.WriteByte('/')
+                       itoa(buf, int(t.Day), 2)
+                       buf.WriteByte(' ')
                }
                if l.flag&(Ltime|Lmicroseconds) != 0 {
-                       h += itoa(t.Hour, 2) + ":" + itoa(t.Minute, 2) + ":" + itoa(t.Second, 2)
+                       itoa(buf, int(t.Hour), 2)
+                       buf.WriteByte(':')
+                       itoa(buf, int(t.Minute), 2)
+                       buf.WriteByte(':')
+                       itoa(buf, int(t.Second), 2)
                        if l.flag&Lmicroseconds != 0 {
-                               h += "." + itoa(int(ns%1e9)/1e3, 6)
+                               buf.WriteByte('.')
+                               itoa(buf, int(ns%1e9)/1e3, 6)
                        }
-                       h += " "
+                       buf.WriteByte(' ')
                }
        }
        if l.flag&(Lshortfile|Llongfile) != 0 {
@@ -106,9 +122,11 @@ func (l *Logger) formatHeader(ns int64, calldepth int) string {
                        file = "???"
                        line = 0
                }
-               h += file + ":" + itoa(line, -1) + ": "
+               buf.WriteString(file)
+               buf.WriteByte(':')
+               itoa(buf, line, -1)
+               buf.WriteString(": ")
        }
-       return h
 }
 
 // Output writes the output for a logging event.  The string s contains the text to print after
@@ -116,12 +134,13 @@ func (l *Logger) formatHeader(ns int64, calldepth int) string {
 // at the moment on all pre-defined paths it will be 2.
 func (l *Logger) Output(calldepth int, s string) os.Error {
        now := time.Nanoseconds() // get this early.
-       newline := "\n"
-       if len(s) > 0 && s[len(s)-1] == '\n' {
-               newline = ""
+       buf := new(bytes.Buffer)
+       l.formatHeader(buf, now, calldepth+1)
+       buf.WriteString(s)
+       if len(s) > 0 && s[len(s)-1] != '\n' {
+               buf.WriteByte('\n')
        }
-       s = l.formatHeader(now, calldepth+1) + s + newline
-       _, err := io.WriteString(l.out, s)
+       _, err := std.out.Write(buf.Bytes())
        return err
 }
 
@@ -143,7 +162,7 @@ func SetOutput(w io.Writer) {
 
 // SetFlags sets the output flags for the standard logger.
 func SetFlags(flag int) {
-       std.flag = flag & lallBits
+       std.flag = flag
 }
 
 // SetPrefix sets the output prefix for the standard logger.

diff --git a/src/pkg/log/log_test.go b/src/pkg/log/log_test.go
index a5b1f281debf52a4e7d94c21d95f7eeffa72ac88..0a5753f3a911515e1aeefdf6ae3c59f2e53da59e 100644 (file)
--- a/src/pkg/log/log_test.go
+++ b/src/pkg/log/log_test.go
@@ -8,6 +8,7 @@ package log
 
 import (
        "bytes"
+       "os"
        "regexp"
        "testing"
 )
@@ -16,7 +17,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         = `(53|55):` // must update if the calls to l.Printf / l.Print below move
+       Rline         = `(54|56):` // 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
 )
@@ -64,6 +65,7 @@ func testPrint(t *testing.T, flag int, prefix string, pattern string, useFormat
        if !matched {
                t.Errorf("log output should match %q is %q", pattern, line)
        }
+       SetOutput(os.Stderr)
 }
 
 func TestAll(t *testing.T) {