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