From c4206d458c3fff11d3b508eb96dc2f8f76ff50bb Mon Sep 17 00:00:00 2001 From: Ian Cottrell Date: Sun, 1 Mar 2020 18:35:55 -0500 Subject: [PATCH] internal/telemetry: change tracing to be event based MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit We no longer use the span as the core type of tracing, instead that is an artifact of the exporter, and start and end tracing is just event based. This both makes the interface normalized, and also means the null exporter case is considerably cheaper in memory and cpu. See below for benchstat changes name old time/op new time/op delta TracingNoExporter-8 4.19µs ±12% 2.71µs ±11% -35.33% (p=0.000 n=20+20) Tracing-8 24.1µs ± 3% 5.1µs ±17% -78.66% (p=0.000 n=16+20) name old alloc/op new alloc/op delta TracingNoExporter-8 2.32kB ± 0% 0.40kB ± 0% -82.76% (p=0.000 n=20+20) Tracing-8 6.32kB ± 0% 2.32kB ± 0% -63.30% (p=0.000 n=20+20) name old allocs/op new allocs/op delta TracingNoExporter-8 35.0 ± 0% 15.0 ± 0% -57.14% (p=0.000 n=20+20) Tracing-8 215 ± 0% 35 ± 0% -83.72% (p=0.000 n=20+20) Change-Id: I3cf25871fa49584819504b5c19aa580e5dd03395 Reviewed-on: https://go-review.googlesource.com/c/tools/+/221740 Run-TryBot: Ian Cottrell TryBot-Result: Gobot Gobot Reviewed-by: Emmanuel Odeke --- internal/lsp/debug/serve.go | 32 +---- internal/lsp/debug/trace.go | 124 +++++++++--------- internal/telemetry/bench_test.go | 9 +- internal/telemetry/context.go | 25 ---- internal/telemetry/event.go | 2 + internal/telemetry/export/export.go | 28 +--- internal/telemetry/{ => export}/id.go | 6 +- internal/telemetry/export/log.go | 35 +++-- internal/telemetry/export/ocagent/ocagent.go | 20 +-- .../telemetry/export/ocagent/ocagent_test.go | 23 +++- internal/telemetry/export/trace.go | 88 +++++++++++++ internal/telemetry/trace.go | 37 ------ internal/telemetry/trace/trace.go | 28 ++-- 13 files changed, 221 insertions(+), 236 deletions(-) delete mode 100644 internal/telemetry/context.go rename internal/telemetry/{ => export}/id.go (94%) create mode 100644 internal/telemetry/export/trace.go delete mode 100644 internal/telemetry/trace.go diff --git a/internal/lsp/debug/serve.go b/internal/lsp/debug/serve.go index 0e3b318c0a..4e48f128cf 100644 --- a/internal/lsp/debug/serve.go +++ b/internal/lsp/debug/serve.go @@ -544,44 +544,22 @@ func (i *Instance) writeMemoryDebug(threshold uint64) error { return nil } -func (e *exporter) StartSpan(ctx context.Context, spn *telemetry.Span) { - i := GetInstance(ctx) - if i == nil { - return - } - if i.ocagent != nil { - i.ocagent.StartSpan(ctx, spn) - } - if i.traces != nil { - i.traces.StartSpan(ctx, spn) - } -} - -func (e *exporter) FinishSpan(ctx context.Context, spn *telemetry.Span) { - i := GetInstance(ctx) - if i == nil { - return - } - if i.ocagent != nil { - i.ocagent.FinishSpan(ctx, spn) - } - if i.traces != nil { - i.traces.FinishSpan(ctx, spn) - } -} - func (e *exporter) ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { + ctx = export.ContextSpan(ctx, event) i := GetInstance(ctx) if event.Type == telemetry.EventLog && (event.Error != nil || i == nil) { fmt.Fprintf(e.stderr, "%v\n", event) } - protocol.LogEvent(ctx, event) + ctx = protocol.LogEvent(ctx, event) if i == nil { return ctx } if i.ocagent != nil { ctx = i.ocagent.ProcessEvent(ctx, event) } + if i.traces != nil { + ctx = i.traces.ProcessEvent(ctx, event) + } return ctx } diff --git a/internal/lsp/debug/trace.go b/internal/lsp/debug/trace.go index a455048b7f..8abd8eb66e 100644 --- a/internal/lsp/debug/trace.go +++ b/internal/lsp/debug/trace.go @@ -16,6 +16,7 @@ import ( "time" "golang.org/x/tools/internal/telemetry" + "golang.org/x/tools/internal/telemetry/export" ) var traceTmpl = template.Must(template.Must(baseTemplate.Clone()).Parse(` @@ -38,7 +39,7 @@ var traceTmpl = template.Must(template.Must(baseTemplate.Clone()).Parse(` type traces struct { mu sync.Mutex sets map[string]*traceSet - unfinished map[telemetry.SpanContext]*traceData + unfinished map[export.SpanContext]*traceData } type traceResults struct { @@ -53,9 +54,9 @@ type traceSet struct { } type traceData struct { - TraceID telemetry.TraceID - SpanID telemetry.SpanID - ParentID telemetry.SpanID + TraceID export.TraceID + SpanID export.SpanID + ParentID export.SpanID Name string Start time.Time Finish time.Time @@ -72,68 +73,73 @@ type traceEvent struct { Tags string } -func (t *traces) StartSpan(ctx context.Context, span *telemetry.Span) { +func (t *traces) ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { t.mu.Lock() defer t.mu.Unlock() - if t.sets == nil { - t.sets = make(map[string]*traceSet) - t.unfinished = make(map[telemetry.SpanContext]*traceData) + span := export.GetSpan(ctx) + if span == nil { + return ctx } - // just starting, add it to the unfinished map - td := &traceData{ - TraceID: span.ID.TraceID, - SpanID: span.ID.SpanID, - ParentID: span.ParentID, - Name: span.Name, - Start: span.Start, - Tags: renderTags(span.Tags), - } - t.unfinished[span.ID] = td - // and wire up parents if we have them - if !span.ParentID.IsValid() { - return - } - parentID := telemetry.SpanContext{TraceID: span.ID.TraceID, SpanID: span.ParentID} - parent, found := t.unfinished[parentID] - if !found { - // trace had an invalid parent, so it cannot itself be valid - return - } - parent.Children = append(parent.Children, td) -} + switch event.Type { + case telemetry.EventStartSpan: + if t.sets == nil { + t.sets = make(map[string]*traceSet) + t.unfinished = make(map[export.SpanContext]*traceData) + } + // just starting, add it to the unfinished map + td := &traceData{ + TraceID: span.ID.TraceID, + SpanID: span.ID.SpanID, + ParentID: span.ParentID, + Name: span.Name, + Start: span.Start, + Tags: renderTags(span.Tags), + } + t.unfinished[span.ID] = td + // and wire up parents if we have them + if !span.ParentID.IsValid() { + return ctx + } + parentID := export.SpanContext{TraceID: span.ID.TraceID, SpanID: span.ParentID} + parent, found := t.unfinished[parentID] + if !found { + // trace had an invalid parent, so it cannot itself be valid + return ctx + } + parent.Children = append(parent.Children, td) -func (t *traces) FinishSpan(ctx context.Context, span *telemetry.Span) { - t.mu.Lock() - defer t.mu.Unlock() - // finishing, must be already in the map - td, found := t.unfinished[span.ID] - if !found { - return // if this happens we are in a bad place - } - delete(t.unfinished, span.ID) + case telemetry.EventEndSpan: + // finishing, must be already in the map + td, found := t.unfinished[span.ID] + if !found { + return ctx // if this happens we are in a bad place + } + delete(t.unfinished, span.ID) - td.Finish = span.Finish - td.Duration = span.Finish.Sub(span.Start) - td.Events = make([]traceEvent, len(span.Events)) - for i, event := range span.Events { - td.Events[i] = traceEvent{ - Time: event.At, - Tags: renderTags(event.Tags), + td.Finish = span.Finish + td.Duration = span.Finish.Sub(span.Start) + td.Events = make([]traceEvent, len(span.Events)) + for i, event := range span.Events { + td.Events[i] = traceEvent{ + Time: event.At, + Tags: renderTags(event.Tags), + } + } + + set, ok := t.sets[span.Name] + if !ok { + set = &traceSet{Name: span.Name} + t.sets[span.Name] = set + } + set.Last = td + if set.Longest == nil || set.Last.Duration > set.Longest.Duration { + set.Longest = set.Last + } + if !td.ParentID.IsValid() { + fillOffsets(td, td.Start) } } - - set, ok := t.sets[span.Name] - if !ok { - set = &traceSet{Name: span.Name} - t.sets[span.Name] = set - } - set.Last = td - if set.Longest == nil || set.Last.Duration > set.Longest.Duration { - set.Longest = set.Last - } - if !td.ParentID.IsValid() { - fillOffsets(td, td.Start) - } + return ctx } func (t *traces) getData(req *http.Request) interface{} { diff --git a/internal/telemetry/bench_test.go b/internal/telemetry/bench_test.go index c3e5317a28..8145e9fcd2 100644 --- a/internal/telemetry/bench_test.go +++ b/internal/telemetry/bench_test.go @@ -107,6 +107,7 @@ func newExporter() *loggingExporter { } func (e *loggingExporter) ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { + export.ContextSpan(ctx, event) return e.logger.ProcessEvent(ctx, event) } @@ -114,14 +115,6 @@ func (e *loggingExporter) Metric(ctx context.Context, data telemetry.MetricData) e.logger.Metric(ctx, data) } -func (e *loggingExporter) StartSpan(ctx context.Context, span *telemetry.Span) { - e.logger.StartSpan(ctx, span) -} - -func (e *loggingExporter) FinishSpan(ctx context.Context, span *telemetry.Span) { - e.logger.FinishSpan(ctx, span) -} - func BenchmarkBaseline(b *testing.B) { ctx := context.Background() b.ReportAllocs() diff --git a/internal/telemetry/context.go b/internal/telemetry/context.go deleted file mode 100644 index b8037ca0f0..0000000000 --- a/internal/telemetry/context.go +++ /dev/null @@ -1,25 +0,0 @@ -// Copyright 2019 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -package telemetry - -import "context" - -type contextKeyType int - -const ( - spanContextKey = contextKeyType(iota) -) - -func WithSpan(ctx context.Context, span *Span) context.Context { - return context.WithValue(ctx, spanContextKey, span) -} - -func GetSpan(ctx context.Context) *Span { - v := ctx.Value(spanContextKey) - if v == nil { - return nil - } - return v.(*Span) -} diff --git a/internal/telemetry/event.go b/internal/telemetry/event.go index 4964ccf717..3eaf094c74 100644 --- a/internal/telemetry/event.go +++ b/internal/telemetry/event.go @@ -13,6 +13,8 @@ type EventType uint8 const ( EventLog = EventType(iota) + EventStartSpan + EventEndSpan ) type Event struct { diff --git a/internal/telemetry/export/export.go b/internal/telemetry/export/export.go index e99cda7d2e..a1f6dfaa7b 100644 --- a/internal/telemetry/export/export.go +++ b/internal/telemetry/export/export.go @@ -23,9 +23,6 @@ type Exporter interface { // given event. ProcessEvent(context.Context, telemetry.Event) context.Context - StartSpan(context.Context, *telemetry.Span) - FinishSpan(context.Context, *telemetry.Span) - Metric(context.Context, telemetry.MetricData) } @@ -45,31 +42,13 @@ func SetExporter(e Exporter) { atomic.StorePointer(&exporter, p) } -func StartSpan(ctx context.Context, span *telemetry.Span, at time.Time) { - exporterPtr := (*Exporter)(atomic.LoadPointer(&exporter)) - if exporterPtr == nil { - return - } - span.Start = at - (*exporterPtr).StartSpan(ctx, span) -} - -func FinishSpan(ctx context.Context, span *telemetry.Span, at time.Time) { - exporterPtr := (*Exporter)(atomic.LoadPointer(&exporter)) - if exporterPtr == nil { - return - } - span.Finish = at - (*exporterPtr).FinishSpan(ctx, span) -} - func Tag(ctx context.Context, at time.Time, tags telemetry.TagList) { exporterPtr := (*Exporter)(atomic.LoadPointer(&exporter)) if exporterPtr == nil { return } // If context has a span we need to add the tags to it - span := telemetry.GetSpan(ctx) + span := GetSpan(ctx) if span == nil { return } @@ -90,11 +69,6 @@ func ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { if exporterPtr == nil { return ctx } - // If context has a span we need to add the event to it - span := telemetry.GetSpan(ctx) - if span != nil { - span.Events = append(span.Events, event) - } // and now also hand the event of to the current exporter return (*exporterPtr).ProcessEvent(ctx, event) } diff --git a/internal/telemetry/id.go b/internal/telemetry/export/id.go similarity index 94% rename from internal/telemetry/id.go rename to internal/telemetry/export/id.go index 8be110c622..bf9938b38c 100644 --- a/internal/telemetry/id.go +++ b/internal/telemetry/export/id.go @@ -2,7 +2,7 @@ // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. -package telemetry +package export import ( crand "crypto/rand" @@ -48,7 +48,7 @@ func initGenerator() { spanIDInc |= 1 } -func NewTraceID() TraceID { +func newTraceID() TraceID { generationMu.Lock() defer generationMu.Unlock() if traceIDRand == nil { @@ -60,7 +60,7 @@ func NewTraceID() TraceID { return tid } -func NewSpanID() SpanID { +func newSpanID() SpanID { var id uint64 for id == 0 { id = atomic.AddUint64(&nextSpanID, spanIDInc) diff --git a/internal/telemetry/export/log.go b/internal/telemetry/export/log.go index 752e686e8b..5fa2a88b61 100644 --- a/internal/telemetry/export/log.go +++ b/internal/telemetry/export/log.go @@ -25,26 +25,25 @@ type logWriter struct { onlyErrors bool } -func (w *logWriter) StartSpan(ctx context.Context, span *telemetry.Span) { - if w.onlyErrors { - return - } - fmt.Fprintf(w.writer, "start: %v %v", span.Name, span.ID) - if span.ParentID.IsValid() { - fmt.Fprintf(w.writer, "[%v]", span.ParentID) - } -} -func (w *logWriter) FinishSpan(ctx context.Context, span *telemetry.Span) { - if w.onlyErrors { - return - } - fmt.Fprintf(w.writer, "finish: %v %v", span.Name, span.ID) -} func (w *logWriter) ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { - if w.onlyErrors && event.Error == nil { - return ctx + switch event.Type { + case telemetry.EventLog: + if w.onlyErrors && event.Error == nil { + return ctx + } + fmt.Fprintf(w.writer, "%v\n", event) + case telemetry.EventStartSpan: + if span := GetSpan(ctx); span != nil { + fmt.Fprintf(w.writer, "start: %v %v", span.Name, span.ID) + if span.ParentID.IsValid() { + fmt.Fprintf(w.writer, "[%v]", span.ParentID) + } + } + case telemetry.EventEndSpan: + if span := GetSpan(ctx); span != nil { + fmt.Fprintf(w.writer, "finish: %v %v", span.Name, span.ID) + } } - fmt.Fprintf(w.writer, "%v\n", event) return ctx } func (w *logWriter) Metric(context.Context, telemetry.MetricData) {} diff --git a/internal/telemetry/export/ocagent/ocagent.go b/internal/telemetry/export/ocagent/ocagent.go index 038cb4fb5b..d01b7b3641 100644 --- a/internal/telemetry/export/ocagent/ocagent.go +++ b/internal/telemetry/export/ocagent/ocagent.go @@ -19,6 +19,7 @@ import ( "time" "golang.org/x/tools/internal/telemetry" + "golang.org/x/tools/internal/telemetry/export" "golang.org/x/tools/internal/telemetry/export/ocagent/wire" "golang.org/x/tools/internal/telemetry/tag" ) @@ -45,7 +46,7 @@ func Discover() *Config { type Exporter struct { mu sync.Mutex config Config - spans []*telemetry.Span + spans []*export.Span metrics []telemetry.MetricData } @@ -84,15 +85,16 @@ func Connect(config *Config) *Exporter { return exporter } -func (e *Exporter) StartSpan(ctx context.Context, span *telemetry.Span) {} - -func (e *Exporter) FinishSpan(ctx context.Context, span *telemetry.Span) { +func (e *Exporter) ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { + if event.Type != telemetry.EventEndSpan { + return ctx + } e.mu.Lock() defer e.mu.Unlock() - e.spans = append(e.spans, span) -} - -func (e *Exporter) ProcessEvent(ctx context.Context, event telemetry.Event) context.Context { + span := export.GetSpan(ctx) + if span != nil { + e.spans = append(e.spans, span) + } return ctx } @@ -189,7 +191,7 @@ func toTruncatableString(s string) *wire.TruncatableString { return &wire.TruncatableString{Value: s} } -func convertSpan(span *telemetry.Span) *wire.Span { +func convertSpan(span *export.Span) *wire.Span { result := &wire.Span{ TraceID: span.ID.TraceID[:], SpanID: span.ID.SpanID[:], diff --git a/internal/telemetry/export/ocagent/ocagent_test.go b/internal/telemetry/export/ocagent/ocagent_test.go index 50b92477f7..f30da2283a 100644 --- a/internal/telemetry/export/ocagent/ocagent_test.go +++ b/internal/telemetry/export/ocagent/ocagent_test.go @@ -17,6 +17,7 @@ import ( "time" "golang.org/x/tools/internal/telemetry" + "golang.org/x/tools/internal/telemetry/export" "golang.org/x/tools/internal/telemetry/export/ocagent" "golang.org/x/tools/internal/telemetry/tag" ) @@ -213,14 +214,22 @@ func TestEvents(t *testing.T) { ctx := context.TODO() for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - span := &telemetry.Span{ - Name: "event span", - Start: start, - Finish: end, - Events: []telemetry.Event{tt.event(ctx)}, + startEvent := telemetry.Event{ + Type: telemetry.EventStartSpan, + Message: "event span", + At: start, } - exporter.StartSpan(ctx, span) - exporter.FinishSpan(ctx, span) + endEvent := telemetry.Event{ + Type: telemetry.EventEndSpan, + At: end, + } + ctx := export.ContextSpan(ctx, startEvent) + span := export.GetSpan(ctx) + span.ID = export.SpanContext{} + span.Events = []telemetry.Event{tt.event(ctx)} + exporter.ProcessEvent(ctx, startEvent) + export.ContextSpan(ctx, endEvent) + exporter.ProcessEvent(ctx, endEvent) exporter.Flush() got := sent.get("/v1/trace") checkJSON(t, got, []byte(tt.want)) diff --git a/internal/telemetry/export/trace.go b/internal/telemetry/export/trace.go new file mode 100644 index 0000000000..f45e049594 --- /dev/null +++ b/internal/telemetry/export/trace.go @@ -0,0 +1,88 @@ +// Copyright 2019 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package export + +import ( + "context" + "fmt" + "time" + + "golang.org/x/tools/internal/telemetry" +) + +type SpanContext struct { + TraceID TraceID + SpanID SpanID +} + +type Span struct { + Name string + ID SpanContext + ParentID SpanID + Start time.Time + Finish time.Time + Tags telemetry.TagList + Events []telemetry.Event +} + +type contextKeyType int + +const ( + spanContextKey = contextKeyType(iota) +) + +func GetSpan(ctx context.Context) *Span { + v := ctx.Value(spanContextKey) + if v == nil { + return nil + } + return v.(*Span) +} + +func ContextSpan(ctx context.Context, event telemetry.Event) context.Context { + switch event.Type { + case telemetry.EventLog: + if span := GetSpan(ctx); span != nil { + span.Events = append(span.Events, event) + } + case telemetry.EventStartSpan: + span := &Span{ + Name: event.Message, + Start: event.At, + Tags: event.Tags, + } + if parent := GetSpan(ctx); parent != nil { + span.ID.TraceID = parent.ID.TraceID + span.ParentID = parent.ID.SpanID + } else { + span.ID.TraceID = newTraceID() + } + span.ID.SpanID = newSpanID() + ctx = context.WithValue(ctx, spanContextKey, span) + case telemetry.EventEndSpan: + if span := GetSpan(ctx); span != nil { + span.Finish = event.At + } + } + return ctx +} + +// Detach returns a context without an associated span. +// This allows the creation of spans that are not children of the current span. +func Detach(ctx context.Context) context.Context { + return context.WithValue(ctx, spanContextKey, nil) +} + +func (s *SpanContext) Format(f fmt.State, r rune) { + fmt.Fprintf(f, "%v:%v", s.TraceID, s.SpanID) +} + +func (s *Span) Format(f fmt.State, r rune) { + fmt.Fprintf(f, "%v %v", s.Name, s.ID) + if s.ParentID.IsValid() { + fmt.Fprintf(f, "[%v]", s.ParentID) + } + fmt.Fprintf(f, " %v->%v", s.Start, s.Finish) +} diff --git a/internal/telemetry/trace.go b/internal/telemetry/trace.go deleted file mode 100644 index 5356baa41c..0000000000 --- a/internal/telemetry/trace.go +++ /dev/null @@ -1,37 +0,0 @@ -// Copyright 2019 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -package telemetry - -import ( - "fmt" - "time" -) - -type SpanContext struct { - TraceID TraceID - SpanID SpanID -} - -type Span struct { - Name string - ID SpanContext - ParentID SpanID - Start time.Time - Finish time.Time - Tags TagList - Events []Event -} - -func (s *SpanContext) Format(f fmt.State, r rune) { - fmt.Fprintf(f, "%v:%v", s.TraceID, s.SpanID) -} - -func (s *Span) Format(f fmt.State, r rune) { - fmt.Fprintf(f, "%v %v", s.Name, s.ID) - if s.ParentID.IsValid() { - fmt.Fprintf(f, "[%v]", s.ParentID) - } - fmt.Fprintf(f, " %v->%v", s.Start, s.Finish) -} diff --git a/internal/telemetry/trace/trace.go b/internal/telemetry/trace/trace.go index 014c554b27..603b0bcb7c 100644 --- a/internal/telemetry/trace/trace.go +++ b/internal/telemetry/trace/trace.go @@ -11,29 +11,25 @@ import ( "golang.org/x/tools/internal/telemetry" "golang.org/x/tools/internal/telemetry/export" - "golang.org/x/tools/internal/telemetry/tag" ) func StartSpan(ctx context.Context, name string, tags ...telemetry.Tag) (context.Context, func()) { - start := time.Now() - span := &telemetry.Span{Name: name} - if parent := telemetry.GetSpan(ctx); parent != nil { - span.ID.TraceID = parent.ID.TraceID - span.ParentID = parent.ID.SpanID - } else { - span.ID.TraceID = telemetry.NewTraceID() + ctx = export.ProcessEvent(ctx, telemetry.Event{ + Type: telemetry.EventStartSpan, + Message: name, + At: time.Now(), + Tags: tags, + }) + return ctx, func() { + export.ProcessEvent(ctx, telemetry.Event{ + Type: telemetry.EventEndSpan, + At: time.Now(), + }) } - span.ID.SpanID = telemetry.NewSpanID() - ctx = telemetry.WithSpan(ctx, span) - if len(tags) > 0 { - ctx = tag.With(ctx, tags...) - } - export.StartSpan(ctx, span, start) - return ctx, func() { export.FinishSpan(ctx, span, time.Now()) } } // Detach returns a context without an associated span. // This allows the creation of spans that are not children of the current span. func Detach(ctx context.Context) context.Context { - return telemetry.WithSpan(ctx, nil) + return export.Detach(ctx) }