qbit/go
1
0
Fork 0
mirror of https://github.com/golang/go synced 2024-11-18 14:54:40 -07:00
Code Releases Activity

internal/telemetry: change tracing to be event based

Browse Source 
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 <iancottrell@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com>
This commit is contained in:
Ian Cottrell 2020-03-01 18:35:55 -05:00
parent c5a1414753
commit c4206d458c
13 changed files with 221 additions and 236 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

32
internal/lsp/debug/serve.go
View File

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

124
internal/lsp/debug/trace.go
View File

@ -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{} {

9
internal/telemetry/bench_test.go
View File

@ -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()

25
internal/telemetry/context.go
View File

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

2
internal/telemetry/event.go
View File

@ -13,6 +13,8 @@ type EventType uint8
const (
EventLog = EventType(iota)
EventStartSpan
EventEndSpan
)
type Event struct {

28
internal/telemetry/export/export.go
View File

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

6
internal/telemetry/id.go → internal/telemetry/export/id.go
View File

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

35
internal/telemetry/export/log.go
View File

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

20
internal/telemetry/export/ocagent/ocagent.go
View File

@ -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[:],

23
internal/telemetry/export/ocagent/ocagent_test.go
View File

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

88
internal/telemetry/export/trace.go Normal file
View File

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

37
internal/telemetry/trace.go
View File

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

28
internal/telemetry/trace/trace.go
View File

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