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