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 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 (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 (µs) of {{$.Family}} over {{$.HistogramWindow}}</h4> 1076{{$.Histogram}} 1077{{end}} {{/* if $.Histogram */}} 1078 1079 </body> 1080</html> 1081{{end}} {{/* end of Epilog */}} 1082` 1083