vendor/golang.org/x/net/trace/events.go

   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 `