File: trace.go

package info (click to toggle)
golang-github-cue-lang-cue 0.12.0.-1
  • links: PTS, VCS
  • area: main
  • in suites: forky, sid, trixie
  • size: 19,072 kB
  • sloc: sh: 57; makefile: 17
file content (320 lines) | stat: -rw-r--r-- 9,051 bytes parent folder | download
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
// 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"

	"cuelang.org/go/internal/golangorgx/tools/event"
	"cuelang.org/go/internal/golangorgx/tools/event/core"
	"cuelang.org/go/internal/golangorgx/tools/event/export"
	"cuelang.org/go/internal/golangorgx/tools/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(ev, lm)
			trace.Log(ctx, "start", msg)
		case event.IsLog(ev):
			category := ""
			if event.IsError(ev) {
				category = "error"
			}
			msg := formatEvent(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(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) {
	t.recent = append(t.recent, spanStartEnd{Start: start, Span: span})

	const maxRecent = 100 // number of log entries before eviction
	for len(t.recent) > maxRecent {
		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()
}