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/*
6Package trace implements tracing of requests and long-lived objects.
7It exports HTTP interfaces on /debug/requests and /debug/events.
8
9A trace.Trace provides tracing for short-lived objects, usually requests.
10A 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
24The /debug/requests HTTP endpoint organizes the traces by family,
25errors, and duration. It also provides histogram of request duration
26for each family.
27
28A trace.EventLog provides tracing for long-lived objects, such as RPC
29connections.
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
59The /debug/events HTTP endpoint organizes the event logs by family and
60by time since the last error. The expanded view displays recent log
61entries and the log's call stack.
62*/
63package trace // import "golang.org/x/net/trace"
64
65import (
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.
87var DebugUseAfterFinish = false
88
89// HTTP ServeMux paths.
90const (
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].
105var 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
120func 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.
136func 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.
141func 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.
151func 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.
166func 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.
180func 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
288func 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
304func 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
312type contextKeyT string
313
314var contextKey = contextKeyT("golang.org/x/net/trace.Trace")
315
316// Trace represents an active request.
317type 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
351type lazySprintf struct {
352 format string
353 a []interface{}
354}
355
356func (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.
361func 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
397func (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
433const (
434 bucketsPerFamily = 9
435 tracesPerBucket = 10
436 maxActiveTraces = 20 // Maximum number of active traces to show.
437 maxEventsPerTrace = 10
438 numHistogramBuckets = 38
439)
440
441var (
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
451type 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
462func (ts *traceSet) Len() int {
463 ts.mu.RLock()
464 defer ts.mu.RUnlock()
465 return len(ts.m)
466}
467
468func (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
477func (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.
484func (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
532func 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
542func 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
552func 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.
564type 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
573func 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.
592type 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
602func (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.
630func (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
649func (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.
656type cond interface {
657 match(t *trace) bool
658 String() string
659}
660
661type minCond time.Duration
662
663func (m minCond) match(t *trace) bool { return t.Elapsed >= time.Duration(m) }
664func (m minCond) String() string { return fmt.Sprintf("≥%gs", time.Duration(m).Seconds()) }
665
666type errorCond struct{}
667
668func (e errorCond) match(t *trace) bool { return t.IsError }
669func (e errorCond) String() string { return "errors" }
670
671type traceList []*trace
672
673// Free calls unref on each element of the list.
674func (trl traceList) Free() {
675 for _, t := range trl {
676 t.unref()
677 }
678}
679
680// traceList may be sorted in reverse chronological order.
681func (trl traceList) Len() int { return len(trl) }
682func (trl traceList) Less(i, j int) bool { return trl[i].Start.After(trl[j].Start) }
683func (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.
686type 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.
697func (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.
706type discarded int
707
708func (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.
714type 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
741func (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
768func (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
776func (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
829func (tr *trace) LazyLog(x fmt.Stringer, sensitive bool) {
830 tr.addEvent(x, true, sensitive)
831}
832
833func (tr *trace) LazyPrintf(format string, a ...interface{}) {
834 tr.addEvent(&lazySprintf{format, a}, false, false)
835}
836
837func (tr *trace) SetError() {
838 tr.mu.Lock()
839 tr.IsError = true
840 tr.mu.Unlock()
841}
842
843func (tr *trace) SetRecycler(f func(interface{})) {
844 tr.mu.Lock()
845 tr.recycler = f
846 tr.mu.Unlock()
847}
848
849func (tr *trace) SetTraceInfo(traceID, spanID uint64) {
850 tr.mu.Lock()
851 tr.traceID, tr.spanID = traceID, spanID
852 tr.mu.Unlock()
853}
854
855func (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
864func (tr *trace) ref() {
865 atomic.AddInt32(&tr.refs, 1)
866}
867
868func (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
887func (tr *trace) When() string {
888 return tr.Start.Format("2006/01/02 15:04:05.000000")
889}
890
891func (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
903func (tr *trace) Events() []event {
904 tr.mu.RLock()
905 defer tr.mu.RUnlock()
906 return tr.events
907}
908
909var traceFreeList = make(chan *trace, 1000) // TODO(dsymonds): Use sync.Pool?
910
911// newTrace returns a trace ready to use.
912func 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.
923func 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
934func 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
956var pageTmplCache *template.Template
957var pageTmplOnce sync.Once
958
959func 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
969const 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`