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