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