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