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