// Copyright 2015 The Go Authors. All rights reserved. // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. package trace import ( "bytes" "fmt" "html/template" "io" "log" "net/http" "runtime" "sort" "strconv" "strings" "sync" "sync/atomic" "text/tabwriter" "time" ) const maxEventsPerLog = 100 type bucket struct { MaxErrAge time.Duration String string } var buckets = []bucket{ {0, "total"}, {10 * time.Second, "errs<10s"}, {1 * time.Minute, "errs<1m"}, {10 * time.Minute, "errs<10m"}, {1 * time.Hour, "errs<1h"}, {10 * time.Hour, "errs<10h"}, {24000 * time.Hour, "errors"}, } // RenderEvents renders the HTML page typically served at /debug/events. // It does not do any auth checking. The request may be nil. // // Most users will use the Events handler. func RenderEvents(w http.ResponseWriter, req *http.Request, sensitive bool) { now := time.Now() data := &struct { Families []string // family names Buckets []bucket Counts [][]int // eventLog count per family/bucket // Set when a bucket has been selected. Family string Bucket int EventLogs eventLogs Expanded bool }{ Buckets: buckets, } data.Families = make([]string, 0, len(families)) famMu.RLock() for name := range families { data.Families = append(data.Families, name) } famMu.RUnlock() sort.Strings(data.Families) // Count the number of eventLogs in each family for each error age. data.Counts = make([][]int, len(data.Families)) for i, name := range data.Families { // TODO(sameer): move this loop under the family lock. f := getEventFamily(name) data.Counts[i] = make([]int, len(data.Buckets)) for j, b := range data.Buckets { data.Counts[i][j] = f.Count(now, b.MaxErrAge) } } if req != nil { var ok bool data.Family, data.Bucket, ok = parseEventsArgs(req) if !ok { // No-op } else { data.EventLogs = getEventFamily(data.Family).Copy(now, buckets[data.Bucket].MaxErrAge) } if data.EventLogs != nil { defer data.EventLogs.Free() sort.Sort(data.EventLogs) } if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil { data.Expanded = exp } } famMu.RLock() defer famMu.RUnlock() if err := eventsTmpl().Execute(w, data); err != nil { log.Printf("net/trace: Failed executing template: %v", err) } } func parseEventsArgs(req *http.Request) (fam string, b int, ok bool) { fam, bStr := req.FormValue("fam"), req.FormValue("b") if fam == "" || bStr == "" { return "", 0, false } b, err := strconv.Atoi(bStr) if err != nil || b < 0 || b >= len(buckets) { return "", 0, false } return fam, b, true } // An EventLog provides a log of events associated with a specific object. type EventLog interface { // Printf formats its arguments with fmt.Sprintf and adds the // result to the event log. Printf(format string, a ...interface{}) // Errorf is like Printf, but it marks this event as an error. Errorf(format string, a ...interface{}) // Finish declares that this event log is complete. // The event log should not be used after calling this method. Finish() } // NewEventLog returns a new EventLog with the specified family name // and title. func NewEventLog(family, title string) EventLog { el := newEventLog() el.ref() el.Family, el.Title = family, title el.Start = time.Now() el.events = make([]logEntry, 0, maxEventsPerLog) el.stack = make([]uintptr, 32) n := runtime.Callers(2, el.stack) el.stack = el.stack[:n] getEventFamily(family).add(el) return el } func (el *eventLog) Finish() { getEventFamily(el.Family).remove(el) el.unref() // matches ref in New } var ( famMu sync.RWMutex families = make(map[string]*eventFamily) // family name => family ) func getEventFamily(fam string) *eventFamily { famMu.Lock() defer famMu.Unlock() f := families[fam] if f == nil { f = &eventFamily{} families[fam] = f } return f } type eventFamily struct { mu sync.RWMutex eventLogs eventLogs } func (f *eventFamily) add(el *eventLog) { f.mu.Lock() f.eventLogs = append(f.eventLogs, el) f.mu.Unlock() } func (f *eventFamily) remove(el *eventLog) { f.mu.Lock() defer f.mu.Unlock() for i, el0 := range f.eventLogs { if el == el0 { copy(f.eventLogs[i:], f.eventLogs[i+1:]) f.eventLogs = f.eventLogs[:len(f.eventLogs)-1] return } } } func (f *eventFamily) Count(now time.Time, maxErrAge time.Duration) (n int) { f.mu.RLock() defer f.mu.RUnlock() for _, el := range f.eventLogs { if el.hasRecentError(now, maxErrAge) { n++ } } return } func (f *eventFamily) Copy(now time.Time, maxErrAge time.Duration) (els eventLogs) { f.mu.RLock() defer f.mu.RUnlock() els = make(eventLogs, 0, len(f.eventLogs)) for _, el := range f.eventLogs { if el.hasRecentError(now, maxErrAge) { el.ref() els = append(els, el) } } return } type eventLogs []*eventLog // Free calls unref on each element of the list. func (els eventLogs) Free() { for _, el := range els { el.unref() } } // eventLogs may be sorted in reverse chronological order. func (els eventLogs) Len() int { return len(els) } func (els eventLogs) Less(i, j int) bool { return els[i].Start.After(els[j].Start) } func (els eventLogs) Swap(i, j int) { els[i], els[j] = els[j], els[i] } // A logEntry is a timestamped log entry in an event log. type logEntry struct { When time.Time Elapsed time.Duration // since previous event in log NewDay bool // whether this event is on a different day to the previous event What string IsErr bool } // WhenString returns a string representation of the elapsed time of the event. // It will include the date if midnight was crossed. func (e logEntry) WhenString() string { if e.NewDay { return e.When.Format("2006/01/02 15:04:05.000000") } return e.When.Format("15:04:05.000000") } // An eventLog represents an active event log. type eventLog struct { // Family is the top-level grouping of event logs to which this belongs. Family string // Title is the title of this event log. Title string // Timing information. Start time.Time // Call stack where this event log was created. stack []uintptr // Append-only sequence of events. // // TODO(sameer): change this to a ring buffer to avoid the array copy // when we hit maxEventsPerLog. mu sync.RWMutex events []logEntry LastErrorTime time.Time discarded int refs int32 // how many buckets this is in } func (el *eventLog) reset() { // Clear all but the mutex. Mutexes may not be copied, even when unlocked. el.Family = "" el.Title = "" el.Start = time.Time{} el.stack = nil el.events = nil el.LastErrorTime = time.Time{} el.discarded = 0 el.refs = 0 } func (el *eventLog) hasRecentError(now time.Time, maxErrAge time.Duration) bool { if maxErrAge == 0 { return true } el.mu.RLock() defer el.mu.RUnlock() return now.Sub(el.LastErrorTime) < maxErrAge } // delta returns the elapsed time since the last event or the log start, // and whether it spans midnight. // L >= el.mu func (el *eventLog) delta(t time.Time) (time.Duration, bool) { if len(el.events) == 0 { return t.Sub(el.Start), false } prev := el.events[len(el.events)-1].When return t.Sub(prev), prev.Day() != t.Day() } func (el *eventLog) Printf(format string, a ...interface{}) { el.printf(false, format, a...) } func (el *eventLog) Errorf(format string, a ...interface{}) { el.printf(true, format, a...) } func (el *eventLog) printf(isErr bool, format string, a ...interface{}) { e := logEntry{When: time.Now(), IsErr: isErr, What: fmt.Sprintf(format, a...)} el.mu.Lock() e.Elapsed, e.NewDay = el.delta(e.When) if len(el.events) < maxEventsPerLog { el.events = append(el.events, e) } else { // Discard the oldest event. if el.discarded == 0 { // el.discarded starts at two to count for the event it // is replacing, plus the next one that we are about to // drop. el.discarded = 2 } else { el.discarded++ } // TODO(sameer): if this causes allocations on a critical path, // change eventLog.What to be a fmt.Stringer, as in trace.go. el.events[0].What = fmt.Sprintf("(%d events discarded)", el.discarded) // The timestamp of the discarded meta-event should be // the time of the last event it is representing. el.events[0].When = el.events[1].When copy(el.events[1:], el.events[2:]) el.events[maxEventsPerLog-1] = e } if e.IsErr { el.LastErrorTime = e.When } el.mu.Unlock() } func (el *eventLog) ref() { atomic.AddInt32(&el.refs, 1) } func (el *eventLog) unref() { if atomic.AddInt32(&el.refs, -1) == 0 { freeEventLog(el) } } func (el *eventLog) When() string { return el.Start.Format("2006/01/02 15:04:05.000000") } func (el *eventLog) ElapsedTime() string { elapsed := time.Since(el.Start) return fmt.Sprintf("%.6f", elapsed.Seconds()) } func (el *eventLog) Stack() string { buf := new(bytes.Buffer) tw := tabwriter.NewWriter(buf, 1, 8, 1, '\t', 0) printStackRecord(tw, el.stack) tw.Flush() return buf.String() } // printStackRecord prints the function + source line information // for a single stack trace. // Adapted from runtime/pprof/pprof.go. func printStackRecord(w io.Writer, stk []uintptr) { for _, pc := range stk { f := runtime.FuncForPC(pc) if f == nil { continue } file, line := f.FileLine(pc) name := f.Name() // Hide runtime.goexit and any runtime functions at the beginning. if strings.HasPrefix(name, "runtime.") { continue } fmt.Fprintf(w, "# %s\t%s:%d\n", name, file, line) } } func (el *eventLog) Events() []logEntry { el.mu.RLock() defer el.mu.RUnlock() return el.events } // freeEventLogs is a freelist of *eventLog var freeEventLogs = make(chan *eventLog, 1000) // newEventLog returns a event log ready to use. func newEventLog() *eventLog { select { case el := <-freeEventLogs: return el default: return new(eventLog) } } // freeEventLog adds el to freeEventLogs if there's room. // This is non-blocking. func freeEventLog(el *eventLog) { el.reset() select { case freeEventLogs <- el: default: } } var eventsTmplCache *template.Template var eventsTmplOnce sync.Once func eventsTmpl() *template.Template { eventsTmplOnce.Do(func() { eventsTmplCache = template.Must(template.New("events").Funcs(template.FuncMap{ "elapsed": elapsed, "trimSpace": strings.TrimSpace, }).Parse(eventsHTML)) }) return eventsTmplCache } const eventsHTML = ` <html> <head> <title>events</title> </head> <style type="text/css"> body { font-family: sans-serif; } table#req-status td.family { padding-right: 2em; } table#req-status td.active { padding-right: 1em; } table#req-status td.empty { color: #aaa; } table#reqs { margin-top: 1em; } table#reqs tr.first { {{if $.Expanded}}font-weight: bold;{{end}} } table#reqs td { font-family: monospace; } table#reqs td.when { text-align: right; white-space: nowrap; } table#reqs td.elapsed { padding: 0 0.5em; text-align: right; white-space: pre; width: 10em; } address { font-size: smaller; margin-top: 5em; } </style> <body> <h1>/debug/events</h1> <table id="req-status"> {{range $i, $fam := .Families}} <tr> <td class="family">{{$fam}}</td> {{range $j, $bucket := $.Buckets}} {{$n := index $.Counts $i $j}} <td class="{{if not $bucket.MaxErrAge}}active{{end}}{{if not $n}}empty{{end}}"> {{if $n}}<a href="?fam={{$fam}}&b={{$j}}{{if $.Expanded}}&exp=1{{end}}">{{end}} [{{$n}} {{$bucket.String}}] {{if $n}}</a>{{end}} </td> {{end}} </tr>{{end}} </table> {{if $.EventLogs}} <hr /> <h3>Family: {{$.Family}}</h3> {{if $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}">{{end}} [Summary]{{if $.Expanded}}</a>{{end}} {{if not $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">{{end}} [Expanded]{{if not $.Expanded}}</a>{{end}} <table id="reqs"> <tr><th>When</th><th>Elapsed</th></tr> {{range $el := $.EventLogs}} <tr class="first"> <td class="when">{{$el.When}}</td> <td class="elapsed">{{$el.ElapsedTime}}</td> <td>{{$el.Title}} </tr> {{if $.Expanded}} <tr> <td class="when"></td> <td class="elapsed"></td> <td><pre>{{$el.Stack|trimSpace}}</pre></td> </tr> {{range $el.Events}} <tr> <td class="when">{{.WhenString}}</td> <td class="elapsed">{{elapsed .Elapsed}}</td> <td>.{{if .IsErr}}E{{else}}.{{end}}. {{.What}}</td> </tr> {{end}} {{end}} {{end}} </table> {{end}} </body> </html> `