events.go raw
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 famMu.RLock()
62 data.Families = make([]string, 0, len(families))
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}}</td>
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