532 lines
12 KiB
Go
532 lines
12 KiB
Go
// 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>
|
|
`
|