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>

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;
+}
+
 </style>
 {{block "head" .}}{{end}}
 </head>
@@ -299,6 +307,7 @@ td.value {
 <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" .}}

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

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

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