events.go 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532
  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. package trace
  5. import (
  6. "bytes"
  7. "fmt"
  8. "html/template"
  9. "io"
  10. "log"
  11. "net/http"
  12. "runtime"
  13. "sort"
  14. "strconv"
  15. "strings"
  16. "sync"
  17. "sync/atomic"
  18. "text/tabwriter"
  19. "time"
  20. )
  21. const maxEventsPerLog = 100
  22. type bucket struct {
  23. MaxErrAge time.Duration
  24. String string
  25. }
  26. var buckets = []bucket{
  27. {0, "total"},
  28. {10 * time.Second, "errs<10s"},
  29. {1 * time.Minute, "errs<1m"},
  30. {10 * time.Minute, "errs<10m"},
  31. {1 * time.Hour, "errs<1h"},
  32. {10 * time.Hour, "errs<10h"},
  33. {24000 * time.Hour, "errors"},
  34. }
  35. // RenderEvents renders the HTML page typically served at /debug/events.
  36. // It does not do any auth checking. The request may be nil.
  37. //
  38. // Most users will use the Events handler.
  39. func RenderEvents(w http.ResponseWriter, req *http.Request, sensitive bool) {
  40. now := time.Now()
  41. data := &struct {
  42. Families []string // family names
  43. Buckets []bucket
  44. Counts [][]int // eventLog count per family/bucket
  45. // Set when a bucket has been selected.
  46. Family string
  47. Bucket int
  48. EventLogs eventLogs
  49. Expanded bool
  50. }{
  51. Buckets: buckets,
  52. }
  53. data.Families = make([]string, 0, len(families))
  54. famMu.RLock()
  55. for name := range families {
  56. data.Families = append(data.Families, name)
  57. }
  58. famMu.RUnlock()
  59. sort.Strings(data.Families)
  60. // Count the number of eventLogs in each family for each error age.
  61. data.Counts = make([][]int, len(data.Families))
  62. for i, name := range data.Families {
  63. // TODO(sameer): move this loop under the family lock.
  64. f := getEventFamily(name)
  65. data.Counts[i] = make([]int, len(data.Buckets))
  66. for j, b := range data.Buckets {
  67. data.Counts[i][j] = f.Count(now, b.MaxErrAge)
  68. }
  69. }
  70. if req != nil {
  71. var ok bool
  72. data.Family, data.Bucket, ok = parseEventsArgs(req)
  73. if !ok {
  74. // No-op
  75. } else {
  76. data.EventLogs = getEventFamily(data.Family).Copy(now, buckets[data.Bucket].MaxErrAge)
  77. }
  78. if data.EventLogs != nil {
  79. defer data.EventLogs.Free()
  80. sort.Sort(data.EventLogs)
  81. }
  82. if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil {
  83. data.Expanded = exp
  84. }
  85. }
  86. famMu.RLock()
  87. defer famMu.RUnlock()
  88. if err := eventsTmpl().Execute(w, data); err != nil {
  89. log.Printf("net/trace: Failed executing template: %v", err)
  90. }
  91. }
  92. func parseEventsArgs(req *http.Request) (fam string, b int, ok bool) {
  93. fam, bStr := req.FormValue("fam"), req.FormValue("b")
  94. if fam == "" || bStr == "" {
  95. return "", 0, false
  96. }
  97. b, err := strconv.Atoi(bStr)
  98. if err != nil || b < 0 || b >= len(buckets) {
  99. return "", 0, false
  100. }
  101. return fam, b, true
  102. }
  103. // An EventLog provides a log of events associated with a specific object.
  104. type EventLog interface {
  105. // Printf formats its arguments with fmt.Sprintf and adds the
  106. // result to the event log.
  107. Printf(format string, a ...interface{})
  108. // Errorf is like Printf, but it marks this event as an error.
  109. Errorf(format string, a ...interface{})
  110. // Finish declares that this event log is complete.
  111. // The event log should not be used after calling this method.
  112. Finish()
  113. }
  114. // NewEventLog returns a new EventLog with the specified family name
  115. // and title.
  116. func NewEventLog(family, title string) EventLog {
  117. el := newEventLog()
  118. el.ref()
  119. el.Family, el.Title = family, title
  120. el.Start = time.Now()
  121. el.events = make([]logEntry, 0, maxEventsPerLog)
  122. el.stack = make([]uintptr, 32)
  123. n := runtime.Callers(2, el.stack)
  124. el.stack = el.stack[:n]
  125. getEventFamily(family).add(el)
  126. return el
  127. }
  128. func (el *eventLog) Finish() {
  129. getEventFamily(el.Family).remove(el)
  130. el.unref() // matches ref in New
  131. }
  132. var (
  133. famMu sync.RWMutex
  134. families = make(map[string]*eventFamily) // family name => family
  135. )
  136. func getEventFamily(fam string) *eventFamily {
  137. famMu.Lock()
  138. defer famMu.Unlock()
  139. f := families[fam]
  140. if f == nil {
  141. f = &eventFamily{}
  142. families[fam] = f
  143. }
  144. return f
  145. }
  146. type eventFamily struct {
  147. mu sync.RWMutex
  148. eventLogs eventLogs
  149. }
  150. func (f *eventFamily) add(el *eventLog) {
  151. f.mu.Lock()
  152. f.eventLogs = append(f.eventLogs, el)
  153. f.mu.Unlock()
  154. }
  155. func (f *eventFamily) remove(el *eventLog) {
  156. f.mu.Lock()
  157. defer f.mu.Unlock()
  158. for i, el0 := range f.eventLogs {
  159. if el == el0 {
  160. copy(f.eventLogs[i:], f.eventLogs[i+1:])
  161. f.eventLogs = f.eventLogs[:len(f.eventLogs)-1]
  162. return
  163. }
  164. }
  165. }
  166. func (f *eventFamily) Count(now time.Time, maxErrAge time.Duration) (n int) {
  167. f.mu.RLock()
  168. defer f.mu.RUnlock()
  169. for _, el := range f.eventLogs {
  170. if el.hasRecentError(now, maxErrAge) {
  171. n++
  172. }
  173. }
  174. return
  175. }
  176. func (f *eventFamily) Copy(now time.Time, maxErrAge time.Duration) (els eventLogs) {
  177. f.mu.RLock()
  178. defer f.mu.RUnlock()
  179. els = make(eventLogs, 0, len(f.eventLogs))
  180. for _, el := range f.eventLogs {
  181. if el.hasRecentError(now, maxErrAge) {
  182. el.ref()
  183. els = append(els, el)
  184. }
  185. }
  186. return
  187. }
  188. type eventLogs []*eventLog
  189. // Free calls unref on each element of the list.
  190. func (els eventLogs) Free() {
  191. for _, el := range els {
  192. el.unref()
  193. }
  194. }
  195. // eventLogs may be sorted in reverse chronological order.
  196. func (els eventLogs) Len() int { return len(els) }
  197. func (els eventLogs) Less(i, j int) bool { return els[i].Start.After(els[j].Start) }
  198. func (els eventLogs) Swap(i, j int) { els[i], els[j] = els[j], els[i] }
  199. // A logEntry is a timestamped log entry in an event log.
  200. type logEntry struct {
  201. When time.Time
  202. Elapsed time.Duration // since previous event in log
  203. NewDay bool // whether this event is on a different day to the previous event
  204. What string
  205. IsErr bool
  206. }
  207. // WhenString returns a string representation of the elapsed time of the event.
  208. // It will include the date if midnight was crossed.
  209. func (e logEntry) WhenString() string {
  210. if e.NewDay {
  211. return e.When.Format("2006/01/02 15:04:05.000000")
  212. }
  213. return e.When.Format("15:04:05.000000")
  214. }
  215. // An eventLog represents an active event log.
  216. type eventLog struct {
  217. // Family is the top-level grouping of event logs to which this belongs.
  218. Family string
  219. // Title is the title of this event log.
  220. Title string
  221. // Timing information.
  222. Start time.Time
  223. // Call stack where this event log was created.
  224. stack []uintptr
  225. // Append-only sequence of events.
  226. //
  227. // TODO(sameer): change this to a ring buffer to avoid the array copy
  228. // when we hit maxEventsPerLog.
  229. mu sync.RWMutex
  230. events []logEntry
  231. LastErrorTime time.Time
  232. discarded int
  233. refs int32 // how many buckets this is in
  234. }
  235. func (el *eventLog) reset() {
  236. // Clear all but the mutex. Mutexes may not be copied, even when unlocked.
  237. el.Family = ""
  238. el.Title = ""
  239. el.Start = time.Time{}
  240. el.stack = nil
  241. el.events = nil
  242. el.LastErrorTime = time.Time{}
  243. el.discarded = 0
  244. el.refs = 0
  245. }
  246. func (el *eventLog) hasRecentError(now time.Time, maxErrAge time.Duration) bool {
  247. if maxErrAge == 0 {
  248. return true
  249. }
  250. el.mu.RLock()
  251. defer el.mu.RUnlock()
  252. return now.Sub(el.LastErrorTime) < maxErrAge
  253. }
  254. // delta returns the elapsed time since the last event or the log start,
  255. // and whether it spans midnight.
  256. // L >= el.mu
  257. func (el *eventLog) delta(t time.Time) (time.Duration, bool) {
  258. if len(el.events) == 0 {
  259. return t.Sub(el.Start), false
  260. }
  261. prev := el.events[len(el.events)-1].When
  262. return t.Sub(prev), prev.Day() != t.Day()
  263. }
  264. func (el *eventLog) Printf(format string, a ...interface{}) {
  265. el.printf(false, format, a...)
  266. }
  267. func (el *eventLog) Errorf(format string, a ...interface{}) {
  268. el.printf(true, format, a...)
  269. }
  270. func (el *eventLog) printf(isErr bool, format string, a ...interface{}) {
  271. e := logEntry{When: time.Now(), IsErr: isErr, What: fmt.Sprintf(format, a...)}
  272. el.mu.Lock()
  273. e.Elapsed, e.NewDay = el.delta(e.When)
  274. if len(el.events) < maxEventsPerLog {
  275. el.events = append(el.events, e)
  276. } else {
  277. // Discard the oldest event.
  278. if el.discarded == 0 {
  279. // el.discarded starts at two to count for the event it
  280. // is replacing, plus the next one that we are about to
  281. // drop.
  282. el.discarded = 2
  283. } else {
  284. el.discarded++
  285. }
  286. // TODO(sameer): if this causes allocations on a critical path,
  287. // change eventLog.What to be a fmt.Stringer, as in trace.go.
  288. el.events[0].What = fmt.Sprintf("(%d events discarded)", el.discarded)
  289. // The timestamp of the discarded meta-event should be
  290. // the time of the last event it is representing.
  291. el.events[0].When = el.events[1].When
  292. copy(el.events[1:], el.events[2:])
  293. el.events[maxEventsPerLog-1] = e
  294. }
  295. if e.IsErr {
  296. el.LastErrorTime = e.When
  297. }
  298. el.mu.Unlock()
  299. }
  300. func (el *eventLog) ref() {
  301. atomic.AddInt32(&el.refs, 1)
  302. }
  303. func (el *eventLog) unref() {
  304. if atomic.AddInt32(&el.refs, -1) == 0 {
  305. freeEventLog(el)
  306. }
  307. }
  308. func (el *eventLog) When() string {
  309. return el.Start.Format("2006/01/02 15:04:05.000000")
  310. }
  311. func (el *eventLog) ElapsedTime() string {
  312. elapsed := time.Since(el.Start)
  313. return fmt.Sprintf("%.6f", elapsed.Seconds())
  314. }
  315. func (el *eventLog) Stack() string {
  316. buf := new(bytes.Buffer)
  317. tw := tabwriter.NewWriter(buf, 1, 8, 1, '\t', 0)
  318. printStackRecord(tw, el.stack)
  319. tw.Flush()
  320. return buf.String()
  321. }
  322. // printStackRecord prints the function + source line information
  323. // for a single stack trace.
  324. // Adapted from runtime/pprof/pprof.go.
  325. func printStackRecord(w io.Writer, stk []uintptr) {
  326. for _, pc := range stk {
  327. f := runtime.FuncForPC(pc)
  328. if f == nil {
  329. continue
  330. }
  331. file, line := f.FileLine(pc)
  332. name := f.Name()
  333. // Hide runtime.goexit and any runtime functions at the beginning.
  334. if strings.HasPrefix(name, "runtime.") {
  335. continue
  336. }
  337. fmt.Fprintf(w, "# %s\t%s:%d\n", name, file, line)
  338. }
  339. }
  340. func (el *eventLog) Events() []logEntry {
  341. el.mu.RLock()
  342. defer el.mu.RUnlock()
  343. return el.events
  344. }
  345. // freeEventLogs is a freelist of *eventLog
  346. var freeEventLogs = make(chan *eventLog, 1000)
  347. // newEventLog returns a event log ready to use.
  348. func newEventLog() *eventLog {
  349. select {
  350. case el := <-freeEventLogs:
  351. return el
  352. default:
  353. return new(eventLog)
  354. }
  355. }
  356. // freeEventLog adds el to freeEventLogs if there's room.
  357. // This is non-blocking.
  358. func freeEventLog(el *eventLog) {
  359. el.reset()
  360. select {
  361. case freeEventLogs <- el:
  362. default:
  363. }
  364. }
  365. var eventsTmplCache *template.Template
  366. var eventsTmplOnce sync.Once
  367. func eventsTmpl() *template.Template {
  368. eventsTmplOnce.Do(func() {
  369. eventsTmplCache = template.Must(template.New("events").Funcs(template.FuncMap{
  370. "elapsed": elapsed,
  371. "trimSpace": strings.TrimSpace,
  372. }).Parse(eventsHTML))
  373. })
  374. return eventsTmplCache
  375. }
  376. const eventsHTML = `
  377. <html>
  378. <head>
  379. <title>events</title>
  380. </head>
  381. <style type="text/css">
  382. body {
  383. font-family: sans-serif;
  384. }
  385. table#req-status td.family {
  386. padding-right: 2em;
  387. }
  388. table#req-status td.active {
  389. padding-right: 1em;
  390. }
  391. table#req-status td.empty {
  392. color: #aaa;
  393. }
  394. table#reqs {
  395. margin-top: 1em;
  396. }
  397. table#reqs tr.first {
  398. {{if $.Expanded}}font-weight: bold;{{end}}
  399. }
  400. table#reqs td {
  401. font-family: monospace;
  402. }
  403. table#reqs td.when {
  404. text-align: right;
  405. white-space: nowrap;
  406. }
  407. table#reqs td.elapsed {
  408. padding: 0 0.5em;
  409. text-align: right;
  410. white-space: pre;
  411. width: 10em;
  412. }
  413. address {
  414. font-size: smaller;
  415. margin-top: 5em;
  416. }
  417. </style>
  418. <body>
  419. <h1>/debug/events</h1>
  420. <table id="req-status">
  421. {{range $i, $fam := .Families}}
  422. <tr>
  423. <td class="family">{{$fam}}</td>
  424. {{range $j, $bucket := $.Buckets}}
  425. {{$n := index $.Counts $i $j}}
  426. <td class="{{if not $bucket.MaxErrAge}}active{{end}}{{if not $n}}empty{{end}}">
  427. {{if $n}}<a href="?fam={{$fam}}&b={{$j}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
  428. [{{$n}} {{$bucket.String}}]
  429. {{if $n}}</a>{{end}}
  430. </td>
  431. {{end}}
  432. </tr>{{end}}
  433. </table>
  434. {{if $.EventLogs}}
  435. <hr />
  436. <h3>Family: {{$.Family}}</h3>
  437. {{if $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}">{{end}}
  438. [Summary]{{if $.Expanded}}</a>{{end}}
  439. {{if not $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">{{end}}
  440. [Expanded]{{if not $.Expanded}}</a>{{end}}
  441. <table id="reqs">
  442. <tr><th>When</th><th>Elapsed</th></tr>
  443. {{range $el := $.EventLogs}}
  444. <tr class="first">
  445. <td class="when">{{$el.When}}</td>
  446. <td class="elapsed">{{$el.ElapsedTime}}</td>
  447. <td>{{$el.Title}}
  448. </tr>
  449. {{if $.Expanded}}
  450. <tr>
  451. <td class="when"></td>
  452. <td class="elapsed"></td>
  453. <td><pre>{{$el.Stack|trimSpace}}</pre></td>
  454. </tr>
  455. {{range $el.Events}}
  456. <tr>
  457. <td class="when">{{.WhenString}}</td>
  458. <td class="elapsed">{{elapsed .Elapsed}}</td>
  459. <td>.{{if .IsErr}}E{{else}}.{{end}}. {{.What}}</td>
  460. </tr>
  461. {{end}}
  462. {{end}}
  463. {{end}}
  464. </table>
  465. {{end}}
  466. </body>
  467. </html>
  468. `