Revert "trace: don't allocate all events upfront"

This reverts commit If7c68bb1809fb92fa5d06cb6640be5e09e1f131f.

Reason for revert: breaks the build for Go 1.6 or below due to use of Go 1.7+ only features.

Original change's description:
> 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>
> 

Change-Id: I7cf25464ae836489e0af4a59a4d534a5d25ee352
Reviewed-on: https://go-review.googlesource.com/30650
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

trace/trace.go

@@ -333,8 +333,7 @@ func New(family, title string) Trace {
 	tr.ref()
 	tr.Family, tr.Title = family, title
 	tr.Start = time.Now()
-	tr.maxEvents = maxEventsPerTrace
-	tr.events = tr.eventsBuf[:0]
+	tr.events = make([]event, 0, maxEventsPerTrace)
 
 	activeMu.RLock()
 	s := activeTraces[tr.Family]
@@ -651,8 +650,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
-	Sensitive  bool          // whether this event contains sensitive information
 	What       interface{}   // string or fmt.Stringer
+	Sensitive  bool          // whether this event contains sensitive information
 }
 
 // WhenString returns a string representation of the elapsed time of the event.
@@ -693,17 +692,14 @@ type trace struct {
 	IsError bool
 
 	// Append-only sequence of events (modulo discards).
-	mu        sync.RWMutex
-	events    []event
-	maxEvents int
+	mu     sync.RWMutex
+	events []event
 
 	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() {
@@ -715,15 +711,11 @@ 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,
@@ -761,11 +753,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) < tr.maxEvents {
+	if len(tr.events) < cap(tr.events) {
 		tr.events = append(tr.events, e)
 	} else {
 		// Discard the middle events.
-		di := int((tr.maxEvents - 1) / 2)
+		di := int((cap(tr.events) - 1) / 2)
 		if d, ok := tr.events[di].What.(*discarded); ok {
 			(*d)++
 		} else {
@@ -785,7 +777,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[tr.maxEvents-1] = e
+		tr.events[cap(tr.events)-1] = e
 	}
 	tr.mu.Unlock()
 }
@@ -811,7 +803,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.maxEvents = m
+		tr.events = make([]event, 0, m)
 	}
 }
 

trace/trace_test.go

@@ -5,7 +5,6 @@
 package trace
 
 import (
-	"fmt"
 	"net/http"
 	"reflect"
 	"testing"
@@ -70,27 +69,3 @@ 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)
-			})
-		}
-	}
-}