1// Copyright 2015 The Go Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style
3// license that can be found in the LICENSE file.
4
5/*
6Package trace implements tracing of requests and long-lived objects.
7It exports HTTP interfaces on /debug/requests and /debug/events.
8
9A trace.Trace provides tracing for short-lived objects, usually requests.
10A request handler might be implemented like this:
11
12	func fooHandler(w http.ResponseWriter, req *http.Request) {
13		tr := trace.New("mypkg.Foo", req.URL.Path)
14		defer tr.Finish()
15		...
16		tr.LazyPrintf("some event %q happened", str)
17		...
18		if err := somethingImportant(); err != nil {
19			tr.LazyPrintf("somethingImportant failed: %v", err)
20			tr.SetError()
21		}
22	}
23
24The /debug/requests HTTP endpoint organizes the traces by family,
25errors, and duration.  It also provides histogram of request duration
26for each family.
27
28A trace.EventLog provides tracing for long-lived objects, such as RPC
29connections.
30
31	// A Fetcher fetches URL paths for a single domain.
32	type Fetcher struct {
33		domain string
34		events trace.EventLog
35	}
36
37	func NewFetcher(domain string) *Fetcher {
38		return &Fetcher{
39			domain,
40			trace.NewEventLog("mypkg.Fetcher", domain),
41		}
42	}
43
44	func (f *Fetcher) Fetch(path string) (string, error) {
45		resp, err := http.Get("http://" + f.domain + "/" + path)
46		if err != nil {
47			f.events.Errorf("Get(%q) = %v", path, err)
48			return "", err
49		}
50		f.events.Printf("Get(%q) = %s", path, resp.Status)
51		...
52	}
53
54	func (f *Fetcher) Close() error {
55		f.events.Finish()
56		return nil
57	}
58
59The /debug/events HTTP endpoint organizes the event logs by family and
60by time since the last error.  The expanded view displays recent log
61entries and the log's call stack.
62*/
63package trace // import "golang.org/x/net/trace"
64
65import (
66	"bytes"
67	"fmt"
68	"html/template"
69	"io"
70	"log"
71	"net"
72	"net/http"
73	"runtime"
74	"sort"
75	"strconv"
76	"sync"
77	"sync/atomic"
78	"time"
79
80	"golang.org/x/net/internal/timeseries"
81)
82
83// DebugUseAfterFinish controls whether to debug uses of Trace values after finishing.
84// FOR DEBUGGING ONLY. This will slow down the program.
85var DebugUseAfterFinish = false
86
87// AuthRequest determines whether a specific request is permitted to load the
88// /debug/requests or /debug/events pages.
89//
90// It returns two bools; the first indicates whether the page may be viewed at all,
91// and the second indicates whether sensitive events will be shown.
92//
93// AuthRequest may be replaced by a program to customize its authorization requirements.
94//
95// The default AuthRequest function returns (true, true) if and only if the request
96// comes from localhost/127.0.0.1/[::1].
97var AuthRequest = func(req *http.Request) (any, sensitive bool) {
98	// RemoteAddr is commonly in the form "IP" or "IP:port".
99	// If it is in the form "IP:port", split off the port.
100	host, _, err := net.SplitHostPort(req.RemoteAddr)
101	if err != nil {
102		host = req.RemoteAddr
103	}
104	switch host {
105	case "localhost", "127.0.0.1", "::1":
106		return true, true
107	default:
108		return false, false
109	}
110}
111
112func init() {
113	// TODO(jbd): Serve Traces from /debug/traces in the future?
114	// There is no requirement for a request to be present to have traces.
115	http.HandleFunc("/debug/requests", Traces)
116	http.HandleFunc("/debug/events", Events)
117}
118
119// Traces responds with traces from the program.
120// The package initialization registers it in http.DefaultServeMux
121// at /debug/requests.
122//
123// It performs authorization by running AuthRequest.
124func Traces(w http.ResponseWriter, req *http.Request) {
125	any, sensitive := AuthRequest(req)
126	if !any {
127		http.Error(w, "not allowed", http.StatusUnauthorized)
128		return
129	}
130	w.Header().Set("Content-Type", "text/html; charset=utf-8")
131	Render(w, req, sensitive)
132}
133
134// Events responds with a page of events collected by EventLogs.
135// The package initialization registers it in http.DefaultServeMux
136// at /debug/events.
137//
138// It performs authorization by running AuthRequest.
139func Events(w http.ResponseWriter, req *http.Request) {
140	any, sensitive := AuthRequest(req)
141	if !any {
142		http.Error(w, "not allowed", http.StatusUnauthorized)
143		return
144	}
145	w.Header().Set("Content-Type", "text/html; charset=utf-8")
146	RenderEvents(w, req, sensitive)
147}
148
149// Render renders the HTML page typically served at /debug/requests.
150// It does not do any auth checking. The request may be nil.
151//
152// Most users will use the Traces handler.
153func Render(w io.Writer, req *http.Request, sensitive bool) {
154	data := &struct {
155		Families         []string
156		ActiveTraceCount map[string]int
157		CompletedTraces  map[string]*family
158
159		// Set when a bucket has been selected.
160		Traces        traceList
161		Family        string
162		Bucket        int
163		Expanded      bool
164		Traced        bool
165		Active        bool
166		ShowSensitive bool // whether to show sensitive events
167
168		Histogram       template.HTML
169		HistogramWindow string // e.g. "last minute", "last hour", "all time"
170
171		// If non-zero, the set of traces is a partial set,
172		// and this is the total number.
173		Total int
174	}{
175		CompletedTraces: completedTraces,
176	}
177
178	data.ShowSensitive = sensitive
179	if req != nil {
180		// Allow show_sensitive=0 to force hiding of sensitive data for testing.
181		// This only goes one way; you can't use show_sensitive=1 to see things.
182		if req.FormValue("show_sensitive") == "0" {
183			data.ShowSensitive = false
184		}
185
186		if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil {
187			data.Expanded = exp
188		}
189		if exp, err := strconv.ParseBool(req.FormValue("rtraced")); err == nil {
190			data.Traced = exp
191		}
192	}
193
194	completedMu.RLock()
195	data.Families = make([]string, 0, len(completedTraces))
196	for fam := range completedTraces {
197		data.Families = append(data.Families, fam)
198	}
199	completedMu.RUnlock()
200	sort.Strings(data.Families)
201
202	// We are careful here to minimize the time spent locking activeMu,
203	// since that lock is required every time an RPC starts and finishes.
204	data.ActiveTraceCount = make(map[string]int, len(data.Families))
205	activeMu.RLock()
206	for fam, s := range activeTraces {
207		data.ActiveTraceCount[fam] = s.Len()
208	}
209	activeMu.RUnlock()
210
211	var ok bool
212	data.Family, data.Bucket, ok = parseArgs(req)
213	switch {
214	case !ok:
215		// No-op
216	case data.Bucket == -1:
217		data.Active = true
218		n := data.ActiveTraceCount[data.Family]
219		data.Traces = getActiveTraces(data.Family)
220		if len(data.Traces) < n {
221			data.Total = n
222		}
223	case data.Bucket < bucketsPerFamily:
224		if b := lookupBucket(data.Family, data.Bucket); b != nil {
225			data.Traces = b.Copy(data.Traced)
226		}
227	default:
228		if f := getFamily(data.Family, false); f != nil {
229			var obs timeseries.Observable
230			f.LatencyMu.RLock()
231			switch o := data.Bucket - bucketsPerFamily; o {
232			case 0:
233				obs = f.Latency.Minute()
234				data.HistogramWindow = "last minute"
235			case 1:
236				obs = f.Latency.Hour()
237				data.HistogramWindow = "last hour"
238			case 2:
239				obs = f.Latency.Total()
240				data.HistogramWindow = "all time"
241			}
242			f.LatencyMu.RUnlock()
243			if obs != nil {
244				data.Histogram = obs.(*histogram).html()
245			}
246		}
247	}
248
249	if data.Traces != nil {
250		defer data.Traces.Free()
251		sort.Sort(data.Traces)
252	}
253
254	completedMu.RLock()
255	defer completedMu.RUnlock()
256	if err := pageTmpl().ExecuteTemplate(w, "Page", data); err != nil {
257		log.Printf("net/trace: Failed executing template: %v", err)
258	}
259}
260
261func parseArgs(req *http.Request) (fam string, b int, ok bool) {
262	if req == nil {
263		return "", 0, false
264	}
265	fam, bStr := req.FormValue("fam"), req.FormValue("b")
266	if fam == "" || bStr == "" {
267		return "", 0, false
268	}
269	b, err := strconv.Atoi(bStr)
270	if err != nil || b < -1 {
271		return "", 0, false
272	}
273
274	return fam, b, true
275}
276
277func lookupBucket(fam string, b int) *traceBucket {
278	f := getFamily(fam, false)
279	if f == nil || b < 0 || b >= len(f.Buckets) {
280		return nil
281	}
282	return f.Buckets[b]
283}
284
285type contextKeyT string
286
287var contextKey = contextKeyT("golang.org/x/net/trace.Trace")
288
289// Trace represents an active request.
290type Trace interface {
291	// LazyLog adds x to the event log. It will be evaluated each time the
292	// /debug/requests page is rendered. Any memory referenced by x will be
293	// pinned until the trace is finished and later discarded.
294	LazyLog(x fmt.Stringer, sensitive bool)
295
296	// LazyPrintf evaluates its arguments with fmt.Sprintf each time the
297	// /debug/requests page is rendered. Any memory referenced by a will be
298	// pinned until the trace is finished and later discarded.
299	LazyPrintf(format string, a ...interface{})
300
301	// SetError declares that this trace resulted in an error.
302	SetError()
303
304	// SetRecycler sets a recycler for the trace.
305	// f will be called for each event passed to LazyLog at a time when
306	// it is no longer required, whether while the trace is still active
307	// and the event is discarded, or when a completed trace is discarded.
308	SetRecycler(f func(interface{}))
309
310	// SetTraceInfo sets the trace info for the trace.
311	// This is currently unused.
312	SetTraceInfo(traceID, spanID uint64)
313
314	// SetMaxEvents sets the maximum number of events that will be stored
315	// in the trace. This has no effect if any events have already been
316	// added to the trace.
317	SetMaxEvents(m int)
318
319	// Finish declares that this trace is complete.
320	// The trace should not be used after calling this method.
321	Finish()
322}
323
324type lazySprintf struct {
325	format string
326	a      []interface{}
327}
328
329func (l *lazySprintf) String() string {
330	return fmt.Sprintf(l.format, l.a...)
331}
332
333// New returns a new Trace with the specified family and title.
334func New(family, title string) Trace {
335	tr := newTrace()
336	tr.ref()
337	tr.Family, tr.Title = family, title
338	tr.Start = time.Now()
339	tr.maxEvents = maxEventsPerTrace
340	tr.events = tr.eventsBuf[:0]
341
342	activeMu.RLock()
343	s := activeTraces[tr.Family]
344	activeMu.RUnlock()
345	if s == nil {
346		activeMu.Lock()
347		s = activeTraces[tr.Family] // check again
348		if s == nil {
349			s = new(traceSet)
350			activeTraces[tr.Family] = s
351		}
352		activeMu.Unlock()
353	}
354	s.Add(tr)
355
356	// Trigger allocation of the completed trace structure for this family.
357	// This will cause the family to be present in the request page during
358	// the first trace of this family. We don't care about the return value,
359	// nor is there any need for this to run inline, so we execute it in its
360	// own goroutine, but only if the family isn't allocated yet.
361	completedMu.RLock()
362	if _, ok := completedTraces[tr.Family]; !ok {
363		go allocFamily(tr.Family)
364	}
365	completedMu.RUnlock()
366
367	return tr
368}
369
370func (tr *trace) Finish() {
371	elapsed := time.Now().Sub(tr.Start)
372	tr.mu.Lock()
373	tr.Elapsed = elapsed
374	tr.mu.Unlock()
375
376	if DebugUseAfterFinish {
377		buf := make([]byte, 4<<10) // 4 KB should be enough
378		n := runtime.Stack(buf, false)
379		tr.finishStack = buf[:n]
380	}
381
382	activeMu.RLock()
383	m := activeTraces[tr.Family]
384	activeMu.RUnlock()
385	m.Remove(tr)
386
387	f := getFamily(tr.Family, true)
388	tr.mu.RLock() // protects tr fields in Cond.match calls
389	for _, b := range f.Buckets {
390		if b.Cond.match(tr) {
391			b.Add(tr)
392		}
393	}
394	tr.mu.RUnlock()
395
396	// Add a sample of elapsed time as microseconds to the family's timeseries
397	h := new(histogram)
398	h.addMeasurement(elapsed.Nanoseconds() / 1e3)
399	f.LatencyMu.Lock()
400	f.Latency.Add(h)
401	f.LatencyMu.Unlock()
402
403	tr.unref() // matches ref in New
404}
405
406const (
407	bucketsPerFamily    = 9
408	tracesPerBucket     = 10
409	maxActiveTraces     = 20 // Maximum number of active traces to show.
410	maxEventsPerTrace   = 10
411	numHistogramBuckets = 38
412)
413
414var (
415	// The active traces.
416	activeMu     sync.RWMutex
417	activeTraces = make(map[string]*traceSet) // family -> traces
418
419	// Families of completed traces.
420	completedMu     sync.RWMutex
421	completedTraces = make(map[string]*family) // family -> traces
422)
423
424type traceSet struct {
425	mu sync.RWMutex
426	m  map[*trace]bool
427
428	// We could avoid the entire map scan in FirstN by having a slice of all the traces
429	// ordered by start time, and an index into that from the trace struct, with a periodic
430	// repack of the slice after enough traces finish; we could also use a skip list or similar.
431	// However, that would shift some of the expense from /debug/requests time to RPC time,
432	// which is probably the wrong trade-off.
433}
434
435func (ts *traceSet) Len() int {
436	ts.mu.RLock()
437	defer ts.mu.RUnlock()
438	return len(ts.m)
439}
440
441func (ts *traceSet) Add(tr *trace) {
442	ts.mu.Lock()
443	if ts.m == nil {
444		ts.m = make(map[*trace]bool)
445	}
446	ts.m[tr] = true
447	ts.mu.Unlock()
448}
449
450func (ts *traceSet) Remove(tr *trace) {
451	ts.mu.Lock()
452	delete(ts.m, tr)
453	ts.mu.Unlock()
454}
455
456// FirstN returns the first n traces ordered by time.
457func (ts *traceSet) FirstN(n int) traceList {
458	ts.mu.RLock()
459	defer ts.mu.RUnlock()
460
461	if n > len(ts.m) {
462		n = len(ts.m)
463	}
464	trl := make(traceList, 0, n)
465
466	// Fast path for when no selectivity is needed.
467	if n == len(ts.m) {
468		for tr := range ts.m {
469			tr.ref()
470			trl = append(trl, tr)
471		}
472		sort.Sort(trl)
473		return trl
474	}
475
476	// Pick the oldest n traces.
477	// This is inefficient. See the comment in the traceSet struct.
478	for tr := range ts.m {
479		// Put the first n traces into trl in the order they occur.
480		// When we have n, sort trl, and thereafter maintain its order.
481		if len(trl) < n {
482			tr.ref()
483			trl = append(trl, tr)
484			if len(trl) == n {
485				// This is guaranteed to happen exactly once during this loop.
486				sort.Sort(trl)
487			}
488			continue
489		}
490		if tr.Start.After(trl[n-1].Start) {
491			continue
492		}
493
494		// Find where to insert this one.
495		tr.ref()
496		i := sort.Search(n, func(i int) bool { return trl[i].Start.After(tr.Start) })
497		trl[n-1].unref()
498		copy(trl[i+1:], trl[i:])
499		trl[i] = tr
500	}
501
502	return trl
503}
504
505func getActiveTraces(fam string) traceList {
506	activeMu.RLock()
507	s := activeTraces[fam]
508	activeMu.RUnlock()
509	if s == nil {
510		return nil
511	}
512	return s.FirstN(maxActiveTraces)
513}
514
515func getFamily(fam string, allocNew bool) *family {
516	completedMu.RLock()
517	f := completedTraces[fam]
518	completedMu.RUnlock()
519	if f == nil && allocNew {
520		f = allocFamily(fam)
521	}
522	return f
523}
524
525func allocFamily(fam string) *family {
526	completedMu.Lock()
527	defer completedMu.Unlock()
528	f := completedTraces[fam]
529	if f == nil {
530		f = newFamily()
531		completedTraces[fam] = f
532	}
533	return f
534}
535
536// family represents a set of trace buckets and associated latency information.
537type family struct {
538	// traces may occur in multiple buckets.
539	Buckets [bucketsPerFamily]*traceBucket
540
541	// latency time series
542	LatencyMu sync.RWMutex
543	Latency   *timeseries.MinuteHourSeries
544}
545
546func newFamily() *family {
547	return &family{
548		Buckets: [bucketsPerFamily]*traceBucket{
549			{Cond: minCond(0)},
550			{Cond: minCond(50 * time.Millisecond)},
551			{Cond: minCond(100 * time.Millisecond)},
552			{Cond: minCond(200 * time.Millisecond)},
553			{Cond: minCond(500 * time.Millisecond)},
554			{Cond: minCond(1 * time.Second)},
555			{Cond: minCond(10 * time.Second)},
556			{Cond: minCond(100 * time.Second)},
557			{Cond: errorCond{}},
558		},
559		Latency: timeseries.NewMinuteHourSeries(func() timeseries.Observable { return new(histogram) }),
560	}
561}
562
563// traceBucket represents a size-capped bucket of historic traces,
564// along with a condition for a trace to belong to the bucket.
565type traceBucket struct {
566	Cond cond
567
568	// Ring buffer implementation of a fixed-size FIFO queue.
569	mu     sync.RWMutex
570	buf    [tracesPerBucket]*trace
571	start  int // < tracesPerBucket
572	length int // <= tracesPerBucket
573}
574
575func (b *traceBucket) Add(tr *trace) {
576	b.mu.Lock()
577	defer b.mu.Unlock()
578
579	i := b.start + b.length
580	if i >= tracesPerBucket {
581		i -= tracesPerBucket
582	}
583	if b.length == tracesPerBucket {
584		// "Remove" an element from the bucket.
585		b.buf[i].unref()
586		b.start++
587		if b.start == tracesPerBucket {
588			b.start = 0
589		}
590	}
591	b.buf[i] = tr
592	if b.length < tracesPerBucket {
593		b.length++
594	}
595	tr.ref()
596}
597
598// Copy returns a copy of the traces in the bucket.
599// If tracedOnly is true, only the traces with trace information will be returned.
600// The logs will be ref'd before returning; the caller should call
601// the Free method when it is done with them.
602// TODO(dsymonds): keep track of traced requests in separate buckets.
603func (b *traceBucket) Copy(tracedOnly bool) traceList {
604	b.mu.RLock()
605	defer b.mu.RUnlock()
606
607	trl := make(traceList, 0, b.length)
608	for i, x := 0, b.start; i < b.length; i++ {
609		tr := b.buf[x]
610		if !tracedOnly || tr.spanID != 0 {
611			tr.ref()
612			trl = append(trl, tr)
613		}
614		x++
615		if x == b.length {
616			x = 0
617		}
618	}
619	return trl
620}
621
622func (b *traceBucket) Empty() bool {
623	b.mu.RLock()
624	defer b.mu.RUnlock()
625	return b.length == 0
626}
627
628// cond represents a condition on a trace.
629type cond interface {
630	match(t *trace) bool
631	String() string
632}
633
634type minCond time.Duration
635
636func (m minCond) match(t *trace) bool { return t.Elapsed >= time.Duration(m) }
637func (m minCond) String() string      { return fmt.Sprintf("≥%gs", time.Duration(m).Seconds()) }
638
639type errorCond struct{}
640
641func (e errorCond) match(t *trace) bool { return t.IsError }
642func (e errorCond) String() string      { return "errors" }
643
644type traceList []*trace
645
646// Free calls unref on each element of the list.
647func (trl traceList) Free() {
648	for _, t := range trl {
649		t.unref()
650	}
651}
652
653// traceList may be sorted in reverse chronological order.
654func (trl traceList) Len() int           { return len(trl) }
655func (trl traceList) Less(i, j int) bool { return trl[i].Start.After(trl[j].Start) }
656func (trl traceList) Swap(i, j int)      { trl[i], trl[j] = trl[j], trl[i] }
657
658// An event is a timestamped log entry in a trace.
659type event struct {
660	When       time.Time
661	Elapsed    time.Duration // since previous event in trace
662	NewDay     bool          // whether this event is on a different day to the previous event
663	Recyclable bool          // whether this event was passed via LazyLog
664	Sensitive  bool          // whether this event contains sensitive information
665	What       interface{}   // string or fmt.Stringer
666}
667
668// WhenString returns a string representation of the elapsed time of the event.
669// It will include the date if midnight was crossed.
670func (e event) WhenString() string {
671	if e.NewDay {
672		return e.When.Format("2006/01/02 15:04:05.000000")
673	}
674	return e.When.Format("15:04:05.000000")
675}
676
677// discarded represents a number of discarded events.
678// It is stored as *discarded to make it easier to update in-place.
679type discarded int
680
681func (d *discarded) String() string {
682	return fmt.Sprintf("(%d events discarded)", int(*d))
683}
684
685// trace represents an active or complete request,
686// either sent or received by this program.
687type trace struct {
688	// Family is the top-level grouping of traces to which this belongs.
689	Family string
690
691	// Title is the title of this trace.
692	Title string
693
694	// Start time of the this trace.
695	Start time.Time
696
697	mu        sync.RWMutex
698	events    []event // Append-only sequence of events (modulo discards).
699	maxEvents int
700	recycler  func(interface{})
701	IsError   bool          // Whether this trace resulted in an error.
702	Elapsed   time.Duration // Elapsed time for this trace, zero while active.
703	traceID   uint64        // Trace information if non-zero.
704	spanID    uint64
705
706	refs int32     // how many buckets this is in
707	disc discarded // scratch space to avoid allocation
708
709	finishStack []byte // where finish was called, if DebugUseAfterFinish is set
710
711	eventsBuf [4]event // preallocated buffer in case we only log a few events
712}
713
714func (tr *trace) reset() {
715	// Clear all but the mutex. Mutexes may not be copied, even when unlocked.
716	tr.Family = ""
717	tr.Title = ""
718	tr.Start = time.Time{}
719
720	tr.mu.Lock()
721	tr.Elapsed = 0
722	tr.traceID = 0
723	tr.spanID = 0
724	tr.IsError = false
725	tr.maxEvents = 0
726	tr.events = nil
727	tr.recycler = nil
728	tr.mu.Unlock()
729
730	tr.refs = 0
731	tr.disc = 0
732	tr.finishStack = nil
733	for i := range tr.eventsBuf {
734		tr.eventsBuf[i] = event{}
735	}
736}
737
738// delta returns the elapsed time since the last event or the trace start,
739// and whether it spans midnight.
740// L >= tr.mu
741func (tr *trace) delta(t time.Time) (time.Duration, bool) {
742	if len(tr.events) == 0 {
743		return t.Sub(tr.Start), false
744	}
745	prev := tr.events[len(tr.events)-1].When
746	return t.Sub(prev), prev.Day() != t.Day()
747}
748
749func (tr *trace) addEvent(x interface{}, recyclable, sensitive bool) {
750	if DebugUseAfterFinish && tr.finishStack != nil {
751		buf := make([]byte, 4<<10) // 4 KB should be enough
752		n := runtime.Stack(buf, false)
753		log.Printf("net/trace: trace used after finish:\nFinished at:\n%s\nUsed at:\n%s", tr.finishStack, buf[:n])
754	}
755
756	/*
757		NOTE TO DEBUGGERS
758
759		If you are here because your program panicked in this code,
760		it is almost definitely the fault of code using this package,
761		and very unlikely to be the fault of this code.
762
763		The most likely scenario is that some code elsewhere is using
764		a trace.Trace after its Finish method is called.
765		You can temporarily set the DebugUseAfterFinish var
766		to help discover where that is; do not leave that var set,
767		since it makes this package much less efficient.
768	*/
769
770	e := event{When: time.Now(), What: x, Recyclable: recyclable, Sensitive: sensitive}
771	tr.mu.Lock()
772	e.Elapsed, e.NewDay = tr.delta(e.When)
773	if len(tr.events) < tr.maxEvents {
774		tr.events = append(tr.events, e)
775	} else {
776		// Discard the middle events.
777		di := int((tr.maxEvents - 1) / 2)
778		if d, ok := tr.events[di].What.(*discarded); ok {
779			(*d)++
780		} else {
781			// disc starts at two to count for the event it is replacing,
782			// plus the next one that we are about to drop.
783			tr.disc = 2
784			if tr.recycler != nil && tr.events[di].Recyclable {
785				go tr.recycler(tr.events[di].What)
786			}
787			tr.events[di].What = &tr.disc
788		}
789		// The timestamp of the discarded meta-event should be
790		// the time of the last event it is representing.
791		tr.events[di].When = tr.events[di+1].When
792
793		if tr.recycler != nil && tr.events[di+1].Recyclable {
794			go tr.recycler(tr.events[di+1].What)
795		}
796		copy(tr.events[di+1:], tr.events[di+2:])
797		tr.events[tr.maxEvents-1] = e
798	}
799	tr.mu.Unlock()
800}
801
802func (tr *trace) LazyLog(x fmt.Stringer, sensitive bool) {
803	tr.addEvent(x, true, sensitive)
804}
805
806func (tr *trace) LazyPrintf(format string, a ...interface{}) {
807	tr.addEvent(&lazySprintf{format, a}, false, false)
808}
809
810func (tr *trace) SetError() {
811	tr.mu.Lock()
812	tr.IsError = true
813	tr.mu.Unlock()
814}
815
816func (tr *trace) SetRecycler(f func(interface{})) {
817	tr.mu.Lock()
818	tr.recycler = f
819	tr.mu.Unlock()
820}
821
822func (tr *trace) SetTraceInfo(traceID, spanID uint64) {
823	tr.mu.Lock()
824	tr.traceID, tr.spanID = traceID, spanID
825	tr.mu.Unlock()
826}
827
828func (tr *trace) SetMaxEvents(m int) {
829	tr.mu.Lock()
830	// Always keep at least three events: first, discarded count, last.
831	if len(tr.events) == 0 && m > 3 {
832		tr.maxEvents = m
833	}
834	tr.mu.Unlock()
835}
836
837func (tr *trace) ref() {
838	atomic.AddInt32(&tr.refs, 1)
839}
840
841func (tr *trace) unref() {
842	if atomic.AddInt32(&tr.refs, -1) == 0 {
843		tr.mu.RLock()
844		if tr.recycler != nil {
845			// freeTrace clears tr, so we hold tr.recycler and tr.events here.
846			go func(f func(interface{}), es []event) {
847				for _, e := range es {
848					if e.Recyclable {
849						f(e.What)
850					}
851				}
852			}(tr.recycler, tr.events)
853		}
854		tr.mu.RUnlock()
855
856		freeTrace(tr)
857	}
858}
859
860func (tr *trace) When() string {
861	return tr.Start.Format("2006/01/02 15:04:05.000000")
862}
863
864func (tr *trace) ElapsedTime() string {
865	tr.mu.RLock()
866	t := tr.Elapsed
867	tr.mu.RUnlock()
868
869	if t == 0 {
870		// Active trace.
871		t = time.Since(tr.Start)
872	}
873	return fmt.Sprintf("%.6f", t.Seconds())
874}
875
876func (tr *trace) Events() []event {
877	tr.mu.RLock()
878	defer tr.mu.RUnlock()
879	return tr.events
880}
881
882var traceFreeList = make(chan *trace, 1000) // TODO(dsymonds): Use sync.Pool?
883
884// newTrace returns a trace ready to use.
885func newTrace() *trace {
886	select {
887	case tr := <-traceFreeList:
888		return tr
889	default:
890		return new(trace)
891	}
892}
893
894// freeTrace adds tr to traceFreeList if there's room.
895// This is non-blocking.
896func freeTrace(tr *trace) {
897	if DebugUseAfterFinish {
898		return // never reuse
899	}
900	tr.reset()
901	select {
902	case traceFreeList <- tr:
903	default:
904	}
905}
906
907func elapsed(d time.Duration) string {
908	b := []byte(fmt.Sprintf("%.6f", d.Seconds()))
909
910	// For subsecond durations, blank all zeros before decimal point,
911	// and all zeros between the decimal point and the first non-zero digit.
912	if d < time.Second {
913		dot := bytes.IndexByte(b, '.')
914		for i := 0; i < dot; i++ {
915			b[i] = ' '
916		}
917		for i := dot + 1; i < len(b); i++ {
918			if b[i] == '0' {
919				b[i] = ' '
920			} else {
921				break
922			}
923		}
924	}
925
926	return string(b)
927}
928
929var pageTmplCache *template.Template
930var pageTmplOnce sync.Once
931
932func pageTmpl() *template.Template {
933	pageTmplOnce.Do(func() {
934		pageTmplCache = template.Must(template.New("Page").Funcs(template.FuncMap{
935			"elapsed": elapsed,
936			"add":     func(a, b int) int { return a + b },
937		}).Parse(pageHTML))
938	})
939	return pageTmplCache
940}
941
942const pageHTML = `
943{{template "Prolog" .}}
944{{template "StatusTable" .}}
945{{template "Epilog" .}}
946
947{{define "Prolog"}}
948<html>
949	<head>
950	<title>/debug/requests</title>
951	<style type="text/css">
952		body {
953			font-family: sans-serif;
954		}
955		table#tr-status td.family {
956			padding-right: 2em;
957		}
958		table#tr-status td.active {
959			padding-right: 1em;
960		}
961		table#tr-status td.latency-first {
962			padding-left: 1em;
963		}
964		table#tr-status td.empty {
965			color: #aaa;
966		}
967		table#reqs {
968			margin-top: 1em;
969		}
970		table#reqs tr.first {
971			{{if $.Expanded}}font-weight: bold;{{end}}
972		}
973		table#reqs td {
974			font-family: monospace;
975		}
976		table#reqs td.when {
977			text-align: right;
978			white-space: nowrap;
979		}
980		table#reqs td.elapsed {
981			padding: 0 0.5em;
982			text-align: right;
983			white-space: pre;
984			width: 10em;
985		}
986		address {
987			font-size: smaller;
988			margin-top: 5em;
989		}
990	</style>
991	</head>
992	<body>
993
994<h1>/debug/requests</h1>
995{{end}} {{/* end of Prolog */}}
996
997{{define "StatusTable"}}
998<table id="tr-status">
999	{{range $fam := .Families}}
1000	<tr>
1001		<td class="family">{{$fam}}</td>
1002
1003		{{$n := index $.ActiveTraceCount $fam}}
1004		<td class="active {{if not $n}}empty{{end}}">
1005			{{if $n}}<a href="?fam={{$fam}}&b=-1{{if $.Expanded}}&exp=1{{end}}">{{end}}
1006			[{{$n}} active]
1007			{{if $n}}</a>{{end}}
1008		</td>
1009
1010		{{$f := index $.CompletedTraces $fam}}
1011		{{range $i, $b := $f.Buckets}}
1012		{{$empty := $b.Empty}}
1013		<td {{if $empty}}class="empty"{{end}}>
1014		{{if not $empty}}<a href="?fam={{$fam}}&b={{$i}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
1015		[{{.Cond}}]
1016		{{if not $empty}}</a>{{end}}
1017		</td>
1018		{{end}}
1019
1020		{{$nb := len $f.Buckets}}
1021		<td class="latency-first">
1022		<a href="?fam={{$fam}}&b={{$nb}}">[minute]</a>
1023		</td>
1024		<td>
1025		<a href="?fam={{$fam}}&b={{add $nb 1}}">[hour]</a>
1026		</td>
1027		<td>
1028		<a href="?fam={{$fam}}&b={{add $nb 2}}">[total]</a>
1029		</td>
1030
1031	</tr>
1032	{{end}}
1033</table>
1034{{end}} {{/* end of StatusTable */}}
1035
1036{{define "Epilog"}}
1037{{if $.Traces}}
1038<hr />
1039<h3>Family: {{$.Family}}</h3>
1040
1041{{if or $.Expanded $.Traced}}
1042  <a href="?fam={{$.Family}}&b={{$.Bucket}}">[Normal/Summary]</a>
1043{{else}}
1044  [Normal/Summary]
1045{{end}}
1046
1047{{if or (not $.Expanded) $.Traced}}
1048  <a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">[Normal/Expanded]</a>
1049{{else}}
1050  [Normal/Expanded]
1051{{end}}
1052
1053{{if not $.Active}}
1054	{{if or $.Expanded (not $.Traced)}}
1055	<a href="?fam={{$.Family}}&b={{$.Bucket}}&rtraced=1">[Traced/Summary]</a>
1056	{{else}}
1057	[Traced/Summary]
1058	{{end}}
1059	{{if or (not $.Expanded) (not $.Traced)}}
1060	<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1&rtraced=1">[Traced/Expanded]</a>
1061        {{else}}
1062	[Traced/Expanded]
1063	{{end}}
1064{{end}}
1065
1066{{if $.Total}}
1067<p><em>Showing <b>{{len $.Traces}}</b> of <b>{{$.Total}}</b> traces.</em></p>
1068{{end}}
1069
1070<table id="reqs">
1071	<caption>
1072		{{if $.Active}}Active{{else}}Completed{{end}} Requests
1073	</caption>
1074	<tr><th>When</th><th>Elapsed&nbsp;(s)</th></tr>
1075	{{range $tr := $.Traces}}
1076	<tr class="first">
1077		<td class="when">{{$tr.When}}</td>
1078		<td class="elapsed">{{$tr.ElapsedTime}}</td>
1079		<td>{{$tr.Title}}</td>
1080		{{/* TODO: include traceID/spanID */}}
1081	</tr>
1082	{{if $.Expanded}}
1083	{{range $tr.Events}}
1084	<tr>
1085		<td class="when">{{.WhenString}}</td>
1086		<td class="elapsed">{{elapsed .Elapsed}}</td>
1087		<td>{{if or $.ShowSensitive (not .Sensitive)}}... {{.What}}{{else}}<em>[redacted]</em>{{end}}</td>
1088	</tr>
1089	{{end}}
1090	{{end}}
1091	{{end}}
1092</table>
1093{{end}} {{/* if $.Traces */}}
1094
1095{{if $.Histogram}}
1096<h4>Latency (&micro;s) of {{$.Family}} over {{$.HistogramWindow}}</h4>
1097{{$.Histogram}}
1098{{end}} {{/* if $.Histogram */}}
1099
1100	</body>
1101</html>
1102{{end}} {{/* end of Epilog */}}
1103`
1104