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