internal/telemetry: a faster logging exporter

Moved printing directly inside the exporter,
which yields a massive reduction in allocations.

name                old time/op    new time/op    delta
/Log-8                41.7µs ± 1%    13.6µs ± 2%  -67.48%

name                old alloc/op   new alloc/op   delta
/Log-8                20.9kB ± 0%     3.6kB ± 0%  -82.86%

name                old allocs/op  new allocs/op  delta
/Log-8                   286 ± 0%        16 ± 0%  -94.41%

Change-Id: Ieafd644683d98d24978c8be061e6632dd8ef113e
Reviewed-on: https://go-review.googlesource.com/c/tools/+/227302
Run-TryBot: Ian Cottrell <[email protected]>
Reviewed-by: Robert Findley <[email protected]>
Reviewed-by: Emmanuel Odeke <[email protected]>

Author: ianthehat

internal/telemetry/export/log.go

@@ -8,6 +8,8 @@ import (
 	"context"
 	"fmt"
 	"io"
+	"strconv"
+	"sync"
 
 	"golang.org/x/tools/internal/telemetry/event"
 )
@@ -22,6 +24,8 @@ func LogWriter(w io.Writer, onlyErrors bool) event.Exporter {
 }
 
 type logWriter struct {
+	mu         sync.Mutex
+	buffer     [128]byte
 	writer     io.Writer
 	onlyErrors bool
 }
@@ -32,7 +36,66 @@ func (w *logWriter) ProcessEvent(ctx context.Context, ev event.Event, tagMap eve
 		if w.onlyErrors && event.Err.Get(tagMap) == nil {
 			return ctx
 		}
-		fmt.Fprintf(w.writer, "%v\n", ev)
+		w.mu.Lock()
+		defer w.mu.Unlock()
+
+		buf := w.buffer[:0]
+		if !ev.At.IsZero() {
+			w.writer.Write(ev.At.AppendFormat(buf, "2006/01/02 15:04:05 "))
+		}
+		msg := event.Msg.Get(tagMap)
+		io.WriteString(w.writer, msg)
+		if err := event.Err.Get(tagMap); err != nil {
+			io.WriteString(w.writer, ": ")
+			io.WriteString(w.writer, err.Error())
+		}
+		for index := 0; ev.Valid(index); index++ {
+			tag := ev.Tag(index)
+			if !tag.Valid() || tag.Key == event.Msg || tag.Key == event.Err {
+				continue
+			}
+			io.WriteString(w.writer, "\n\t")
+			io.WriteString(w.writer, tag.Key.Name())
+			io.WriteString(w.writer, "=")
+			switch key := tag.Key.(type) {
+			case *event.IntKey:
+				w.writer.Write(strconv.AppendInt(buf, int64(key.From(tag)), 10))
+			case *event.Int8Key:
+				w.writer.Write(strconv.AppendInt(buf, int64(key.From(tag)), 10))
+			case *event.Int16Key:
+				w.writer.Write(strconv.AppendInt(buf, int64(key.From(tag)), 10))
+			case *event.Int32Key:
+				w.writer.Write(strconv.AppendInt(buf, int64(key.From(tag)), 10))
+			case *event.Int64Key:
+				w.writer.Write(strconv.AppendInt(buf, key.From(tag), 10))
+			case *event.UIntKey:
+				w.writer.Write(strconv.AppendUint(buf, uint64(key.From(tag)), 10))
+			case *event.UInt8Key:
+				w.writer.Write(strconv.AppendUint(buf, uint64(key.From(tag)), 10))
+			case *event.UInt16Key:
+				w.writer.Write(strconv.AppendUint(buf, uint64(key.From(tag)), 10))
+			case *event.UInt32Key:
+				w.writer.Write(strconv.AppendUint(buf, uint64(key.From(tag)), 10))
+			case *event.UInt64Key:
+				w.writer.Write(strconv.AppendUint(buf, key.From(tag), 10))
+			case *event.Float32Key:
+				w.writer.Write(strconv.AppendFloat(buf, float64(key.From(tag)), 'E', -1, 32))
+			case *event.Float64Key:
+				w.writer.Write(strconv.AppendFloat(buf, key.From(tag), 'E', -1, 64))
+			case *event.BooleanKey:
+				w.writer.Write(strconv.AppendBool(buf, key.From(tag)))
+			case *event.StringKey:
+				w.writer.Write(strconv.AppendQuote(buf, key.From(tag)))
+			case *event.ErrorKey:
+				io.WriteString(w.writer, key.From(tag).Error())
+			case *event.ValueKey:
+				fmt.Fprint(w.writer, key.From(tag))
+			default:
+				fmt.Fprintf(w.writer, `"invalid key type %T"`, key)
+			}
+		}
+		io.WriteString(w.writer, "\n")
+
 	case ev.IsStartSpan():
 		if span := GetSpan(ctx); span != nil {
 			fmt.Fprintf(w.writer, "start: %v %v", span.Name, span.ID)