123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524 |
- // 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"
- )
- var eventsTmpl = template.Must(template.New("events").Funcs(template.FuncMap{
- "elapsed": elapsed,
- "trimSpace": strings.TrimSpace,
- }).Parse(eventsHTML))
- 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; see AuthRequest for the default auth check
- // used by the handler registered on http.DefaultServeMux.
- // req may be nil.
- 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:
- }
- }
- 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>
- `
|