trace.go 25 KB

12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455565758596061626364656667686970717273747576777879808182838485868788899091929394959697989910010110210310410510610710810911011111211311411511611711811912012112212312412512612712812913013113213313413513613713813914014114214314414514614714814915015115215315415515615715815916016116216316416516616716816917017117217317417517617717817918018118218318418518618718818919019119219319419519619719819920020120220320420520620720820921021121221321421521621721821922022122222322422522622722822923023123223323423523623723823924024124224324424524624724824925025125225325425525625725825926026126226326426526626726826927027127227327427527627727827928028128228328428528628728828929029129229329429529629729829930030130230330430530630730830931031131231331431531631731831932032132232332432532632732832933033133233333433533633733833934034134234334434534634734834935035135235335435535635735835936036136236336436536636736836937037137237337437537637737837938038138238338438538638738838939039139239339439539639739839940040140240340440540640740840941041141241341441541641741841942042142242342442542642742842943043143243343443543643743843944044144244344444544644744844945045145245345445545645745845946046146246346446546646746846947047147247347447547647747847948048148248348448548648748848949049149249349449549649749849950050150250350450550650750850951051151251351451551651751851952052152252352452552652752852953053153253353453553653753853954054154254354454554654754854955055155255355455555655755855956056156256356456556656756856957057157257357457557657757857958058158258358458558658758858959059159259359459559659759859960060160260360460560660760860961061161261361461561661761861962062162262362462562662762862963063163263363463563663763863964064164264364464564664764864965065165265365465565665765865966066166266366466566666766866967067167267367467567667767867968068168268368468568668768868969069169269369469569669769869970070170270370470570670770870971071171271371471571671771871972072172272372472572672772872973073173273373473573673773873974074174274374474574674774874975075175275375475575675775875976076176276376476576676776876977077177277377477577677777877978078178278378478578678778878979079179279379479579679779879980080180280380480580680780880981081181281381481581681781881982082182282382482582682782882983083183283383483583683783883984084184284384484584684784884985085185285385485585685785885986086186286386486586686786886987087187287387487587687787887988088188288388488588688788888989089189289389489589689789889990090190290390490590690790890991091191291391491591691791891992092192292392492592692792892993093193293393493593693793893994094194294394494594694794894995095195295395495595695795895996096196296396496596696796896997097197297397497597697797897998098198298398498598698798898999099199299399499599699799899910001001100210031004
  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 implements tracing of requests.
  6. It exports an HTTP interface on /debug/requests.
  7. A request handler might be implemented like this:
  8. func myHandler(w http.ResponseWriter, req *http.Request) {
  9. tr := trace.New("Received", req.URL.Path)
  10. defer tr.Finish()
  11. ...
  12. tr.LazyPrintf("some event %q happened", str)
  13. ...
  14. if err := somethingImportant(); err != nil {
  15. tr.LazyPrintf("somethingImportant failed: %v", err)
  16. tr.SetError()
  17. }
  18. }
  19. */
  20. package trace // import "golang.org/x/net/trace"
  21. import (
  22. "bytes"
  23. "fmt"
  24. "html/template"
  25. "io"
  26. "log"
  27. "net"
  28. "net/http"
  29. "runtime"
  30. "sort"
  31. "strconv"
  32. "sync"
  33. "sync/atomic"
  34. "time"
  35. "golang.org/x/net/context"
  36. "golang.org/x/net/internal/timeseries"
  37. )
  38. // DebugUseAfterFinish controls whether to debug uses of Trace values after finishing.
  39. // FOR DEBUGGING ONLY. This will slow down the program.
  40. var DebugUseAfterFinish = false
  41. // AuthRequest determines whether a specific request is permitted to load the /debug/requests page.
  42. // It returns two bools; the first indicates whether the page may be viewed at all,
  43. // and the second indicates whether sensitive events will be shown.
  44. //
  45. // AuthRequest may be replaced by a program to customise its authorisation requirements.
  46. //
  47. // The default AuthRequest function returns (true, true) iff the request comes from localhost/127.0.0.1/[::1].
  48. var AuthRequest = func(req *http.Request) (any, sensitive bool) {
  49. host, _, err := net.SplitHostPort(req.RemoteAddr)
  50. switch {
  51. case err != nil: // Badly formed address; fail closed.
  52. return false, false
  53. case host == "localhost" || host == "127.0.0.1" || host == "::1":
  54. return true, true
  55. default:
  56. return false, false
  57. }
  58. }
  59. func init() {
  60. http.HandleFunc("/debug/requests", func(w http.ResponseWriter, req *http.Request) {
  61. any, sensitive := AuthRequest(req)
  62. if !any {
  63. http.Error(w, "not allowed", http.StatusUnauthorized)
  64. return
  65. }
  66. render(w, req, sensitive)
  67. })
  68. }
  69. // render renders the HTML page.
  70. // req may be nil.
  71. func render(w io.Writer, req *http.Request, sensitive bool) {
  72. data := &struct {
  73. Families []string
  74. ActiveTraceCount map[string]int
  75. CompletedTraces map[string]*family
  76. // Set when a bucket has been selected.
  77. Traces traceList
  78. Family string
  79. Bucket int
  80. Expanded bool
  81. Traced bool
  82. Active bool
  83. ShowSensitive bool // whether to show sensitive events
  84. Histogram template.HTML
  85. HistogramWindow string // e.g. "last minute", "last hour", "all time"
  86. // If non-zero, the set of traces is a partial set,
  87. // and this is the total number.
  88. Total int
  89. }{
  90. CompletedTraces: completedTraces,
  91. }
  92. data.ShowSensitive = sensitive
  93. if req != nil {
  94. // Allow show_sensitive=0 to force hiding of sensitive data for testing.
  95. // This only goes one way; you can't use show_sensitive=1 to see things.
  96. if req.FormValue("show_sensitive") == "0" {
  97. data.ShowSensitive = false
  98. }
  99. if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil {
  100. data.Expanded = exp
  101. }
  102. if exp, err := strconv.ParseBool(req.FormValue("rtraced")); err == nil {
  103. data.Traced = exp
  104. }
  105. }
  106. completedMu.RLock()
  107. data.Families = make([]string, 0, len(completedTraces))
  108. for fam, _ := range completedTraces {
  109. data.Families = append(data.Families, fam)
  110. }
  111. completedMu.RUnlock()
  112. sort.Strings(data.Families)
  113. // We are careful here to minimize the time spent locking activeMu,
  114. // since that lock is required every time an RPC starts and finishes.
  115. data.ActiveTraceCount = make(map[string]int, len(data.Families))
  116. activeMu.RLock()
  117. for fam, s := range activeTraces {
  118. data.ActiveTraceCount[fam] = s.Len()
  119. }
  120. activeMu.RUnlock()
  121. var ok bool
  122. data.Family, data.Bucket, ok = parseArgs(req)
  123. switch {
  124. case !ok:
  125. // No-op
  126. case data.Bucket == -1:
  127. data.Active = true
  128. n := data.ActiveTraceCount[data.Family]
  129. data.Traces = getActiveTraces(data.Family)
  130. if len(data.Traces) < n {
  131. data.Total = n
  132. }
  133. case data.Bucket < bucketsPerFamily:
  134. if b := lookupBucket(data.Family, data.Bucket); b != nil {
  135. data.Traces = b.Copy(data.Traced)
  136. }
  137. default:
  138. if f := getFamily(data.Family, false); f != nil {
  139. var obs timeseries.Observable
  140. f.LatencyMu.RLock()
  141. switch o := data.Bucket - bucketsPerFamily; o {
  142. case 0:
  143. obs = f.Latency.Minute()
  144. data.HistogramWindow = "last minute"
  145. case 1:
  146. obs = f.Latency.Hour()
  147. data.HistogramWindow = "last hour"
  148. case 2:
  149. obs = f.Latency.Total()
  150. data.HistogramWindow = "all time"
  151. }
  152. f.LatencyMu.RUnlock()
  153. if obs != nil {
  154. data.Histogram = obs.(*histogram).html()
  155. }
  156. }
  157. }
  158. if data.Traces != nil {
  159. defer data.Traces.Free()
  160. sort.Sort(data.Traces)
  161. }
  162. completedMu.RLock()
  163. defer completedMu.RUnlock()
  164. if err := pageTmpl.ExecuteTemplate(w, "Page", data); err != nil {
  165. log.Printf("net/trace: Failed executing template: %v", err)
  166. }
  167. }
  168. func parseArgs(req *http.Request) (fam string, b int, ok bool) {
  169. if req == nil {
  170. return "", 0, false
  171. }
  172. fam, bStr := req.FormValue("fam"), req.FormValue("b")
  173. if fam == "" || bStr == "" {
  174. return "", 0, false
  175. }
  176. b, err := strconv.Atoi(bStr)
  177. if err != nil || b < -1 {
  178. return "", 0, false
  179. }
  180. return fam, b, true
  181. }
  182. func lookupBucket(fam string, b int) *traceBucket {
  183. f := getFamily(fam, false)
  184. if f == nil || b < 0 || b >= len(f.Buckets) {
  185. return nil
  186. }
  187. return f.Buckets[b]
  188. }
  189. type contextKeyT string
  190. var contextKey = contextKeyT("golang.org/x/net/trace.Trace")
  191. // NewContext returns a copy of the parent context
  192. // and associates it with a Trace.
  193. func NewContext(ctx context.Context, tr Trace) context.Context {
  194. return context.WithValue(ctx, contextKey, tr)
  195. }
  196. // FromContext returns the Trace bound to the context, if any.
  197. func FromContext(ctx context.Context) (tr Trace, ok bool) {
  198. tr, ok = ctx.Value(contextKey).(Trace)
  199. return
  200. }
  201. // Trace represents an active request.
  202. type Trace interface {
  203. // LazyLog adds x to the event log. It will be evaluated each time the
  204. // /debug/requests page is rendered. Any memory referenced by x will be
  205. // pinned until the trace is finished and later discarded.
  206. LazyLog(x fmt.Stringer, sensitive bool)
  207. // LazyPrintf evaluates its arguments with fmt.Sprintf each time the
  208. // /debug/requests page is rendered. Any memory referenced by a will be
  209. // pinned until the trace is finished and later discarded.
  210. LazyPrintf(format string, a ...interface{})
  211. // SetError declares that this trace resulted in an error.
  212. SetError()
  213. // SetRecycler sets a recycler for the trace.
  214. // f will be called for each event passed to LazyLog at a time when
  215. // it is no longer required, whether while the trace is still active
  216. // and the event is discarded, or when a completed trace is discarded.
  217. SetRecycler(f func(interface{}))
  218. // SetTraceInfo sets the trace info for the trace.
  219. // This is currently unused.
  220. SetTraceInfo(traceID, spanID uint64)
  221. // SetMaxEvents sets the maximum number of events that will be stored
  222. // in the trace. This has no effect if any events have already been
  223. // added to the trace.
  224. SetMaxEvents(m int)
  225. // Finish declares that this trace is complete.
  226. // The trace should not be used after calling this method.
  227. Finish()
  228. }
  229. type lazySprintf struct {
  230. format string
  231. a []interface{}
  232. }
  233. func (l *lazySprintf) String() string {
  234. return fmt.Sprintf(l.format, l.a...)
  235. }
  236. // New returns a new Trace with the specified family and title.
  237. func New(family, title string) Trace {
  238. tr := newTrace()
  239. tr.ref()
  240. tr.Family, tr.Title = family, title
  241. tr.Start = time.Now()
  242. tr.events = make([]event, 0, maxEventsPerTrace)
  243. activeMu.RLock()
  244. s := activeTraces[tr.Family]
  245. activeMu.RUnlock()
  246. if s == nil {
  247. activeMu.Lock()
  248. s = activeTraces[tr.Family] // check again
  249. if s == nil {
  250. s = new(traceSet)
  251. activeTraces[tr.Family] = s
  252. }
  253. activeMu.Unlock()
  254. }
  255. s.Add(tr)
  256. // Trigger allocation of the completed trace structure for this family.
  257. // This will cause the family to be present in the request page during
  258. // the first trace of this family. We don't care about the return value,
  259. // nor is there any need for this to run inline, so we execute it in its
  260. // own goroutine, but only if the family isn't allocated yet.
  261. completedMu.RLock()
  262. if _, ok := completedTraces[tr.Family]; !ok {
  263. go allocFamily(tr.Family)
  264. }
  265. completedMu.RUnlock()
  266. return tr
  267. }
  268. func (tr *trace) Finish() {
  269. tr.Elapsed = time.Now().Sub(tr.Start)
  270. if DebugUseAfterFinish {
  271. buf := make([]byte, 4<<10) // 4 KB should be enough
  272. n := runtime.Stack(buf, false)
  273. tr.finishStack = buf[:n]
  274. }
  275. activeMu.RLock()
  276. m := activeTraces[tr.Family]
  277. activeMu.RUnlock()
  278. m.Remove(tr)
  279. f := getFamily(tr.Family, true)
  280. for _, b := range f.Buckets {
  281. if b.Cond.match(tr) {
  282. b.Add(tr)
  283. }
  284. }
  285. // Add a sample of elapsed time as microseconds to the family's timeseries
  286. h := new(histogram)
  287. h.addMeasurement(tr.Elapsed.Nanoseconds() / 1e3)
  288. f.LatencyMu.Lock()
  289. f.Latency.Add(h)
  290. f.LatencyMu.Unlock()
  291. tr.unref() // matches ref in New
  292. }
  293. const (
  294. bucketsPerFamily = 9
  295. tracesPerBucket = 10
  296. maxActiveTraces = 20 // Maximum number of active traces to show.
  297. maxEventsPerTrace = 10
  298. numHistogramBuckets = 38
  299. )
  300. var (
  301. // The active traces.
  302. activeMu sync.RWMutex
  303. activeTraces = make(map[string]*traceSet) // family -> traces
  304. // Families of completed traces.
  305. completedMu sync.RWMutex
  306. completedTraces = make(map[string]*family) // family -> traces
  307. )
  308. type traceSet struct {
  309. mu sync.RWMutex
  310. m map[*trace]bool
  311. // We could avoid the entire map scan in FirstN by having a slice of all the traces
  312. // ordered by start time, and an index into that from the trace struct, with a periodic
  313. // repack of the slice after enough traces finish; we could also use a skip list or similar.
  314. // However, that would shift some of the expense from /debug/requests time to RPC time,
  315. // which is probably the wrong trade-off.
  316. }
  317. func (ts *traceSet) Len() int {
  318. ts.mu.RLock()
  319. defer ts.mu.RUnlock()
  320. return len(ts.m)
  321. }
  322. func (ts *traceSet) Add(tr *trace) {
  323. ts.mu.Lock()
  324. if ts.m == nil {
  325. ts.m = make(map[*trace]bool)
  326. }
  327. ts.m[tr] = true
  328. ts.mu.Unlock()
  329. }
  330. func (ts *traceSet) Remove(tr *trace) {
  331. ts.mu.Lock()
  332. delete(ts.m, tr)
  333. ts.mu.Unlock()
  334. }
  335. // FirstN returns the first n traces ordered by time.
  336. func (ts *traceSet) FirstN(n int) traceList {
  337. ts.mu.RLock()
  338. defer ts.mu.RUnlock()
  339. if n > len(ts.m) {
  340. n = len(ts.m)
  341. }
  342. trl := make(traceList, 0, n)
  343. // Fast path for when no selectivity is needed.
  344. if n == len(ts.m) {
  345. for tr := range ts.m {
  346. tr.ref()
  347. trl = append(trl, tr)
  348. }
  349. sort.Sort(trl)
  350. return trl
  351. }
  352. // Pick the oldest n traces.
  353. // This is inefficient. See the comment in the traceSet struct.
  354. for tr := range ts.m {
  355. // Put the first n traces into trl in the order they occur.
  356. // When we have n, sort trl, and thereafter maintain its order.
  357. if len(trl) < n {
  358. tr.ref()
  359. trl = append(trl, tr)
  360. if len(trl) == n {
  361. // This is guaranteed to happen exactly once during this loop.
  362. sort.Sort(trl)
  363. }
  364. continue
  365. }
  366. if tr.Start.After(trl[n-1].Start) {
  367. continue
  368. }
  369. // Find where to insert this one.
  370. tr.ref()
  371. i := sort.Search(n, func(i int) bool { return trl[i].Start.After(tr.Start) })
  372. trl[n-1].unref()
  373. copy(trl[i+1:], trl[i:])
  374. trl[i] = tr
  375. }
  376. return trl
  377. }
  378. func getActiveTraces(fam string) traceList {
  379. activeMu.RLock()
  380. s := activeTraces[fam]
  381. activeMu.RUnlock()
  382. if s == nil {
  383. return nil
  384. }
  385. return s.FirstN(maxActiveTraces)
  386. }
  387. func getFamily(fam string, allocNew bool) *family {
  388. completedMu.RLock()
  389. f := completedTraces[fam]
  390. completedMu.RUnlock()
  391. if f == nil && allocNew {
  392. f = allocFamily(fam)
  393. }
  394. return f
  395. }
  396. func allocFamily(fam string) *family {
  397. completedMu.Lock()
  398. defer completedMu.Unlock()
  399. f := completedTraces[fam]
  400. if f == nil {
  401. f = newFamily()
  402. completedTraces[fam] = f
  403. }
  404. return f
  405. }
  406. // family represents a set of trace buckets and associated latency information.
  407. type family struct {
  408. // traces may occur in multiple buckets.
  409. Buckets [bucketsPerFamily]*traceBucket
  410. // latency time series
  411. LatencyMu sync.RWMutex
  412. Latency *timeseries.MinuteHourSeries
  413. }
  414. func newFamily() *family {
  415. return &family{
  416. Buckets: [bucketsPerFamily]*traceBucket{
  417. {Cond: minCond(0)},
  418. {Cond: minCond(50 * time.Millisecond)},
  419. {Cond: minCond(100 * time.Millisecond)},
  420. {Cond: minCond(200 * time.Millisecond)},
  421. {Cond: minCond(500 * time.Millisecond)},
  422. {Cond: minCond(1 * time.Second)},
  423. {Cond: minCond(10 * time.Second)},
  424. {Cond: minCond(100 * time.Second)},
  425. {Cond: errorCond{}},
  426. },
  427. Latency: timeseries.NewMinuteHourSeries(func() timeseries.Observable { return new(histogram) }),
  428. }
  429. }
  430. // traceBucket represents a size-capped bucket of historic traces,
  431. // along with a condition for a trace to belong to the bucket.
  432. type traceBucket struct {
  433. Cond cond
  434. // Ring buffer implementation of a fixed-size FIFO queue.
  435. mu sync.RWMutex
  436. buf [tracesPerBucket]*trace
  437. start int // < tracesPerBucket
  438. length int // <= tracesPerBucket
  439. }
  440. func (b *traceBucket) Add(tr *trace) {
  441. b.mu.Lock()
  442. defer b.mu.Unlock()
  443. i := b.start + b.length
  444. if i >= tracesPerBucket {
  445. i -= tracesPerBucket
  446. }
  447. if b.length == tracesPerBucket {
  448. // "Remove" an element from the bucket.
  449. b.buf[i].unref()
  450. b.start++
  451. if b.start == tracesPerBucket {
  452. b.start = 0
  453. }
  454. }
  455. b.buf[i] = tr
  456. if b.length < tracesPerBucket {
  457. b.length++
  458. }
  459. tr.ref()
  460. }
  461. // Copy returns a copy of the traces in the bucket.
  462. // If tracedOnly is true, only the traces with trace information will be returned.
  463. // The logs will be ref'd before returning; the caller should call
  464. // the Free method when it is done with them.
  465. // TODO(dsymonds): keep track of traced requests in separate buckets.
  466. func (b *traceBucket) Copy(tracedOnly bool) traceList {
  467. b.mu.RLock()
  468. defer b.mu.RUnlock()
  469. trl := make(traceList, 0, b.length)
  470. for i, x := 0, b.start; i < b.length; i++ {
  471. tr := b.buf[x]
  472. if !tracedOnly || tr.spanID != 0 {
  473. tr.ref()
  474. trl = append(trl, tr)
  475. }
  476. x++
  477. if x == b.length {
  478. x = 0
  479. }
  480. }
  481. return trl
  482. }
  483. func (b *traceBucket) Empty() bool {
  484. b.mu.RLock()
  485. defer b.mu.RUnlock()
  486. return b.length == 0
  487. }
  488. // cond represents a condition on a trace.
  489. type cond interface {
  490. match(t *trace) bool
  491. String() string
  492. }
  493. type minCond time.Duration
  494. func (m minCond) match(t *trace) bool { return t.Elapsed >= time.Duration(m) }
  495. func (m minCond) String() string { return fmt.Sprintf("≥%gs", time.Duration(m).Seconds()) }
  496. type errorCond struct{}
  497. func (e errorCond) match(t *trace) bool { return t.IsError }
  498. func (e errorCond) String() string { return "errors" }
  499. type traceList []*trace
  500. // Free calls unref on each element of the list.
  501. func (trl traceList) Free() {
  502. for _, t := range trl {
  503. t.unref()
  504. }
  505. }
  506. // traceList may be sorted in reverse chronological order.
  507. func (trl traceList) Len() int { return len(trl) }
  508. func (trl traceList) Less(i, j int) bool { return trl[i].Start.After(trl[j].Start) }
  509. func (trl traceList) Swap(i, j int) { trl[i], trl[j] = trl[j], trl[i] }
  510. // An event is a timestamped log entry in a trace.
  511. type event struct {
  512. When time.Time
  513. Elapsed time.Duration // since previous event in trace
  514. NewDay bool // whether this event is on a different day to the previous event
  515. Recyclable bool // whether this event was passed via LazyLog
  516. What interface{} // string or fmt.Stringer
  517. Sensitive bool // whether this event contains sensitive information
  518. }
  519. // WhenString returns a string representation of the elapsed time of the event.
  520. // It will include the date if midnight was crossed.
  521. func (e event) WhenString() string {
  522. if e.NewDay {
  523. return e.When.Format("2006/01/02 15:04:05.000000")
  524. }
  525. return e.When.Format("15:04:05.000000")
  526. }
  527. // discarded represents a number of discarded events.
  528. // It is stored as *discarded to make it easier to update in-place.
  529. type discarded int
  530. func (d *discarded) String() string {
  531. return fmt.Sprintf("(%d events discarded)", int(*d))
  532. }
  533. // trace represents an active or complete request,
  534. // either sent or received by this program.
  535. type trace struct {
  536. // Family is the top-level grouping of traces to which this belongs.
  537. Family string
  538. // Title is the title of this trace.
  539. Title string
  540. // Timing information.
  541. Start time.Time
  542. Elapsed time.Duration // zero while active
  543. // Trace information if non-zero.
  544. traceID uint64
  545. spanID uint64
  546. // Whether this trace resulted in an error.
  547. IsError bool
  548. // Append-only sequence of events (modulo discards).
  549. mu sync.RWMutex
  550. events []event
  551. refs int32 // how many buckets this is in
  552. recycler func(interface{})
  553. disc discarded // scratch space to avoid allocation
  554. finishStack []byte // where finish was called, if DebugUseAfterFinish is set
  555. }
  556. func (tr *trace) reset() {
  557. // Clear all but the mutex. Mutexes may not be copied, even when unlocked.
  558. tr.Family = ""
  559. tr.Title = ""
  560. tr.Start = time.Time{}
  561. tr.Elapsed = 0
  562. tr.traceID = 0
  563. tr.spanID = 0
  564. tr.IsError = false
  565. tr.events = nil
  566. tr.refs = 0
  567. tr.recycler = nil
  568. tr.disc = 0
  569. tr.finishStack = nil
  570. }
  571. // delta returns the elapsed time since the last event or the trace start,
  572. // and whether it spans midnight.
  573. // L >= tr.mu
  574. func (tr *trace) delta(t time.Time) (time.Duration, bool) {
  575. if len(tr.events) == 0 {
  576. return t.Sub(tr.Start), false
  577. }
  578. prev := tr.events[len(tr.events)-1].When
  579. return t.Sub(prev), prev.Day() != t.Day()
  580. }
  581. func (tr *trace) addEvent(x interface{}, recyclable, sensitive bool) {
  582. if DebugUseAfterFinish && tr.finishStack != nil {
  583. buf := make([]byte, 4<<10) // 4 KB should be enough
  584. n := runtime.Stack(buf, false)
  585. log.Printf("net/trace: trace used after finish:\nFinished at:\n%s\nUsed at:\n%s", tr.finishStack, buf[:n])
  586. }
  587. /*
  588. NOTE TO DEBUGGERS
  589. If you are here because your program panicked in this code,
  590. it is almost definitely the fault of code using this package,
  591. and very unlikely to be the fault of this code.
  592. The most likely scenario is that some code elsewhere is using
  593. a requestz.Trace after its Finish method is called.
  594. You can temporarily set the DebugUseAfterFinish var
  595. to help discover where that is; do not leave that var set,
  596. since it makes this package much less efficient.
  597. */
  598. e := event{When: time.Now(), What: x, Recyclable: recyclable, Sensitive: sensitive}
  599. tr.mu.Lock()
  600. e.Elapsed, e.NewDay = tr.delta(e.When)
  601. if len(tr.events) < cap(tr.events) {
  602. tr.events = append(tr.events, e)
  603. } else {
  604. // Discard the middle events.
  605. di := int((cap(tr.events) - 1) / 2)
  606. if d, ok := tr.events[di].What.(*discarded); ok {
  607. (*d)++
  608. } else {
  609. // disc starts at two to count for the event it is replacing,
  610. // plus the next one that we are about to drop.
  611. tr.disc = 2
  612. if tr.recycler != nil && tr.events[di].Recyclable {
  613. go tr.recycler(tr.events[di].What)
  614. }
  615. tr.events[di].What = &tr.disc
  616. }
  617. // The timestamp of the discarded meta-event should be
  618. // the time of the last event it is representing.
  619. tr.events[di].When = tr.events[di+1].When
  620. if tr.recycler != nil && tr.events[di+1].Recyclable {
  621. go tr.recycler(tr.events[di+1].What)
  622. }
  623. copy(tr.events[di+1:], tr.events[di+2:])
  624. tr.events[cap(tr.events)-1] = e
  625. }
  626. tr.mu.Unlock()
  627. }
  628. func (tr *trace) LazyLog(x fmt.Stringer, sensitive bool) {
  629. tr.addEvent(x, true, sensitive)
  630. }
  631. func (tr *trace) LazyPrintf(format string, a ...interface{}) {
  632. tr.addEvent(&lazySprintf{format, a}, false, false)
  633. }
  634. func (tr *trace) SetError() { tr.IsError = true }
  635. func (tr *trace) SetRecycler(f func(interface{})) {
  636. tr.recycler = f
  637. }
  638. func (tr *trace) SetTraceInfo(traceID, spanID uint64) {
  639. tr.traceID, tr.spanID = traceID, spanID
  640. }
  641. func (tr *trace) SetMaxEvents(m int) {
  642. // Always keep at least three events: first, discarded count, last.
  643. if len(tr.events) == 0 && m > 3 {
  644. tr.events = make([]event, 0, m)
  645. }
  646. }
  647. func (tr *trace) ref() {
  648. atomic.AddInt32(&tr.refs, 1)
  649. }
  650. func (tr *trace) unref() {
  651. if atomic.AddInt32(&tr.refs, -1) == 0 {
  652. if tr.recycler != nil {
  653. // freeTrace clears tr, so we hold tr.recycler and tr.events here.
  654. go func(f func(interface{}), es []event) {
  655. for _, e := range es {
  656. if e.Recyclable {
  657. f(e.What)
  658. }
  659. }
  660. }(tr.recycler, tr.events)
  661. }
  662. freeTrace(tr)
  663. }
  664. }
  665. func (tr *trace) When() string {
  666. return tr.Start.Format("2006/01/02 15:04:05.000000")
  667. }
  668. func (tr *trace) ElapsedTime() string {
  669. t := tr.Elapsed
  670. if t == 0 {
  671. // Active trace.
  672. t = time.Since(tr.Start)
  673. }
  674. return fmt.Sprintf("%.6f", t.Seconds())
  675. }
  676. func (tr *trace) Events() []event {
  677. tr.mu.RLock()
  678. defer tr.mu.RUnlock()
  679. return tr.events
  680. }
  681. var traceFreeList = make(chan *trace, 1000) // TODO(dsymonds): Use sync.Pool?
  682. // newTrace returns a trace ready to use.
  683. func newTrace() *trace {
  684. select {
  685. case tr := <-traceFreeList:
  686. return tr
  687. default:
  688. return new(trace)
  689. }
  690. }
  691. // freeTrace adds tr to traceFreeList if there's room.
  692. // This is non-blocking.
  693. func freeTrace(tr *trace) {
  694. if DebugUseAfterFinish {
  695. return // never reuse
  696. }
  697. tr.reset()
  698. select {
  699. case traceFreeList <- tr:
  700. default:
  701. }
  702. }
  703. func elapsed(d time.Duration) string {
  704. b := []byte(fmt.Sprintf("%.6f", d.Seconds()))
  705. // For subsecond durations, blank all zeros before decimal point,
  706. // and all zeros between the decimal point and the first non-zero digit.
  707. if d < time.Second {
  708. dot := bytes.IndexByte(b, '.')
  709. for i := 0; i < dot; i++ {
  710. b[i] = ' '
  711. }
  712. for i := dot + 1; i < len(b); i++ {
  713. if b[i] == '0' {
  714. b[i] = ' '
  715. } else {
  716. break
  717. }
  718. }
  719. }
  720. return string(b)
  721. }
  722. var pageTmpl = template.Must(template.New("Page").Funcs(template.FuncMap{
  723. "elapsed": elapsed,
  724. "add": func(a, b int) int { return a + b },
  725. }).Parse(pageHTML))
  726. const pageHTML = `
  727. {{template "Prolog" .}}
  728. {{template "StatusTable" .}}
  729. {{template "Epilog" .}}
  730. {{define "Prolog"}}
  731. <html>
  732. <head>
  733. <title>/debug/requests</title>
  734. <style type="text/css">
  735. body {
  736. font-family: sans-serif;
  737. }
  738. table#tr-status td.family {
  739. padding-right: 2em;
  740. }
  741. table#tr-status td.active {
  742. padding-right: 1em;
  743. }
  744. table#tr-status td.latency-first {
  745. padding-left: 1em;
  746. }
  747. table#tr-status td.empty {
  748. color: #aaa;
  749. }
  750. table#reqs {
  751. margin-top: 1em;
  752. }
  753. table#reqs tr.first {
  754. {{if $.Expanded}}font-weight: bold;{{end}}
  755. }
  756. table#reqs td {
  757. font-family: monospace;
  758. }
  759. table#reqs td.when {
  760. text-align: right;
  761. white-space: nowrap;
  762. }
  763. table#reqs td.elapsed {
  764. padding: 0 0.5em;
  765. text-align: right;
  766. white-space: pre;
  767. width: 10em;
  768. }
  769. address {
  770. font-size: smaller;
  771. margin-top: 5em;
  772. }
  773. </style>
  774. </head>
  775. <body>
  776. <h1>/debug/requests</h1>
  777. {{end}} {{/* end of Prolog */}}
  778. {{define "StatusTable"}}
  779. <table id="tr-status">
  780. {{range $fam := .Families}}
  781. <tr>
  782. <td class="family">{{$fam}}</td>
  783. {{$n := index $.ActiveTraceCount $fam}}
  784. <td class="active {{if not $n}}empty{{end}}">
  785. {{if $n}}<a href="/debug/requests?fam={{$fam}}&b=-1{{if $.Expanded}}&exp=1{{end}}">{{end}}
  786. [{{$n}} active]
  787. {{if $n}}</a>{{end}}
  788. </td>
  789. {{$f := index $.CompletedTraces $fam}}
  790. {{range $i, $b := $f.Buckets}}
  791. {{$empty := $b.Empty}}
  792. <td {{if $empty}}class="empty"{{end}}>
  793. {{if not $empty}}<a href="/debug/requests?fam={{$fam}}&b={{$i}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
  794. [{{.Cond}}]
  795. {{if not $empty}}</a>{{end}}
  796. </td>
  797. {{end}}
  798. {{$nb := len $f.Buckets}}
  799. <td class="latency-first">
  800. <a href="/debug/requests?fam={{$fam}}&b={{$nb}}">[minute]</a>
  801. </td>
  802. <td>
  803. <a href="/debug/requests?fam={{$fam}}&b={{add $nb 1}}">[hour]</a>
  804. </td>
  805. <td>
  806. <a href="/debug/requests?fam={{$fam}}&b={{add $nb 2}}">[total]</a>
  807. </td>
  808. </tr>
  809. {{end}}
  810. </table>
  811. {{end}} {{/* end of StatusTable */}}
  812. {{define "Epilog"}}
  813. {{if $.Traces}}
  814. <hr />
  815. <h3>Family: {{$.Family}}</h3>
  816. {{if or $.Expanded $.Traced}}
  817. <a href="/debug/requests?fam={{$.Family}}&b={{$.Bucket}}">[Normal/Summary]</a>
  818. {{else}}
  819. [Normal/Summary]
  820. {{end}}
  821. {{if or (not $.Expanded) $.Traced}}
  822. <a href="/debug/requests?fam={{$.Family}}&b={{$.Bucket}}&exp=1">[Normal/Expanded]</a>
  823. {{else}}
  824. [Normal/Expanded]
  825. {{end}}
  826. {{if not $.Active}}
  827. {{if or $.Expanded (not $.Traced)}}
  828. <a href="/debug/requests?fam={{$.Family}}&b={{$.Bucket}}&rtraced=1">[Traced/Summary]</a>
  829. {{else}}
  830. [Traced/Summary]
  831. {{end}}
  832. {{if or (not $.Expanded) (not $.Traced)}}
  833. <a href="/debug/requests?fam={{$.Family}}&b={{$.Bucket}}&exp=1&rtraced=1">[Traced/Expanded]</a>
  834. {{else}}
  835. [Traced/Expanded]
  836. {{end}}
  837. {{end}}
  838. {{if $.Total}}
  839. <p><em>Showing <b>{{len $.Traces}}</b> of <b>{{$.Total}}</b> traces.</em></p>
  840. {{end}}
  841. <table id="reqs">
  842. <caption>
  843. {{if $.Active}}Active{{else}}Completed{{end}} Requests
  844. </caption>
  845. <tr><th>When</th><th>Elapsed&nbsp;(s)</th></tr>
  846. {{range $tr := $.Traces}}
  847. <tr class="first">
  848. <td class="when">{{$tr.When}}</td>
  849. <td class="elapsed">{{$tr.ElapsedTime}}</td>
  850. <td>{{$tr.Title}}</td>
  851. {{/* TODO: include traceID/spanID */}}
  852. </tr>
  853. {{if $.Expanded}}
  854. {{range $tr.Events}}
  855. <tr>
  856. <td class="when">{{.WhenString}}</td>
  857. <td class="elapsed">{{elapsed .Elapsed}}</td>
  858. <td>{{if or $.ShowSensitive (not .Sensitive)}}... {{.What}}{{else}}<em>[redacted]</em>{{end}}</td>
  859. </tr>
  860. {{end}}
  861. {{end}}
  862. {{end}}
  863. </table>
  864. {{end}} {{/* if $.Traces */}}
  865. {{if $.Histogram}}
  866. <h4>Latency (&micro;s) of {{$.Family}} over {{$.HistogramWindow}}</h4>
  867. {{$.Histogram}}
  868. {{end}} {{/* if $.Histogram */}}
  869. </body>
  870. </html>
  871. {{end}} {{/* end of Epilog */}}
  872. `