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