internal/lsp: new tracing system
Change-Id: Id6e6b121e8c69d6324a15cb46b3b9937dfe7a1dd
Reviewed-on: https://go-review.googlesource.com/c/tools/+/186201
Run-TryBot: Ian Cottrell <iancottrell@google.com>
Reviewed-by: Rebecca Stambler <rstambler@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
diff --git a/internal/lsp/debug/serve.go b/internal/lsp/debug/serve.go
index be64ab6..92c4075 100644
--- a/internal/lsp/debug/serve.go
+++ b/internal/lsp/debug/serve.go
@@ -21,6 +21,7 @@
"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 @@
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 @@
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 @@
td.value {
text-align: right;
}
+ul.events {
+ list-style-type: none;
+}
+
</style>
{{block "head" .}}{{end}}
</head>
@@ -299,6 +307,7 @@
<a href="/memory">Memory</a>
<a href="/metrics">Metrics</a>
<a href="/rpc">RPC</a>
+<a href="/trace">Trace</a>
<hr>
<h1>{{template "title" .}}</h1>
{{block "body" .}}
diff --git a/internal/lsp/debug/trace.go b/internal/lsp/debug/trace.go
new file mode 100644
index 0000000..19911ae
--- /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}}<a href="/trace/{{.Name}}">{{.Name}}</a> last: {{.Last.Duration}}, longest: {{.Longest.Duration}}<br>{{end}}
+ {{if .Selected}}
+ <H2>{{.Selected.Name}}</H2>
+ {{if .Selected.Last}}<H3>Last</H3><ul>{{template "details" .Selected.Last}}</ul>{{end}}
+ {{if .Selected.Longest}}<H3>Longest</H3><ul>{{template "details" .Selected.Longest}}</ul>{{end}}
+ {{end}}
+{{end}}
+{{define "details"}}
+ <li>{{.Offset}} {{.Name}} {{.Duration}} {{.Tags}}</li>
+ {{if .Events}}<ul class=events>{{range .Events}}<li>{{.Offset}} {{.Tags}}</li>{{end}}</ul>{{end}}
+ {{if .Children}}<ul>{{range .Children}}{{template "details" .}}{{end}}</ul>{{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 0000000..c098532
--- /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 2e73536..3ad8849 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)
+}
