Source file src/golang.org/x/net/trace/trace.go

Documentation: golang.org/x/net/trace

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

View as plain text