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
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	tr.Elapsed = time.Now().Sub(tr.Start)
372	if DebugUseAfterFinish {
373		buf := make([]byte, 4<<10) // 4 KB should be enough
374		n := runtime.Stack(buf, false)
375		tr.finishStack = buf[:n]
376	}
377
378	activeMu.RLock()
379	m := activeTraces[tr.Family]
380	activeMu.RUnlock()
381	m.Remove(tr)
382
383	f := getFamily(tr.Family, true)
384	for _, b := range f.Buckets {
385		if b.Cond.match(tr) {
386			b.Add(tr)
387		}
388	}
389	// Add a sample of elapsed time as microseconds to the family's timeseries
390	h := new(histogram)
391	h.addMeasurement(tr.Elapsed.Nanoseconds() / 1e3)
392	f.LatencyMu.Lock()
393	f.Latency.Add(h)
394	f.LatencyMu.Unlock()
395
396	tr.unref() // matches ref in New
397}
398
399const (
400	bucketsPerFamily    = 9
401	tracesPerBucket     = 10
402	maxActiveTraces     = 20 // Maximum number of active traces to show.
403	maxEventsPerTrace   = 10
404	numHistogramBuckets = 38
405)
406
407var (
408	// The active traces.
409	activeMu     sync.RWMutex
410	activeTraces = make(map[string]*traceSet) // family -> traces
411
412	// Families of completed traces.
413	completedMu     sync.RWMutex
414	completedTraces = make(map[string]*family) // family -> traces
415)
416
417type traceSet struct {
418	mu sync.RWMutex
419	m  map[*trace]bool
420
421	// We could avoid the entire map scan in FirstN by having a slice of all the traces
422	// ordered by start time, and an index into that from the trace struct, with a periodic
423	// repack of the slice after enough traces finish; we could also use a skip list or similar.
424	// However, that would shift some of the expense from /debug/requests time to RPC time,
425	// which is probably the wrong trade-off.
426}
427
428func (ts *traceSet) Len() int {
429	ts.mu.RLock()
430	defer ts.mu.RUnlock()
431	return len(ts.m)
432}
433
434func (ts *traceSet) Add(tr *trace) {
435	ts.mu.Lock()
436	if ts.m == nil {
437		ts.m = make(map[*trace]bool)
438	}
439	ts.m[tr] = true
440	ts.mu.Unlock()
441}
442
443func (ts *traceSet) Remove(tr *trace) {
444	ts.mu.Lock()
445	delete(ts.m, tr)
446	ts.mu.Unlock()
447}
448
449// FirstN returns the first n traces ordered by time.
450func (ts *traceSet) FirstN(n int) traceList {
451	ts.mu.RLock()
452	defer ts.mu.RUnlock()
453
454	if n > len(ts.m) {
455		n = len(ts.m)
456	}
457	trl := make(traceList, 0, n)
458
459	// Fast path for when no selectivity is needed.
460	if n == len(ts.m) {
461		for tr := range ts.m {
462			tr.ref()
463			trl = append(trl, tr)
464		}
465		sort.Sort(trl)
466		return trl
467	}
468
469	// Pick the oldest n traces.
470	// This is inefficient. See the comment in the traceSet struct.
471	for tr := range ts.m {
472		// Put the first n traces into trl in the order they occur.
473		// When we have n, sort trl, and thereafter maintain its order.
474		if len(trl) < n {
475			tr.ref()
476			trl = append(trl, tr)
477			if len(trl) == n {
478				// This is guaranteed to happen exactly once during this loop.
479				sort.Sort(trl)
480			}
481			continue
482		}
483		if tr.Start.After(trl[n-1].Start) {
484			continue
485		}
486
487		// Find where to insert this one.
488		tr.ref()
489		i := sort.Search(n, func(i int) bool { return trl[i].Start.After(tr.Start) })
490		trl[n-1].unref()
491		copy(trl[i+1:], trl[i:])
492		trl[i] = tr
493	}
494
495	return trl
496}
497
498func getActiveTraces(fam string) traceList {
499	activeMu.RLock()
500	s := activeTraces[fam]
501	activeMu.RUnlock()
502	if s == nil {
503		return nil
504	}
505	return s.FirstN(maxActiveTraces)
506}
507
508func getFamily(fam string, allocNew bool) *family {
509	completedMu.RLock()
510	f := completedTraces[fam]
511	completedMu.RUnlock()
512	if f == nil && allocNew {
513		f = allocFamily(fam)
514	}
515	return f
516}
517
518func allocFamily(fam string) *family {
519	completedMu.Lock()
520	defer completedMu.Unlock()
521	f := completedTraces[fam]
522	if f == nil {
523		f = newFamily()
524		completedTraces[fam] = f
525	}
526	return f
527}
528
529// family represents a set of trace buckets and associated latency information.
530type family struct {
531	// traces may occur in multiple buckets.
532	Buckets [bucketsPerFamily]*traceBucket
533
534	// latency time series
535	LatencyMu sync.RWMutex
536	Latency   *timeseries.MinuteHourSeries
537}
538
539func newFamily() *family {
540	return &family{
541		Buckets: [bucketsPerFamily]*traceBucket{
542			{Cond: minCond(0)},
543			{Cond: minCond(50 * time.Millisecond)},
544			{Cond: minCond(100 * time.Millisecond)},
545			{Cond: minCond(200 * time.Millisecond)},
546			{Cond: minCond(500 * time.Millisecond)},
547			{Cond: minCond(1 * time.Second)},
548			{Cond: minCond(10 * time.Second)},
549			{Cond: minCond(100 * time.Second)},
550			{Cond: errorCond{}},
551		},
552		Latency: timeseries.NewMinuteHourSeries(func() timeseries.Observable { return new(histogram) }),
553	}
554}
555
556// traceBucket represents a size-capped bucket of historic traces,
557// along with a condition for a trace to belong to the bucket.
558type traceBucket struct {
559	Cond cond
560
561	// Ring buffer implementation of a fixed-size FIFO queue.
562	mu     sync.RWMutex
563	buf    [tracesPerBucket]*trace
564	start  int // < tracesPerBucket
565	length int // <= tracesPerBucket
566}
567
568func (b *traceBucket) Add(tr *trace) {
569	b.mu.Lock()
570	defer b.mu.Unlock()
571
572	i := b.start + b.length
573	if i >= tracesPerBucket {
574		i -= tracesPerBucket
575	}
576	if b.length == tracesPerBucket {
577		// "Remove" an element from the bucket.
578		b.buf[i].unref()
579		b.start++
580		if b.start == tracesPerBucket {
581			b.start = 0
582		}
583	}
584	b.buf[i] = tr
585	if b.length < tracesPerBucket {
586		b.length++
587	}
588	tr.ref()
589}
590
591// Copy returns a copy of the traces in the bucket.
592// If tracedOnly is true, only the traces with trace information will be returned.
593// The logs will be ref'd before returning; the caller should call
594// the Free method when it is done with them.
595// TODO(dsymonds): keep track of traced requests in separate buckets.
596func (b *traceBucket) Copy(tracedOnly bool) traceList {
597	b.mu.RLock()
598	defer b.mu.RUnlock()
599
600	trl := make(traceList, 0, b.length)
601	for i, x := 0, b.start; i < b.length; i++ {
602		tr := b.buf[x]
603		if !tracedOnly || tr.spanID != 0 {
604			tr.ref()
605			trl = append(trl, tr)
606		}
607		x++
608		if x == b.length {
609			x = 0
610		}
611	}
612	return trl
613}
614
615func (b *traceBucket) Empty() bool {
616	b.mu.RLock()
617	defer b.mu.RUnlock()
618	return b.length == 0
619}
620
621// cond represents a condition on a trace.
622type cond interface {
623	match(t *trace) bool
624	String() string
625}
626
627type minCond time.Duration
628
629func (m minCond) match(t *trace) bool { return t.Elapsed >= time.Duration(m) }
630func (m minCond) String() string      { return fmt.Sprintf("≥%gs", time.Duration(m).Seconds()) }
631
632type errorCond struct{}
633
634func (e errorCond) match(t *trace) bool { return t.IsError }
635func (e errorCond) String() string      { return "errors" }
636
637type traceList []*trace
638
639// Free calls unref on each element of the list.
640func (trl traceList) Free() {
641	for _, t := range trl {
642		t.unref()
643	}
644}
645
646// traceList may be sorted in reverse chronological order.
647func (trl traceList) Len() int           { return len(trl) }
648func (trl traceList) Less(i, j int) bool { return trl[i].Start.After(trl[j].Start) }
649func (trl traceList) Swap(i, j int)      { trl[i], trl[j] = trl[j], trl[i] }
650
651// An event is a timestamped log entry in a trace.
652type event struct {
653	When       time.Time
654	Elapsed    time.Duration // since previous event in trace
655	NewDay     bool          // whether this event is on a different day to the previous event
656	Recyclable bool          // whether this event was passed via LazyLog
657	Sensitive  bool          // whether this event contains sensitive information
658	What       interface{}   // string or fmt.Stringer
659}
660
661// WhenString returns a string representation of the elapsed time of the event.
662// It will include the date if midnight was crossed.
663func (e event) WhenString() string {
664	if e.NewDay {
665		return e.When.Format("2006/01/02 15:04:05.000000")
666	}
667	return e.When.Format("15:04:05.000000")
668}
669
670// discarded represents a number of discarded events.
671// It is stored as *discarded to make it easier to update in-place.
672type discarded int
673
674func (d *discarded) String() string {
675	return fmt.Sprintf("(%d events discarded)", int(*d))
676}
677
678// trace represents an active or complete request,
679// either sent or received by this program.
680type trace struct {
681	// Family is the top-level grouping of traces to which this belongs.
682	Family string
683
684	// Title is the title of this trace.
685	Title string
686
687	// Timing information.
688	Start   time.Time
689	Elapsed time.Duration // zero while active
690
691	// Trace information if non-zero.
692	traceID uint64
693	spanID  uint64
694
695	// Whether this trace resulted in an error.
696	IsError bool
697
698	// Append-only sequence of events (modulo discards).
699	mu        sync.RWMutex
700	events    []event
701	maxEvents int
702
703	refs     int32 // how many buckets this is in
704	recycler func(interface{})
705	disc     discarded // scratch space to avoid allocation
706
707	finishStack []byte // where finish was called, if DebugUseAfterFinish is set
708
709	eventsBuf [4]event // preallocated buffer in case we only log a few events
710}
711
712func (tr *trace) reset() {
713	// Clear all but the mutex. Mutexes may not be copied, even when unlocked.
714	tr.Family = ""
715	tr.Title = ""
716	tr.Start = time.Time{}
717	tr.Elapsed = 0
718	tr.traceID = 0
719	tr.spanID = 0
720	tr.IsError = false
721	tr.maxEvents = 0
722	tr.events = nil
723	tr.refs = 0
724	tr.recycler = nil
725	tr.disc = 0
726	tr.finishStack = nil
727	for i := range tr.eventsBuf {
728		tr.eventsBuf[i] = event{}
729	}
730}
731
732// delta returns the elapsed time since the last event or the trace start,
733// and whether it spans midnight.
734// L >= tr.mu
735func (tr *trace) delta(t time.Time) (time.Duration, bool) {
736	if len(tr.events) == 0 {
737		return t.Sub(tr.Start), false
738	}
739	prev := tr.events[len(tr.events)-1].When
740	return t.Sub(prev), prev.Day() != t.Day()
741}
742
743func (tr *trace) addEvent(x interface{}, recyclable, sensitive bool) {
744	if DebugUseAfterFinish && tr.finishStack != nil {
745		buf := make([]byte, 4<<10) // 4 KB should be enough
746		n := runtime.Stack(buf, false)
747		log.Printf("net/trace: trace used after finish:\nFinished at:\n%s\nUsed at:\n%s", tr.finishStack, buf[:n])
748	}
749
750	/*
751		NOTE TO DEBUGGERS
752
753		If you are here because your program panicked in this code,
754		it is almost definitely the fault of code using this package,
755		and very unlikely to be the fault of this code.
756
757		The most likely scenario is that some code elsewhere is using
758		a trace.Trace after its Finish method is called.
759		You can temporarily set the DebugUseAfterFinish var
760		to help discover where that is; do not leave that var set,
761		since it makes this package much less efficient.
762	*/
763
764	e := event{When: time.Now(), What: x, Recyclable: recyclable, Sensitive: sensitive}
765	tr.mu.Lock()
766	e.Elapsed, e.NewDay = tr.delta(e.When)
767	if len(tr.events) < tr.maxEvents {
768		tr.events = append(tr.events, e)
769	} else {
770		// Discard the middle events.
771		di := int((tr.maxEvents - 1) / 2)
772		if d, ok := tr.events[di].What.(*discarded); ok {
773			(*d)++
774		} else {
775			// disc starts at two to count for the event it is replacing,
776			// plus the next one that we are about to drop.
777			tr.disc = 2
778			if tr.recycler != nil && tr.events[di].Recyclable {
779				go tr.recycler(tr.events[di].What)
780			}
781			tr.events[di].What = &tr.disc
782		}
783		// The timestamp of the discarded meta-event should be
784		// the time of the last event it is representing.
785		tr.events[di].When = tr.events[di+1].When
786
787		if tr.recycler != nil && tr.events[di+1].Recyclable {
788			go tr.recycler(tr.events[di+1].What)
789		}
790		copy(tr.events[di+1:], tr.events[di+2:])
791		tr.events[tr.maxEvents-1] = e
792	}
793	tr.mu.Unlock()
794}
795
796func (tr *trace) LazyLog(x fmt.Stringer, sensitive bool) {
797	tr.addEvent(x, true, sensitive)
798}
799
800func (tr *trace) LazyPrintf(format string, a ...interface{}) {
801	tr.addEvent(&lazySprintf{format, a}, false, false)
802}
803
804func (tr *trace) SetError() { tr.IsError = true }
805
806func (tr *trace) SetRecycler(f func(interface{})) {
807	tr.recycler = f
808}
809
810func (tr *trace) SetTraceInfo(traceID, spanID uint64) {
811	tr.traceID, tr.spanID = traceID, spanID
812}
813
814func (tr *trace) SetMaxEvents(m int) {
815	// Always keep at least three events: first, discarded count, last.
816	if len(tr.events) == 0 && m > 3 {
817		tr.maxEvents = m
818	}
819}
820
821func (tr *trace) ref() {
822	atomic.AddInt32(&tr.refs, 1)
823}
824
825func (tr *trace) unref() {
826	if atomic.AddInt32(&tr.refs, -1) == 0 {
827		if tr.recycler != nil {
828			// freeTrace clears tr, so we hold tr.recycler and tr.events here.
829			go func(f func(interface{}), es []event) {
830				for _, e := range es {
831					if e.Recyclable {
832						f(e.What)
833					}
834				}
835			}(tr.recycler, tr.events)
836		}
837
838		freeTrace(tr)
839	}
840}
841
842func (tr *trace) When() string {
843	return tr.Start.Format("2006/01/02 15:04:05.000000")
844}
845
846func (tr *trace) ElapsedTime() string {
847	t := tr.Elapsed
848	if t == 0 {
849		// Active trace.
850		t = time.Since(tr.Start)
851	}
852	return fmt.Sprintf("%.6f", t.Seconds())
853}
854
855func (tr *trace) Events() []event {
856	tr.mu.RLock()
857	defer tr.mu.RUnlock()
858	return tr.events
859}
860
861var traceFreeList = make(chan *trace, 1000) // TODO(dsymonds): Use sync.Pool?
862
863// newTrace returns a trace ready to use.
864func newTrace() *trace {
865	select {
866	case tr := <-traceFreeList:
867		return tr
868	default:
869		return new(trace)
870	}
871}
872
873// freeTrace adds tr to traceFreeList if there's room.
874// This is non-blocking.
875func freeTrace(tr *trace) {
876	if DebugUseAfterFinish {
877		return // never reuse
878	}
879	tr.reset()
880	select {
881	case traceFreeList <- tr:
882	default:
883	}
884}
885
886func elapsed(d time.Duration) string {
887	b := []byte(fmt.Sprintf("%.6f", d.Seconds()))
888
889	// For subsecond durations, blank all zeros before decimal point,
890	// and all zeros between the decimal point and the first non-zero digit.
891	if d < time.Second {
892		dot := bytes.IndexByte(b, '.')
893		for i := 0; i < dot; i++ {
894			b[i] = ' '
895		}
896		for i := dot + 1; i < len(b); i++ {
897			if b[i] == '0' {
898				b[i] = ' '
899			} else {
900				break
901			}
902		}
903	}
904
905	return string(b)
906}
907
908var pageTmplCache *template.Template
909var pageTmplOnce sync.Once
910
911func pageTmpl() *template.Template {
912	pageTmplOnce.Do(func() {
913		pageTmplCache = template.Must(template.New("Page").Funcs(template.FuncMap{
914			"elapsed": elapsed,
915			"add":     func(a, b int) int { return a + b },
916		}).Parse(pageHTML))
917	})
918	return pageTmplCache
919}
920
921const pageHTML = `
922{{template "Prolog" .}}
923{{template "StatusTable" .}}
924{{template "Epilog" .}}
925
926{{define "Prolog"}}
927<html>
928	<head>
929	<title>/debug/requests</title>
930	<style type="text/css">
931		body {
932			font-family: sans-serif;
933		}
934		table#tr-status td.family {
935			padding-right: 2em;
936		}
937		table#tr-status td.active {
938			padding-right: 1em;
939		}
940		table#tr-status td.latency-first {
941			padding-left: 1em;
942		}
943		table#tr-status td.empty {
944			color: #aaa;
945		}
946		table#reqs {
947			margin-top: 1em;
948		}
949		table#reqs tr.first {
950			{{if $.Expanded}}font-weight: bold;{{end}}
951		}
952		table#reqs td {
953			font-family: monospace;
954		}
955		table#reqs td.when {
956			text-align: right;
957			white-space: nowrap;
958		}
959		table#reqs td.elapsed {
960			padding: 0 0.5em;
961			text-align: right;
962			white-space: pre;
963			width: 10em;
964		}
965		address {
966			font-size: smaller;
967			margin-top: 5em;
968		}
969	</style>
970	</head>
971	<body>
972
973<h1>/debug/requests</h1>
974{{end}} {{/* end of Prolog */}}
975
976{{define "StatusTable"}}
977<table id="tr-status">
978	{{range $fam := .Families}}
979	<tr>
980		<td class="family">{{$fam}}</td>
981
982		{{$n := index $.ActiveTraceCount $fam}}
983		<td class="active {{if not $n}}empty{{end}}">
984			{{if $n}}<a href="?fam={{$fam}}&b=-1{{if $.Expanded}}&exp=1{{end}}">{{end}}
985			[{{$n}} active]
986			{{if $n}}</a>{{end}}
987		</td>
988
989		{{$f := index $.CompletedTraces $fam}}
990		{{range $i, $b := $f.Buckets}}
991		{{$empty := $b.Empty}}
992		<td {{if $empty}}class="empty"{{end}}>
993		{{if not $empty}}<a href="?fam={{$fam}}&b={{$i}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
994		[{{.Cond}}]
995		{{if not $empty}}</a>{{end}}
996		</td>
997		{{end}}
998
999		{{$nb := len $f.Buckets}}
1000		<td class="latency-first">
1001		<a href="?fam={{$fam}}&b={{$nb}}">[minute]</a>
1002		</td>
1003		<td>
1004		<a href="?fam={{$fam}}&b={{add $nb 1}}">[hour]</a>
1005		</td>
1006		<td>
1007		<a href="?fam={{$fam}}&b={{add $nb 2}}">[total]</a>
1008		</td>
1009
1010	</tr>
1011	{{end}}
1012</table>
1013{{end}} {{/* end of StatusTable */}}
1014
1015{{define "Epilog"}}
1016{{if $.Traces}}
1017<hr />
1018<h3>Family: {{$.Family}}</h3>
1019
1020{{if or $.Expanded $.Traced}}
1021  <a href="?fam={{$.Family}}&b={{$.Bucket}}">[Normal/Summary]</a>
1022{{else}}
1023  [Normal/Summary]
1024{{end}}
1025
1026{{if or (not $.Expanded) $.Traced}}
1027  <a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">[Normal/Expanded]</a>
1028{{else}}
1029  [Normal/Expanded]
1030{{end}}
1031
1032{{if not $.Active}}
1033	{{if or $.Expanded (not $.Traced)}}
1034	<a href="?fam={{$.Family}}&b={{$.Bucket}}&rtraced=1">[Traced/Summary]</a>
1035	{{else}}
1036	[Traced/Summary]
1037	{{end}}
1038	{{if or (not $.Expanded) (not $.Traced)}}
1039	<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1&rtraced=1">[Traced/Expanded]</a>
1040        {{else}}
1041	[Traced/Expanded]
1042	{{end}}
1043{{end}}
1044
1045{{if $.Total}}
1046<p><em>Showing <b>{{len $.Traces}}</b> of <b>{{$.Total}}</b> traces.</em></p>
1047{{end}}
1048
1049<table id="reqs">
1050	<caption>
1051		{{if $.Active}}Active{{else}}Completed{{end}} Requests
1052	</caption>
1053	<tr><th>When</th><th>Elapsed&nbsp;(s)</th></tr>
1054	{{range $tr := $.Traces}}
1055	<tr class="first">
1056		<td class="when">{{$tr.When}}</td>
1057		<td class="elapsed">{{$tr.ElapsedTime}}</td>
1058		<td>{{$tr.Title}}</td>
1059		{{/* TODO: include traceID/spanID */}}
1060	</tr>
1061	{{if $.Expanded}}
1062	{{range $tr.Events}}
1063	<tr>
1064		<td class="when">{{.WhenString}}</td>
1065		<td class="elapsed">{{elapsed .Elapsed}}</td>
1066		<td>{{if or $.ShowSensitive (not .Sensitive)}}... {{.What}}{{else}}<em>[redacted]</em>{{end}}</td>
1067	</tr>
1068	{{end}}
1069	{{end}}
1070	{{end}}
1071</table>
1072{{end}} {{/* if $.Traces */}}
1073
1074{{if $.Histogram}}
1075<h4>Latency (&micro;s) of {{$.Family}} over {{$.HistogramWindow}}</h4>
1076{{$.Histogram}}
1077{{end}} {{/* if $.Histogram */}}
1078
1079	</body>
1080</html>
1081{{end}} {{/* end of Epilog */}}
1082`
1083