trace: don't allocate all events upfront

SetMaxEvent allocates storage for all events, which is very expensive
if we want to set a high value; even with small values, the
unnecessary allocation of the initial slice is measurable.

We improve the performance by having a few events preallocated as part
of the trace, and appending as necessary. We also co-locate the flags
in event which makes it smaller (by a word).

We also add a set of benchmarks; before and after amortized cost
per-event is shown:

name                 old time/op  new time/op  delta
Trace/0-2-32         1.19µs ± 1%  0.96µs ± 0%  -18.94%  (p=0.008 n=5+5)
Trace/0-10-32         579ns ± 0%   635ns ± 1%   +9.82%  (p=0.008 n=5+5)
Trace/0-100-32        463ns ± 1%   466ns ± 1%     ~     (p=0.190 n=5+5)
Trace/0-1000-32       451ns ± 1%   451ns ± 0%     ~     (p=0.984 n=5+5)
Trace/0-10000-32      451ns ± 2%   449ns ± 1%     ~     (p=0.492 n=5+5)
Trace/10-2-32        1.41µs ± 1%  0.96µs ± 1%  -31.74%  (p=0.008 n=5+5)
Trace/10-10-32        623ns ± 1%   634ns ± 1%   +1.73%  (p=0.008 n=5+5)
Trace/10-100-32       469ns ± 1%   466ns ± 1%     ~     (p=0.357 n=5+5)
Trace/10-1000-32      452ns ± 1%   453ns ± 2%     ~     (p=0.913 n=5+5)
Trace/10-10000-32     451ns ± 1%   449ns ± 1%     ~     (p=0.175 n=5+5)
Trace/100-2-32       2.78µs ± 2%  0.97µs ± 1%  -65.28%  (p=0.008 n=5+5)
Trace/100-10-32       912ns ± 1%   637ns ± 1%  -30.23%  (p=0.008 n=5+5)
Trace/100-100-32      479ns ± 1%   541ns ± 0%  +12.77%  (p=0.008 n=5+5)
Trace/100-1000-32     510ns ± 0%   541ns ± 1%   +6.08%  (p=0.008 n=5+5)
Trace/100-10000-32    514ns ± 1%   540ns ± 0%   +5.14%  (p=0.008 n=5+5)
Trace/1000-2-32      17.2µs ± 1%   1.0µs ± 1%  -94.39%  (p=0.008 n=5+5)
Trace/1000-10-32     3.90µs ± 1%  0.64µs ± 0%  -83.68%  (p=0.008 n=5+5)
Trace/1000-100-32     814ns ± 1%   542ns ± 0%  -33.46%  (p=0.008 n=5+5)
Trace/1000-1000-32    503ns ± 1%   581ns ± 0%  +15.56%  (p=0.008 n=5+5)
Trace/1000-10000-32  1.28µs ± 2%  1.03µs ± 1%  -19.68%  (p=0.008 n=5+5)

Change-Id: If7c68bb1809fb92fa5d06cb6640be5e09e1f131f
Reviewed-on: https://go-review.googlesource.com/30374
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

trace/trace.go

