Elia Battiston | be9edc1 | 2022-03-09 11:35:58 +0100 | [diff] [blame^] | 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 | ` |