github.com/graybobo/golang.org-package-offline-cache@v0.0.0-20200626051047-6608995c132f/x/net/trace/trace.go (about)

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