@@ -333,7 +333,8 @@ func New(family, title string) Trace {
 	tr.ref()
 	tr.Family, tr.Title = family, title
 	tr.Start = time.Now()
-	tr.events = make([]event, 0, maxEventsPerTrace)
+	tr.maxEvents = maxEventsPerTrace
+	tr.events = tr.eventsBuf[:0]
 
 	activeMu.RLock()
 	s := activeTraces[tr.Family]
@@ -650,8 +651,8 @@ type event struct {
 	Elapsed    time.Duration // since previous event in trace
 	NewDay     bool          // whether this event is on a different day to the previous event
 	Recyclable bool          // whether this event was passed via LazyLog
-	What       interface{}   // string or fmt.Stringer
 	Sensitive  bool          // whether this event contains sensitive information
+	What       interface{}   // string or fmt.Stringer
 }
 
 // WhenString returns a string representation of the elapsed time of the event.
@@ -692,14 +693,17 @@ type trace struct {
 	IsError bool
 
 	// Append-only sequence of events (modulo discards).
-	mu     sync.RWMutex
-	events []event
+	mu        sync.RWMutex
+	events    []event
+	maxEvents int
 
 	refs     int32 // how many buckets this is in
 	recycler func(interface{})
 	disc     discarded // scratch space to avoid allocation
 
 	finishStack []byte // where finish was called, if DebugUseAfterFinish is set
+
+	eventsBuf [4]event // preallocated buffer in case we only log a few events
 }
 
 func (tr *trace) reset() {
@@ -711,11 +715,15 @@ func (tr *trace) reset() {
 	tr.traceID = 0
 	tr.spanID = 0
 	tr.IsError = false
+	tr.maxEvents = 0
 	tr.events = nil
 	tr.refs = 0
 	tr.recycler = nil
 	tr.disc = 0
 	tr.finishStack = nil
+	for i := range tr.eventsBuf {
+		tr.eventsBuf[i] = event{}
+	}
 }
 
 // delta returns the elapsed time since the last event or the trace start,
@@ -753,11 +761,11 @@ func (tr *trace) addEvent(x interface{}, recyclable, sensitive bool) {
 	e := event{When: time.Now(), What: x, Recyclable: recyclable, Sensitive: sensitive}
 	tr.mu.Lock()
 	e.Elapsed, e.NewDay = tr.delta(e.When)
-	if len(tr.events) < cap(tr.events) {
+	if len(tr.events) < tr.maxEvents {
 		tr.events = append(tr.events, e)
 	} else {
 		// Discard the middle events.
-		di := int((cap(tr.events) - 1) / 2)
+		di := int((tr.maxEvents - 1) / 2)
 		if d, ok := tr.events[di].What.(*discarded); ok {
 			(*d)++
 		} else {
@@ -777,7 +785,7 @@ func (tr *trace) addEvent(x interface{}, recyclable, sensitive bool) {
 			go tr.recycler(tr.events[di+1].What)
 		}
 		copy(tr.events[di+1:], tr.events[di+2:])
-		tr.events[cap(tr.events)-1] = e
+		tr.events[tr.maxEvents-1] = e
 	}
 	tr.mu.Unlock()
 }
@@ -803,7 +811,7 @@ func (tr *trace) SetTraceInfo(traceID, spanID uint64) {
 func (tr *trace) SetMaxEvents(m int) {
 	// Always keep at least three events: first, discarded count, last.
 	if len(tr.events) == 0 && m > 3 {
-		tr.events = make([]event, 0, m)
+		tr.maxEvents = m
 	}
 }
 

trace/trace_test.go

@@ -5,6 +5,7 @@
 package trace
 
 import (
+	"fmt"
 	"net/http"
 	"reflect"
 	"testing"
@@ -69,3 +70,27 @@ func TestAuthRequest(t *testing.T) {
 		}
 	}
 }
+
+func benchmarkTrace(b *testing.B, maxEvents, numEvents int) {
+	numSpans := (b.N + numEvents + 1) / numEvents
+
+	for i := 0; i < numSpans; i++ {
+		tr := New("test", "test")
+		tr.SetMaxEvents(maxEvents)
+		for j := 0; j < numEvents; j++ {
+			tr.LazyPrintf("%d", j)
+		}
+		tr.Finish()
+	}
+}
+
+func BenchmarkTrace(b *testing.B) {
+	for _, maxEvents := range []int{0, 10, 100, 1000} {
+		for _, numEvents := range []int{2, 10, 100, 1000, 10000} {
+			name := fmt.Sprintf("%d-%d", maxEvents, numEvents)
+			b.Run(name, func(b *testing.B) {
+				benchmarkTrace(b, maxEvents, numEvents)
+			})
+		}
+	}
+}