From 38daa6564ba7c9082106f8f6a36e12aa57225147 Mon Sep 17 00:00:00 2001 From: Ian Cottrell Date: Wed, 26 Jun 2019 22:46:12 -0400 Subject: [PATCH] internal/lsp: new tracing system Change-Id: Id6e6b121e8c69d6324a15cb46b3b9937dfe7a1dd Reviewed-on: https://go-review.googlesource.com/c/tools/+/186201 Run-TryBot: Ian Cottrell Reviewed-by: Rebecca Stambler TryBot-Result: Gobot Gobot --- internal/lsp/debug/serve.go | 9 ++ internal/lsp/debug/trace.go | 172 ++++++++++++++++++++++++++ internal/lsp/telemetry/trace/id.go | 72 +++++++++++ internal/lsp/telemetry/trace/trace.go | 126 ++++++++++++++++++- 4 files changed, 376 insertions(+), 3 deletions(-) create mode 100644 internal/lsp/debug/trace.go create mode 100644 internal/lsp/telemetry/trace/id.go diff --git a/internal/lsp/debug/serve.go b/internal/lsp/debug/serve.go index be64ab65..92c4075f 100644 --- a/internal/lsp/debug/serve.go +++ b/internal/lsp/debug/serve.go @@ -21,6 +21,7 @@ import ( "golang.org/x/tools/internal/lsp/telemetry/log" "golang.org/x/tools/internal/lsp/telemetry/metric" "golang.org/x/tools/internal/lsp/telemetry/tag" + "golang.org/x/tools/internal/lsp/telemetry/trace" "golang.org/x/tools/internal/lsp/telemetry/worker" "golang.org/x/tools/internal/span" ) @@ -219,6 +220,8 @@ func Serve(ctx context.Context, addr string) error { metric.RegisterObservers(prometheus.observeMetric) rpcs := rpcs{} metric.RegisterObservers(rpcs.observeMetric) + traces := traces{} + trace.RegisterObservers(traces.export) go func() { mux := http.NewServeMux() mux.HandleFunc("/", Render(mainTmpl, func(*http.Request) interface{} { return data })) @@ -230,6 +233,7 @@ func Serve(ctx context.Context, addr string) error { mux.HandleFunc("/debug/pprof/trace", pprof.Trace) mux.HandleFunc("/metrics/", prometheus.serve) mux.HandleFunc("/rpc/", Render(rpcTmpl, rpcs.getData)) + mux.HandleFunc("/trace/", Render(traceTmpl, traces.getData)) mux.HandleFunc("/cache/", Render(cacheTmpl, getCache)) mux.HandleFunc("/session/", Render(sessionTmpl, getSession)) mux.HandleFunc("/view/", Render(viewTmpl, getView)) @@ -290,6 +294,10 @@ var BaseTemplate = template.Must(template.New("").Parse(` td.value { text-align: right; } +ul.events { + list-style-type: none; +} + {{block "head" .}}{{end}} @@ -299,6 +307,7 @@ td.value { Memory Metrics RPC +Trace

{{template "title" .}}

{{block "body" .}} diff --git a/internal/lsp/debug/trace.go b/internal/lsp/debug/trace.go new file mode 100644 index 00000000..19911ae8 --- /dev/null +++ b/internal/lsp/debug/trace.go @@ -0,0 +1,172 @@ +// 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 debug + +import ( + "bytes" + "fmt" + "html/template" + "net/http" + "sort" + "strings" + "time" + + "golang.org/x/tools/internal/lsp/telemetry/tag" + "golang.org/x/tools/internal/lsp/telemetry/trace" +) + +var traceTmpl = template.Must(template.Must(BaseTemplate.Clone()).Parse(` +{{define "title"}}Trace Information{{end}} +{{define "body"}} + {{range .Traces}}{{.Name}} last: {{.Last.Duration}}, longest: {{.Longest.Duration}}
{{end}} + {{if .Selected}} +

{{.Selected.Name}}

+ {{if .Selected.Last}}

Last

    {{template "details" .Selected.Last}}
{{end}} + {{if .Selected.Longest}}

