podman

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&nbsp;(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 (&micro;s) of {{$.Family}} over {{$.HistogramWindow}}</h4>
1124
{{$.Histogram}}
1125
{{end}} {{/* if $.Histogram */}}
1126

1127
	</body>
1128
</html>
1129
{{end}} {{/* end of Epilog */}}
1130
`
1131