| // 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" |
| "context" |
| "fmt" |
| "html/template" |
| "net/http" |
| "runtime/trace" |
| "sort" |
| "strings" |
| "sync" |
| "time" |
| |
| "golang.org/x/tools/internal/event" |
| "golang.org/x/tools/internal/event/core" |
| "golang.org/x/tools/internal/event/export" |
| "golang.org/x/tools/internal/event/label" |
| ) |
| |
| // TraceTmpl extends BaseTemplate and renders a TraceResults, e.g. from getData(). |
| 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 class='spans'>{{template "completeSpan" .Selected.Last}}</ul>{{end}} |
| {{if .Selected.Longest}}<H3>Longest</H3><ul class='spans'>{{template "completeSpan" .Selected.Longest}}</ul>{{end}} |
| {{end}} |
| |
| <H2>Recent spans (oldest first)</H2> |
| <p> |
| A finite number of recent span start/end times are shown below. |
| The nesting represents the children of a parent span (and the log events within a span). |
| A span may appear twice: chronologically at toplevel, and nested within its parent. |
| </p> |
| <ul class='spans'>{{range .Recent}}{{template "spanStartEnd" .}}{{end}}</ul> |
| {{end}} |
| {{define "spanStartEnd"}} |
| {{if .Start}} |
| <li>{{.Span.Header .Start}}</li> |
| {{else}} |
| {{template "completeSpan" .Span}} |
| {{end}} |
| {{end}} |
| {{define "completeSpan"}} |
| <li>{{.Header false}}</li> |
| {{if .Events}}<ul>{{range .Events}}<li>{{.Header}}</li>{{end}}</ul>{{end}} |
| {{if .ChildStartEnd}}<ul>{{range .ChildStartEnd}}{{template "spanStartEnd" .}}{{end}}</ul>{{end}} |
| {{end}} |
| `)) |
| |
| type traces struct { |
| mu sync.Mutex |
| sets map[string]*traceSet |
| unfinished map[export.SpanContext]*traceSpan |
| recent []spanStartEnd |
| recentEvictions int |
| } |
| |
| // A spanStartEnd records the start or end of a span. |
| // If Start, the span may be unfinished, so some fields (e.g. Finish) |
| // may be unset and others (e.g. Events) may be being actively populated. |
| type spanStartEnd struct { |
| Start bool |
| Span *traceSpan |
| } |
| |
| func (ev spanStartEnd) Time() time.Time { |
| if ev.Start { |
| return ev.Span.Start |
| } else { |
| return ev.Span.Finish |
| } |
| } |
| |
| // A TraceResults is the subject for the /trace HTML template. |
| type TraceResults struct { // exported for testing |
| Traces []*traceSet |
| Selected *traceSet |
| Recent []spanStartEnd |
| } |
| |
| // A traceSet holds two representative spans of a given span name. |
| type traceSet struct { |
| Name string |
| Last *traceSpan |
| Longest *traceSpan |
| } |
| |
| // A traceSpan holds information about a single span. |
| type traceSpan struct { |
| TraceID export.TraceID |
| SpanID export.SpanID |
| ParentID export.SpanID |
| Name string |
| Start time.Time |
| Finish time.Time // set at end |
| Duration time.Duration // set at end |
| Tags string |
| Events []traceEvent // set at end |
| ChildStartEnd []spanStartEnd // populated while active |
| |
| parent *traceSpan |
| } |
| |
| const timeFormat = "15:04:05.000" |
| |
| // Header renders the time, name, tags, and (if !start), |
| // duration of a span start or end event. |
| func (span *traceSpan) Header(start bool) string { |
| if start { |
| return fmt.Sprintf("%s start %s %s", |
| span.Start.Format(timeFormat), span.Name, span.Tags) |
| } else { |
| return fmt.Sprintf("%s end %s (+%s) %s", |
| span.Finish.Format(timeFormat), span.Name, span.Duration, span.Tags) |
| } |
| } |
| |
| type traceEvent struct { |
| Time time.Time |
| Offset time.Duration // relative to start of span |
| Tags string |
| } |
| |
| func (ev traceEvent) Header() string { |
| return fmt.Sprintf("%s event (+%s) %s", ev.Time.Format(timeFormat), ev.Offset, ev.Tags) |
| } |
| |
| func StdTrace(exporter event.Exporter) event.Exporter { |
| return func(ctx context.Context, ev core.Event, lm label.Map) context.Context { |
| span := export.GetSpan(ctx) |
| if span == nil { |
| return exporter(ctx, ev, lm) |
| } |
| switch { |
| case event.IsStart(ev): |
| if span.ParentID.IsValid() { |
| region := trace.StartRegion(ctx, span.Name) |
| ctx = context.WithValue(ctx, traceKey, region) |
| } else { |
| var task *trace.Task |
| ctx, task = trace.NewTask(ctx, span.Name) |
| ctx = context.WithValue(ctx, traceKey, task) |
| } |
| // Log the start event as it may contain useful labels. |
| msg := formatEvent(ctx, ev, lm) |
| trace.Log(ctx, "start", msg) |
| case event.IsLog(ev): |
| category := "" |
| if event.IsError(ev) { |
| category = "error" |
| } |
| msg := formatEvent(ctx, ev, lm) |
| trace.Log(ctx, category, msg) |
| case event.IsEnd(ev): |
| if v := ctx.Value(traceKey); v != nil { |
| v.(interface{ End() }).End() |
| } |
| } |
| return exporter(ctx, ev, lm) |
| } |
| } |
| |
| func formatEvent(ctx context.Context, ev core.Event, lm label.Map) string { |
| buf := &bytes.Buffer{} |
| p := export.Printer{} |
| p.WriteEvent(buf, ev, lm) |
| return buf.String() |
| } |
| |
| func (t *traces) ProcessEvent(ctx context.Context, ev core.Event, lm label.Map) context.Context { |
| span := export.GetSpan(ctx) |
| if span == nil { |
| return ctx |
| } |
| |
| switch { |
| case event.IsStart(ev): |
| // Just starting: add it to the unfinished map. |
| // Allocate before the critical section. |
| td := &traceSpan{ |
| TraceID: span.ID.TraceID, |
| SpanID: span.ID.SpanID, |
| ParentID: span.ParentID, |
| Name: span.Name, |
| Start: span.Start().At(), |
| Tags: renderLabels(span.Start()), |
| } |
| |
| t.mu.Lock() |
| defer t.mu.Unlock() |
| |
| t.addRecentLocked(td, true) // add start event |
| |
| if t.sets == nil { |
| t.sets = make(map[string]*traceSet) |
| t.unfinished = make(map[export.SpanContext]*traceSpan) |
| } |
| t.unfinished[span.ID] = td |
| |
| // Wire up parents if we have them. |
| if span.ParentID.IsValid() { |
| parentID := export.SpanContext{TraceID: span.ID.TraceID, SpanID: span.ParentID} |
| if parent, ok := t.unfinished[parentID]; ok { |
| td.parent = parent |
| parent.ChildStartEnd = append(parent.ChildStartEnd, spanStartEnd{true, td}) |
| } |
| } |
| |
| case event.IsEnd(ev): |
| // Finishing: must be already in the map. |
| // Allocate events before the critical section. |
| events := span.Events() |
| tdEvents := make([]traceEvent, len(events)) |
| for i, event := range events { |
| tdEvents[i] = traceEvent{ |
| Time: event.At(), |
| Tags: renderLabels(event), |
| } |
| } |
| |
| t.mu.Lock() |
| defer t.mu.Unlock() |
| 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().At() |
| td.Duration = span.Finish().At().Sub(span.Start().At()) |
| td.Events = tdEvents |
| t.addRecentLocked(td, false) // add end event |
| |
| 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.parent != nil { |
| td.parent.ChildStartEnd = append(td.parent.ChildStartEnd, spanStartEnd{false, td}) |
| } else { |
| fillOffsets(td, td.Start) |
| } |
| } |
| return ctx |
| } |
| |
| // addRecentLocked appends a start or end event to the "recent" log, |
| // evicting an old entry if necessary. |
| func (t *traces) addRecentLocked(span *traceSpan, start bool) { |
| const ( |
| maxRecent = 100 // number of log entries before age-based eviction |
| maxAge = 1 * time.Minute |
| ) |
| t.recent = append(t.recent, spanStartEnd{Start: start, Span: span}) |
| |
| for len(t.recent) > maxRecent && t.recent[0].Time().Before(time.Now().Add(-maxAge)) { |
| t.recent[0] = spanStartEnd{} // aid GC |
| t.recent = t.recent[1:] |
| t.recentEvictions++ |
| |
| // Using a slice as a FIFO queue leads to unbounded growth |
| // as Go's GC cannot collect the ever-growing unused prefix. |
| // So, compact it periodically. |
| if t.recentEvictions%maxRecent == 0 { |
| t.recent = append([]spanStartEnd(nil), t.recent...) |
| } |
| } |
| } |
| |
| // getData returns the TraceResults rendered by TraceTmpl for the /trace[/name] endpoint. |
| func (t *traces) getData(req *http.Request) interface{} { |
| // TODO(adonovan): the HTTP request doesn't acquire the mutex |
| // for t or for each span! Audit and fix. |
| |
| // Sort last/longest sets by name. |
| traces := make([]*traceSet, 0, len(t.sets)) |
| for _, set := range t.sets { |
| traces = append(traces, set) |
| } |
| sort.Slice(traces, func(i, j int) bool { |
| return traces[i].Name < traces[j].Name |
| }) |
| |
| return TraceResults{ |
| Traces: traces, |
| Selected: t.sets[strings.TrimPrefix(req.URL.Path, "/trace/")], // may be nil |
| Recent: t.recent, |
| } |
| } |
| |
| func fillOffsets(td *traceSpan, start time.Time) { |
| for i := range td.Events { |
| td.Events[i].Offset = td.Events[i].Time.Sub(start) |
| } |
| for _, child := range td.ChildStartEnd { |
| if !child.Start { |
| fillOffsets(child.Span, start) |
| } |
| } |
| } |
| |
| func renderLabels(labels label.List) string { |
| buf := &bytes.Buffer{} |
| for index := 0; labels.Valid(index); index++ { |
| // The 'start' label duplicates the span name, so discard it. |
| if l := labels.Label(index); l.Valid() && l.Key().Name() != "start" { |
| fmt.Fprintf(buf, "%v ", l) |
| } |
| } |
| return buf.String() |
| } |