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