events.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  package trace
     6  
     7  import (
     8  	"bytes"
     9  	"fmt"
    10  	"html/template"
    11  	"io"
    12  	"log"
    13  	"net/http"
    14  	"runtime"
    15  	"sort"
    16  	"strconv"
    17  	"strings"
    18  	"sync"
    19  	"sync/atomic"
    20  	"text/tabwriter"
    21  	"time"
    22  )
    23  
    24  const maxEventsPerLog = 100
    25  
    26  type bucket struct {
    27  	MaxErrAge time.Duration
    28  	String    string
    29  }
    30  
    31  var buckets = []bucket{
    32  	{0, "total"},
    33  	{10 * time.Second, "errs<10s"},
    34  	{1 * time.Minute, "errs<1m"},
    35  	{10 * time.Minute, "errs<10m"},
    36  	{1 * time.Hour, "errs<1h"},
    37  	{10 * time.Hour, "errs<10h"},
    38  	{24000 * time.Hour, "errors"},
    39  }
    40  
    41  // RenderEvents renders the HTML page typically served at /debug/events.
    42  // It does not do any auth checking. The request may be nil.
    43  //
    44  // Most users will use the Events handler.
    45  func RenderEvents(w http.ResponseWriter, req *http.Request, sensitive bool) {
    46  	now := time.Now()
    47  	data := &struct {
    48  		Families []string // family names
    49  		Buckets  []bucket
    50  		Counts   [][]int // eventLog count per family/bucket
    51  
    52  		// Set when a bucket has been selected.
    53  		Family    string
    54  		Bucket    int
    55  		EventLogs eventLogs
    56  		Expanded  bool
    57  	}{
    58  		Buckets: buckets,
    59  	}
    60  
    61  	data.Families = make([]string, 0, len(families))
    62  	famMu.RLock()
    63  	for name := range families {
    64  		data.Families = append(data.Families, name)
    65  	}
    66  	famMu.RUnlock()
    67  	sort.Strings(data.Families)
    68  
    69  	// Count the number of eventLogs in each family for each error age.
    70  	data.Counts = make([][]int, len(data.Families))
    71  	for i, name := range data.Families {
    72  		// TODO(sameer): move this loop under the family lock.
    73  		f := getEventFamily(name)
    74  		data.Counts[i] = make([]int, len(data.Buckets))
    75  		for j, b := range data.Buckets {
    76  			data.Counts[i][j] = f.Count(now, b.MaxErrAge)
    77  		}
    78  	}
    79  
    80  	if req != nil {
    81  		var ok bool
    82  		data.Family, data.Bucket, ok = parseEventsArgs(req)
    83  		if !ok {
    84  			// No-op
    85  		} else {
    86  			data.EventLogs = getEventFamily(data.Family).Copy(now, buckets[data.Bucket].MaxErrAge)
    87  		}
    88  		if data.EventLogs != nil {
    89  			defer data.EventLogs.Free()
    90  			sort.Sort(data.EventLogs)
    91  		}
    92  		if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil {
    93  			data.Expanded = exp
    94  		}
    95  	}
    96  
    97  	famMu.RLock()
    98  	defer famMu.RUnlock()
    99  	if err := eventsTmpl().Execute(w, data); err != nil {
   100  		log.Printf("net/trace: Failed executing template: %v", err)
   101  	}
   102  }
   103  
   104  func parseEventsArgs(req *http.Request) (fam string, b int, ok bool) {
   105  	fam, bStr := req.FormValue("fam"), req.FormValue("b")
   106  	if fam == "" || bStr == "" {
   107  		return "", 0, false
   108  	}
   109  	b, err := strconv.Atoi(bStr)
   110  	if err != nil || b < 0 || b >= len(buckets) {
   111  		return "", 0, false
   112  	}
   113  	return fam, b, true
   114  }
   115  
   116  // An EventLog provides a log of events associated with a specific object.
   117  type EventLog interface {
   118  	// Printf formats its arguments with fmt.Sprintf and adds the
   119  	// result to the event log.
   120  	Printf(format string, a ...interface{})
   121  
   122  	// Errorf is like Printf, but it marks this event as an error.
   123  	Errorf(format string, a ...interface{})
   124  
   125  	// Finish declares that this event log is complete.
   126  	// The event log should not be used after calling this method.
   127  	Finish()
   128  }
   129  
   130  // NewEventLog returns a new EventLog with the specified family name
   131  // and title.
   132  func NewEventLog(family, title string) EventLog {
   133  	el := newEventLog()
   134  	el.ref()
   135  	el.Family, el.Title = family, title
   136  	el.Start = time.Now()
   137  	el.events = make([]logEntry, 0, maxEventsPerLog)
   138  	el.stack = make([]uintptr, 32)
   139  	n := runtime.Callers(2, el.stack)
   140  	el.stack = el.stack[:n]
   141  
   142  	getEventFamily(family).add(el)
   143  	return el
   144  }
   145  
   146  func (el *eventLog) Finish() {
   147  	getEventFamily(el.Family).remove(el)
   148  	el.unref() // matches ref in New
   149  }
   150  
   151  var (
   152  	famMu    sync.RWMutex
   153  	families = make(map[string]*eventFamily) // family name => family
   154  )
   155  
   156  func getEventFamily(fam string) *eventFamily {
   157  	famMu.Lock()
   158  	defer famMu.Unlock()
   159  	f := families[fam]
   160  	if f == nil {
   161  		f = &eventFamily{}
   162  		families[fam] = f
   163  	}
   164  	return f
   165  }
   166  
   167  type eventFamily struct {
   168  	mu        sync.RWMutex
   169  	eventLogs eventLogs
   170  }
   171  
   172  func (f *eventFamily) add(el *eventLog) {
   173  	f.mu.Lock()
   174  	f.eventLogs = append(f.eventLogs, el)
   175  	f.mu.Unlock()
   176  }
   177  
   178  func (f *eventFamily) remove(el *eventLog) {
   179  	f.mu.Lock()
   180  	defer f.mu.Unlock()
   181  	for i, el0 := range f.eventLogs {
   182  		if el == el0 {
   183  			copy(f.eventLogs[i:], f.eventLogs[i+1:])
   184  			f.eventLogs = f.eventLogs[:len(f.eventLogs)-1]
   185  			return
   186  		}
   187  	}
   188  }
   189  
   190  func (f *eventFamily) Count(now time.Time, maxErrAge time.Duration) (n int) {
   191  	f.mu.RLock()
   192  	defer f.mu.RUnlock()
   193  	for _, el := range f.eventLogs {
   194  		if el.hasRecentError(now, maxErrAge) {
   195  			n++
   196  		}
   197  	}
   198  	return
   199  }
   200  
   201  func (f *eventFamily) Copy(now time.Time, maxErrAge time.Duration) (els eventLogs) {
   202  	f.mu.RLock()
   203  	defer f.mu.RUnlock()
   204  	els = make(eventLogs, 0, len(f.eventLogs))
   205  	for _, el := range f.eventLogs {
   206  		if el.hasRecentError(now, maxErrAge) {
   207  			el.ref()
   208  			els = append(els, el)
   209  		}
   210  	}
   211  	return
   212  }
   213  
   214  type eventLogs []*eventLog
   215  
   216  // Free calls unref on each element of the list.
   217  func (els eventLogs) Free() {
   218  	for _, el := range els {
   219  		el.unref()
   220  	}
   221  }
   222  
   223  // eventLogs may be sorted in reverse chronological order.
   224  func (els eventLogs) Len() int           { return len(els) }
   225  func (els eventLogs) Less(i, j int) bool { return els[i].Start.After(els[j].Start) }
   226  func (els eventLogs) Swap(i, j int)      { els[i], els[j] = els[j], els[i] }
   227  
   228  // A logEntry is a timestamped log entry in an event log.
   229  type logEntry struct {
   230  	When    time.Time
   231  	Elapsed time.Duration // since previous event in log
   232  	NewDay  bool          // whether this event is on a different day to the previous event
   233  	What    string
   234  	IsErr   bool
   235  }
   236  
   237  // WhenString returns a string representation of the elapsed time of the event.
   238  // It will include the date if midnight was crossed.
   239  func (e logEntry) WhenString() string {
   240  	if e.NewDay {
   241  		return e.When.Format("2006/01/02 15:04:05.000000")
   242  	}
   243  	return e.When.Format("15:04:05.000000")
   244  }
   245  
   246  // An eventLog represents an active event log.
   247  type eventLog struct {
   248  	// Family is the top-level grouping of event logs to which this belongs.
   249  	Family string
   250  
   251  	// Title is the title of this event log.
   252  	Title string
   253  
   254  	// Timing information.
   255  	Start time.Time
   256  
   257  	// Call stack where this event log was created.
   258  	stack []uintptr
   259  
   260  	// Append-only sequence of events.
   261  	//
   262  	// TODO(sameer): change this to a ring buffer to avoid the array copy
   263  	// when we hit maxEventsPerLog.
   264  	mu            sync.RWMutex
   265  	events        []logEntry
   266  	LastErrorTime time.Time
   267  	discarded     int
   268  
   269  	refs int32 // how many buckets this is in
   270  }
   271  
   272  func (el *eventLog) reset() {
   273  	// Clear all but the mutex. Mutexes may not be copied, even when unlocked.
   274  	el.Family = ""
   275  	el.Title = ""
   276  	el.Start = time.Time{}
   277  	el.stack = nil
   278  	el.events = nil
   279  	el.LastErrorTime = time.Time{}
   280  	el.discarded = 0
   281  	el.refs = 0
   282  }
   283  
   284  func (el *eventLog) hasRecentError(now time.Time, maxErrAge time.Duration) bool {
   285  	if maxErrAge == 0 {
   286  		return true
   287  	}
   288  	el.mu.RLock()
   289  	defer el.mu.RUnlock()
   290  	return now.Sub(el.LastErrorTime) < maxErrAge
   291  }
   292  
   293  // delta returns the elapsed time since the last event or the log start,
   294  // and whether it spans midnight.
   295  // L >= el.mu
   296  func (el *eventLog) delta(t time.Time) (time.Duration, bool) {
   297  	if len(el.events) == 0 {
   298  		return t.Sub(el.Start), false
   299  	}
   300  	prev := el.events[len(el.events)-1].When
   301  	return t.Sub(prev), prev.Day() != t.Day()
   302  
   303  }
   304  
   305  func (el *eventLog) Printf(format string, a ...interface{}) {
   306  	el.printf(false, format, a...)
   307  }
   308  
   309  func (el *eventLog) Errorf(format string, a ...interface{}) {
   310  	el.printf(true, format, a...)
   311  }
   312  
   313  func (el *eventLog) printf(isErr bool, format string, a ...interface{}) {
   314  	e := logEntry{When: time.Now(), IsErr: isErr, What: fmt.Sprintf(format, a...)}
   315  	el.mu.Lock()
   316  	e.Elapsed, e.NewDay = el.delta(e.When)
   317  	if len(el.events) < maxEventsPerLog {
   318  		el.events = append(el.events, e)
   319  	} else {
   320  		// Discard the oldest event.
   321  		if el.discarded == 0 {
   322  			// el.discarded starts at two to count for the event it
   323  			// is replacing, plus the next one that we are about to
   324  			// drop.
   325  			el.discarded = 2
   326  		} else {
   327  			el.discarded++
   328  		}
   329  		// TODO(sameer): if this causes allocations on a critical path,
   330  		// change eventLog.What to be a fmt.Stringer, as in trace.go.
   331  		el.events[0].What = fmt.Sprintf("(%d events discarded)", el.discarded)
   332  		// The timestamp of the discarded meta-event should be
   333  		// the time of the last event it is representing.
   334  		el.events[0].When = el.events[1].When
   335  		copy(el.events[1:], el.events[2:])
   336  		el.events[maxEventsPerLog-1] = e
   337  	}
   338  	if e.IsErr {
   339  		el.LastErrorTime = e.When
   340  	}
   341  	el.mu.Unlock()
   342  }
   343  
   344  func (el *eventLog) ref() {
   345  	atomic.AddInt32(&el.refs, 1)
   346  }
   347  
   348  func (el *eventLog) unref() {
   349  	if atomic.AddInt32(&el.refs, -1) == 0 {
   350  		freeEventLog(el)
   351  	}
   352  }
   353  
   354  func (el *eventLog) When() string {
   355  	return el.Start.Format("2006/01/02 15:04:05.000000")
   356  }
   357  
   358  func (el *eventLog) ElapsedTime() string {
   359  	elapsed := time.Since(el.Start)
   360  	return fmt.Sprintf("%.6f", elapsed.Seconds())
   361  }
   362  
   363  func (el *eventLog) Stack() string {
   364  	buf := new(bytes.Buffer)
   365  	tw := tabwriter.NewWriter(buf, 1, 8, 1, '\t', 0)
   366  	printStackRecord(tw, el.stack)
   367  	tw.Flush()
   368  	return buf.String()
   369  }
   370  
   371  // printStackRecord prints the function + source line information
   372  // for a single stack trace.
   373  // Adapted from runtime/pprof/pprof.go.
   374  func printStackRecord(w io.Writer, stk []uintptr) {
   375  	for _, pc := range stk {
   376  		f := runtime.FuncForPC(pc)
   377  		if f == nil {
   378  			continue
   379  		}
   380  		file, line := f.FileLine(pc)
   381  		name := f.Name()
   382  		// Hide runtime.goexit and any runtime functions at the beginning.
   383  		if strings.HasPrefix(name, "runtime.") {
   384  			continue
   385  		}
   386  		fmt.Fprintf(w, "#   %s\t%s:%d\n", name, file, line)
   387  	}
   388  }
   389  
   390  func (el *eventLog) Events() []logEntry {
   391  	el.mu.RLock()
   392  	defer el.mu.RUnlock()
   393  	return el.events
   394  }
   395  
   396  // freeEventLogs is a freelist of *eventLog
   397  var freeEventLogs = make(chan *eventLog, 1000)
   398  
   399  // newEventLog returns a event log ready to use.
   400  func newEventLog() *eventLog {
   401  	select {
   402  	case el := <-freeEventLogs:
   403  		return el
   404  	default:
   405  		return new(eventLog)
   406  	}
   407  }
   408  
   409  // freeEventLog adds el to freeEventLogs if there's room.
   410  // This is non-blocking.
   411  func freeEventLog(el *eventLog) {
   412  	el.reset()
   413  	select {
   414  	case freeEventLogs <- el:
   415  	default:
   416  	}
   417  }
   418  
   419  var eventsTmplCache *template.Template
   420  var eventsTmplOnce sync.Once
   421  
   422  func eventsTmpl() *template.Template {
   423  	eventsTmplOnce.Do(func() {
   424  		eventsTmplCache = template.Must(template.New("events").Funcs(template.FuncMap{
   425  			"elapsed":   elapsed,
   426  			"trimSpace": strings.TrimSpace,
   427  		}).Parse(eventsHTML))
   428  	})
   429  	return eventsTmplCache
   430  }
   431  
   432  const eventsHTML = `
   433  <html>
   434  	<head>
   435  		<title>events</title>
   436  	</head>
   437  	<style type="text/css">
   438  		body {
   439  			font-family: sans-serif;
   440  		}
   441  		table#req-status td.family {
   442  			padding-right: 2em;
   443  		}
   444  		table#req-status td.active {
   445  			padding-right: 1em;
   446  		}
   447  		table#req-status td.empty {
   448  			color: #aaa;
   449  		}
   450  		table#reqs {
   451  			margin-top: 1em;
   452  		}
   453  		table#reqs tr.first {
   454  			{{if $.Expanded}}font-weight: bold;{{end}}
   455  		}
   456  		table#reqs td {
   457  			font-family: monospace;
   458  		}
   459  		table#reqs td.when {
   460  			text-align: right;
   461  			white-space: nowrap;
   462  		}
   463  		table#reqs td.elapsed {
   464  			padding: 0 0.5em;
   465  			text-align: right;
   466  			white-space: pre;
   467  			width: 10em;
   468  		}
   469  		address {
   470  			font-size: smaller;
   471  			margin-top: 5em;
   472  		}
   473  	</style>
   474  	<body>
   475  
   476  <h1>/debug/events</h1>
   477  
   478  <table id="req-status">
   479  	{{range $i, $fam := .Families}}
   480  	<tr>
   481  		<td class="family">{{$fam}}</td>
   482  
   483  	        {{range $j, $bucket := $.Buckets}}
   484  	        {{$n := index $.Counts $i $j}}
   485  		<td class="{{if not $bucket.MaxErrAge}}active{{end}}{{if not $n}}empty{{end}}">
   486  	                {{if $n}}<a href="?fam={{$fam}}&b={{$j}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
   487  		        [{{$n}} {{$bucket.String}}]
   488  			{{if $n}}</a>{{end}}
   489  		</td>
   490                  {{end}}
   491  
   492  	</tr>{{end}}
   493  </table>
   494  
   495  {{if $.EventLogs}}
   496  <hr />
   497  <h3>Family: {{$.Family}}</h3>
   498  
   499  {{if $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}">{{end}}
   500  [Summary]{{if $.Expanded}}</a>{{end}}
   501  
   502  {{if not $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">{{end}}
   503  [Expanded]{{if not $.Expanded}}</a>{{end}}
   504  
   505  <table id="reqs">
   506  	<tr><th>When</th><th>Elapsed</th></tr>
   507  	{{range $el := $.EventLogs}}
   508  	<tr class="first">
   509  		<td class="when">{{$el.When}}</td>
   510  		<td class="elapsed">{{$el.ElapsedTime}}</td>
   511  		<td>{{$el.Title}}
   512  	</tr>
   513  	{{if $.Expanded}}
   514  	<tr>
   515  		<td class="when"></td>
   516  		<td class="elapsed"></td>
   517  		<td><pre>{{$el.Stack|trimSpace}}</pre></td>
   518  	</tr>
   519  	{{range $el.Events}}
   520  	<tr>
   521  		<td class="when">{{.WhenString}}</td>
   522  		<td class="elapsed">{{elapsed .Elapsed}}</td>
   523  		<td>.{{if .IsErr}}E{{else}}.{{end}}. {{.What}}</td>
   524  	</tr>
   525  	{{end}}
   526  	{{end}}
   527  	{{end}}
   528  </table>
   529  {{end}}
   530  	</body>
   531  </html>
   532  `
   533
View as plain text