]>
Commit | Line | Data |
---|---|---|
15c0b25d AP |
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 | ` |