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) }