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