Longest

    {{template "details" .Selected.Longest}}
{{end}} + {{end}} +{{end}} +{{define "details"}} +
  • {{.Offset}} {{.Name}} {{.Duration}} {{.Tags}}
  • + {{if .Events}}
      {{range .Events}}
    • {{.Offset}} {{.Tags}}
    • {{end}}
    {{end}} + {{if .Children}}
      {{range .Children}}{{template "details" .}}{{end}}
    {{end}} +{{end}} +`)) + +type traces struct { + sets map[string]*traceSet + unfinished map[trace.SpanID]*traceData +} + +type traceResults struct { + Traces []*traceSet + Selected *traceSet +} + +type traceSet struct { + Name string + Last *traceData + Longest *traceData +} + +type traceData struct { + ID trace.SpanID + ParentID trace.SpanID + Name string + Start time.Time + Finish time.Time + Offset time.Duration + Duration time.Duration + Tags string + Events []traceEvent + Children []*traceData +} + +type traceEvent struct { + Time time.Time + Offset time.Duration + Tags string +} + +func (t *traces) export(span *trace.Span) { + if t.sets == nil { + t.sets = make(map[string]*traceSet) + t.unfinished = make(map[trace.SpanID]*traceData) + } + // is this a completed span? + if span.Finish.IsZero() { + t.start(span) + } else { + t.finish(span) + } +} + +func (t *traces) start(span *trace.Span) { + // just starting, add it to the unfinished map + td := &traceData{ + ID: span.SpanID, + ParentID: span.ParentID, + Name: span.Name, + Start: span.Start, + Tags: renderTags(span.Tags), + } + t.unfinished[span.SpanID] = td + // and wire up parents if we have them + if !span.ParentID.IsValid() { + return + } + parent, found := t.unfinished[span.ParentID] + if !found { + // trace had an invalid parent, so it cannot itself be valid + return + } + parent.Children = append(parent.Children, td) + +} + +func (t *traces) finish(span *trace.Span) { + // finishing, must be already in the map + td, found := t.unfinished[span.SpanID] + if !found { + return // if this happens we are in a bad place + } + delete(t.unfinished, span.SpanID) + + 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.Time, + 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) + } +} + +func (t *traces) getData(req *http.Request) interface{} { + if len(t.sets) == 0 { + return nil + } + data := traceResults{} + data.Traces = make([]*traceSet, 0, len(t.sets)) + for _, set := range t.sets { + data.Traces = append(data.Traces, set) + } + sort.Slice(data.Traces, func(i, j int) bool { return data.Traces[i].Name < data.Traces[j].Name }) + if bits := strings.SplitN(req.URL.Path, "/trace/", 2); len(bits) > 1 { + data.Selected = t.sets[bits[1]] + } + return data +} + +func fillOffsets(td *traceData, start time.Time) { + td.Offset = td.Start.Sub(start) + for i := range td.Events { + td.Events[i].Offset = td.Events[i].Time.Sub(start) + } + for _, child := range td.Children { + fillOffsets(child, start) + } +} + +func renderTags(tags tag.List) string { + buf := &bytes.Buffer{} + for _, tag := range tags { + fmt.Fprintf(buf, "%v=%q ", tag.Key, tag.Value) + } + return buf.String() +} diff --git a/internal/lsp/telemetry/trace/id.go b/internal/lsp/telemetry/trace/id.go new file mode 100644 index 00000000..c0985321 --- /dev/null +++ b/internal/lsp/telemetry/trace/id.go @@ -0,0 +1,72 @@ +// 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 tag adds support for telemetry tracins. +package trace + +import ( + crand "crypto/rand" + "encoding/binary" + "fmt" + "math/rand" + "sync" + "sync/atomic" +) + +type TraceID [16]byte +type SpanID [8]byte + +func (t TraceID) String() string { + return fmt.Sprintf("%02x", t[:]) +} + +func (s SpanID) String() string { + return fmt.Sprintf("%02x", s[:]) +} + +func (s SpanID) IsValid() bool { + return s != SpanID{} +} + +var ( + generationMu sync.Mutex + nextSpanID uint64 + spanIDInc uint64 + + traceIDAdd [2]uint64 + traceIDRand *rand.Rand +) + +func initGenerator() { + var rngSeed int64 + for _, p := range []interface{}{ + &rngSeed, &traceIDAdd, &nextSpanID, &spanIDInc, + } { + binary.Read(crand.Reader, binary.LittleEndian, p) + } + traceIDRand = rand.New(rand.NewSource(rngSeed)) + spanIDInc |= 1 +} + +func newTraceID() TraceID { + generationMu.Lock() + defer generationMu.Unlock() + if traceIDRand == nil { + initGenerator() + } + var tid [16]byte + binary.LittleEndian.PutUint64(tid[0:8], traceIDRand.Uint64()+traceIDAdd[0]) + binary.LittleEndian.PutUint64(tid[8:16], traceIDRand.Uint64()+traceIDAdd[1]) + return tid +} + +func newSpanID() SpanID { + var id uint64 + for id == 0 { + id = atomic.AddUint64(&nextSpanID, spanIDInc) + } + var sid [8]byte + binary.LittleEndian.PutUint64(sid[:], id) + return sid +} diff --git a/internal/lsp/telemetry/trace/trace.go b/internal/lsp/telemetry/trace/trace.go index 2e735360..3ad88492 100644 --- a/internal/lsp/telemetry/trace/trace.go +++ b/internal/lsp/telemetry/trace/trace.go @@ -2,19 +2,139 @@ // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. -// Package tag adds support for telemetry tracing. +// Package trace adds support for telemetry tracing. package trace import ( "context" + "fmt" + "time" + "golang.org/x/tools/internal/lsp/telemetry/log" "golang.org/x/tools/internal/lsp/telemetry/tag" + "golang.org/x/tools/internal/lsp/telemetry/worker" ) +type Span struct { + Name string + TraceID TraceID + SpanID SpanID + ParentID SpanID + Start time.Time + Finish time.Time + Tags tag.List + Events []Event + + ready bool +} + +type Event struct { + Time time.Time + Tags tag.List +} + +type Observer func(*Span) + +func RegisterObservers(o ...Observer) { + worker.Do(func() { + if !registered { + registered = true + tag.Observe(tagObserver) + log.AddLogger(logger) + } + observers = append(observers, o...) + }) +} + func StartSpan(ctx context.Context, name string, tags ...tag.Tag) (context.Context, func()) { - return tag.With(ctx, tags...), func() {} + span := &Span{ + Name: name, + Start: time.Now(), + } + if parent := fromContext(ctx); parent != nil { + span.TraceID = parent.TraceID + span.ParentID = parent.SpanID + } else { + span.TraceID = newTraceID() + } + span.SpanID = newSpanID() + ctx = context.WithValue(ctx, contextKey, span) + if len(tags) > 0 { + ctx = tag.With(ctx, tags...) + } + worker.Do(func() { + span.ready = true + for _, o := range observers { + o(span) + } + }) + return ctx, span.close +} + +func (s *Span) close() { + now := time.Now() + worker.Do(func() { + s.Finish = now + for _, o := range observers { + o(s) + } + }) +} + +func (s *Span) Format(f fmt.State, r rune) { + fmt.Fprintf(f, "%v %v:%v", s.Name, s.TraceID, s.SpanID) + if s.ParentID.IsValid() { + fmt.Fprintf(f, "[%v]", s.ParentID) + } + fmt.Fprintf(f, " %v->%v", s.Start, s.Finish) +} + +type contextKeyType int + +var contextKey contextKeyType + +func fromContext(ctx context.Context) *Span { + v := ctx.Value(contextKey) + if v == nil { + return nil + } + return v.(*Span) +} + +var ( + observers []Observer + registered bool +) + +func tagObserver(ctx context.Context, at time.Time, tags tag.List) { + span := fromContext(ctx) + if span == nil { + return + } + if !span.ready { + span.Tags = append(span.Tags, tags...) + return + } + span.Events = append(span.Events, Event{ + Time: at, + Tags: tags, + }) +} + +func logger(ctx context.Context, at time.Time, tags tag.List) bool { + span := fromContext(ctx) + if span == nil { + return false + } + span.Events = append(span.Events, Event{ + Time: at, + Tags: tags, + }) + return false } // 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 ctx } +func Detach(ctx context.Context) context.Context { + return context.WithValue(ctx, contextKey, nil) +}