cubefs

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
package trace
6

7
import (
8
	"bytes"
9
	"fmt"
10
	"html/template"
11
	"io"
12
	"log"
13
	"net/http"
14
	"runtime"
15
	"sort"
16
	"strconv"
17
	"strings"
18
	"sync"
19
	"sync/atomic"
20
	"text/tabwriter"
21
	"time"
22
)
23

24
const maxEventsPerLog = 100
25

26
type bucket struct {
27
	MaxErrAge time.Duration
28
	String    string
29
}
30

31
var buckets = []bucket{
32
	{0, "total"},
33
	{10 * time.Second, "errs<10s"},
34
	{1 * time.Minute, "errs<1m"},
35
	{10 * time.Minute, "errs<10m"},
36
	{1 * time.Hour, "errs<1h"},
37
	{10 * time.Hour, "errs<10h"},
38
	{24000 * time.Hour, "errors"},
39
}
40

41
// RenderEvents renders the HTML page typically served at /debug/events.
42
// It does not do any auth checking. The request may be nil.
43
//
44
// Most users will use the Events handler.
45
func RenderEvents(w http.ResponseWriter, req *http.Request, sensitive bool) {
46
	now := time.Now()
47
	data := &struct {
48
		Families []string // family names
49
		Buckets  []bucket
50
		Counts   [][]int // eventLog count per family/bucket
51

52
		// Set when a bucket has been selected.
53
		Family    string
54
		Bucket    int
55
		EventLogs eventLogs
56
		Expanded  bool
57
	}{
58
		Buckets: buckets,
59
	}
60

61
	data.Families = make([]string, 0, len(families))
62
	famMu.RLock()
63
	for name := range families {
64
		data.Families = append(data.Families, name)
65
	}
66
	famMu.RUnlock()
67
	sort.Strings(data.Families)
68

69
	// Count the number of eventLogs in each family for each error age.
70
	data.Counts = make([][]int, len(data.Families))
71
	for i, name := range data.Families {
72
		// TODO(sameer): move this loop under the family lock.
73
		f := getEventFamily(name)
74
		data.Counts[i] = make([]int, len(data.Buckets))
75
		for j, b := range data.Buckets {
76
			data.Counts[i][j] = f.Count(now, b.MaxErrAge)
77
		}
78
	}
79

80
	if req != nil {
81
		var ok bool
82
		data.Family, data.Bucket, ok = parseEventsArgs(req)
83
		if !ok {
84
			// No-op
85
		} else {
86
			data.EventLogs = getEventFamily(data.Family).Copy(now, buckets[data.Bucket].MaxErrAge)
87
		}
88
		if data.EventLogs != nil {
89
			defer data.EventLogs.Free()
90
			sort.Sort(data.EventLogs)
91
		}
92
		if exp, err := strconv.ParseBool(req.FormValue("exp")); err == nil {
93
			data.Expanded = exp
94
		}
95
	}
96

97
	famMu.RLock()
98
	defer famMu.RUnlock()
99
	if err := eventsTmpl().Execute(w, data); err != nil {
100
		log.Printf("net/trace: Failed executing template: %v", err)
101
	}
102
}
103

104
func parseEventsArgs(req *http.Request) (fam string, b int, ok bool) {
105
	fam, bStr := req.FormValue("fam"), req.FormValue("b")
106
	if fam == "" || bStr == "" {
107
		return "", 0, false
108
	}
109
	b, err := strconv.Atoi(bStr)
110
	if err != nil || b < 0 || b >= len(buckets) {
111
		return "", 0, false
112
	}
113
	return fam, b, true
114
}
115

116
// An EventLog provides a log of events associated with a specific object.
117
type EventLog interface {
118
	// Printf formats its arguments with fmt.Sprintf and adds the
119
	// result to the event log.
120
	Printf(format string, a ...interface{})
121

122
	// Errorf is like Printf, but it marks this event as an error.
123
	Errorf(format string, a ...interface{})
124

125
	// Finish declares that this event log is complete.
126
	// The event log should not be used after calling this method.
127
	Finish()
128
}
129

130
// NewEventLog returns a new EventLog with the specified family name
131
// and title.
132
func NewEventLog(family, title string) EventLog {
133
	el := newEventLog()
134
	el.ref()
135
	el.Family, el.Title = family, title
136
	el.Start = time.Now()
137
	el.events = make([]logEntry, 0, maxEventsPerLog)
138
	el.stack = make([]uintptr, 32)
139
	n := runtime.Callers(2, el.stack)
140
	el.stack = el.stack[:n]
141

142
	getEventFamily(family).add(el)
143
	return el
144
}
145

146
func (el *eventLog) Finish() {
147
	getEventFamily(el.Family).remove(el)
148
	el.unref() // matches ref in New
149
}
150

151
var (
152
	famMu    sync.RWMutex
153
	families = make(map[string]*eventFamily) // family name => family
154
)
155

156
func getEventFamily(fam string) *eventFamily {
157
	famMu.Lock()
158
	defer famMu.Unlock()
159
	f := families[fam]
160
	if f == nil {
161
		f = &eventFamily{}
162
		families[fam] = f
163
	}
164
	return f
165
}
166

167
type eventFamily struct {
168
	mu        sync.RWMutex
169
	eventLogs eventLogs
170
}
171

172
func (f *eventFamily) add(el *eventLog) {
173
	f.mu.Lock()
174
	f.eventLogs = append(f.eventLogs, el)
175
	f.mu.Unlock()
176
}
177

178
func (f *eventFamily) remove(el *eventLog) {
179
	f.mu.Lock()
180
	defer f.mu.Unlock()
181
	for i, el0 := range f.eventLogs {
182
		if el == el0 {
183
			copy(f.eventLogs[i:], f.eventLogs[i+1:])
184
			f.eventLogs = f.eventLogs[:len(f.eventLogs)-1]
185
			return
186
		}
187
	}
188
}
189

190
func (f *eventFamily) Count(now time.Time, maxErrAge time.Duration) (n int) {
191
	f.mu.RLock()
192
	defer f.mu.RUnlock()
193
	for _, el := range f.eventLogs {
194
		if el.hasRecentError(now, maxErrAge) {
195
			n++
196
		}
197
	}
198
	return
199
}
200

201
func (f *eventFamily) Copy(now time.Time, maxErrAge time.Duration) (els eventLogs) {
202
	f.mu.RLock()
203
	defer f.mu.RUnlock()
204
	els = make(eventLogs, 0, len(f.eventLogs))
205
	for _, el := range f.eventLogs {
206
		if el.hasRecentError(now, maxErrAge) {
207
			el.ref()
208
			els = append(els, el)
209
		}
210
	}
211
	return
212
}
213

214
type eventLogs []*eventLog
215

216
// Free calls unref on each element of the list.
217
func (els eventLogs) Free() {
218
	for _, el := range els {
219
		el.unref()
220
	}
221
}
222

223
// eventLogs may be sorted in reverse chronological order.
224
func (els eventLogs) Len() int           { return len(els) }
225
func (els eventLogs) Less(i, j int) bool { return els[i].Start.After(els[j].Start) }
226
func (els eventLogs) Swap(i, j int)      { els[i], els[j] = els[j], els[i] }
227

228
// A logEntry is a timestamped log entry in an event log.
229
type logEntry struct {
230
	When    time.Time
231
	Elapsed time.Duration // since previous event in log
232
	NewDay  bool          // whether this event is on a different day to the previous event
233
	What    string
234
	IsErr   bool
235
}
236

237
// WhenString returns a string representation of the elapsed time of the event.
238
// It will include the date if midnight was crossed.
239
func (e logEntry) WhenString() string {
240
	if e.NewDay {
241
		return e.When.Format("2006/01/02 15:04:05.000000")
242
	}
243
	return e.When.Format("15:04:05.000000")
244
}
245

246
// An eventLog represents an active event log.
247
type eventLog struct {
248
	// Family is the top-level grouping of event logs to which this belongs.
249
	Family string
250

251
	// Title is the title of this event log.
252
	Title string
253

254
	// Timing information.
255
	Start time.Time
256

257
	// Call stack where this event log was created.
258
	stack []uintptr
259

260
	// Append-only sequence of events.
261
	//
262
	// TODO(sameer): change this to a ring buffer to avoid the array copy
263
	// when we hit maxEventsPerLog.
264
	mu            sync.RWMutex
265
	events        []logEntry
266
	LastErrorTime time.Time
267
	discarded     int
268

269
	refs int32 // how many buckets this is in
270
}
271

272
func (el *eventLog) reset() {
273
	// Clear all but the mutex. Mutexes may not be copied, even when unlocked.
274
	el.Family = ""
275
	el.Title = ""
276
	el.Start = time.Time{}
277
	el.stack = nil
278
	el.events = nil
279
	el.LastErrorTime = time.Time{}
280
	el.discarded = 0
281
	el.refs = 0
282
}
283

284
func (el *eventLog) hasRecentError(now time.Time, maxErrAge time.Duration) bool {
285
	if maxErrAge == 0 {
286
		return true
287
	}
288
	el.mu.RLock()
289
	defer el.mu.RUnlock()
290
	return now.Sub(el.LastErrorTime) < maxErrAge
291
}
292

293
// delta returns the elapsed time since the last event or the log start,
294
// and whether it spans midnight.
295
// L >= el.mu
296
func (el *eventLog) delta(t time.Time) (time.Duration, bool) {
297
	if len(el.events) == 0 {
298
		return t.Sub(el.Start), false
299
	}
300
	prev := el.events[len(el.events)-1].When
301
	return t.Sub(prev), prev.Day() != t.Day()
302

303
}
304

305
func (el *eventLog) Printf(format string, a ...interface{}) {
306
	el.printf(false, format, a...)
307
}
308

309
func (el *eventLog) Errorf(format string, a ...interface{}) {
310
	el.printf(true, format, a...)
311
}
312

313
func (el *eventLog) printf(isErr bool, format string, a ...interface{}) {
314
	e := logEntry{When: time.Now(), IsErr: isErr, What: fmt.Sprintf(format, a...)}
315
	el.mu.Lock()
316
	e.Elapsed, e.NewDay = el.delta(e.When)
317
	if len(el.events) < maxEventsPerLog {
318
		el.events = append(el.events, e)
319
	} else {
320
		// Discard the oldest event.
321
		if el.discarded == 0 {
322
			// el.discarded starts at two to count for the event it
323
			// is replacing, plus the next one that we are about to
324
			// drop.
325
			el.discarded = 2
326
		} else {
327
			el.discarded++
328
		}
329
		// TODO(sameer): if this causes allocations on a critical path,
330
		// change eventLog.What to be a fmt.Stringer, as in trace.go.
331
		el.events[0].What = fmt.Sprintf("(%d events discarded)", el.discarded)
332
		// The timestamp of the discarded meta-event should be
333
		// the time of the last event it is representing.
334
		el.events[0].When = el.events[1].When
335
		copy(el.events[1:], el.events[2:])
336
		el.events[maxEventsPerLog-1] = e
337
	}
338
	if e.IsErr {
339
		el.LastErrorTime = e.When
340
	}
341
	el.mu.Unlock()
342
}
343

344
func (el *eventLog) ref() {
345
	atomic.AddInt32(&el.refs, 1)
346
}
347

348
func (el *eventLog) unref() {
349
	if atomic.AddInt32(&el.refs, -1) == 0 {
350
		freeEventLog(el)
351
	}
352
}
353

354
func (el *eventLog) When() string {
355
	return el.Start.Format("2006/01/02 15:04:05.000000")
356
}
357

358
func (el *eventLog) ElapsedTime() string {
359
	elapsed := time.Since(el.Start)
360
	return fmt.Sprintf("%.6f", elapsed.Seconds())
361
}
362

363
func (el *eventLog) Stack() string {
364
	buf := new(bytes.Buffer)
365
	tw := tabwriter.NewWriter(buf, 1, 8, 1, '\t', 0)
366
	printStackRecord(tw, el.stack)
367
	tw.Flush()
368
	return buf.String()
369
}
370

371
// printStackRecord prints the function + source line information
372
// for a single stack trace.
373
// Adapted from runtime/pprof/pprof.go.
374
func printStackRecord(w io.Writer, stk []uintptr) {
375
	for _, pc := range stk {
376
		f := runtime.FuncForPC(pc)
377
		if f == nil {
378
			continue
379
		}
380
		file, line := f.FileLine(pc)
381
		name := f.Name()
382
		// Hide runtime.goexit and any runtime functions at the beginning.
383
		if strings.HasPrefix(name, "runtime.") {
384
			continue
385
		}
386
		fmt.Fprintf(w, "#   %s\t%s:%d\n", name, file, line)
387
	}
388
}
389

390
func (el *eventLog) Events() []logEntry {
391
	el.mu.RLock()
392
	defer el.mu.RUnlock()
393
	return el.events
394
}
395

396
// freeEventLogs is a freelist of *eventLog
397
var freeEventLogs = make(chan *eventLog, 1000)
398

399
// newEventLog returns a event log ready to use.
400
func newEventLog() *eventLog {
401
	select {
402
	case el := <-freeEventLogs:
403
		return el
404
	default:
405
		return new(eventLog)
406
	}
407
}
408

409
// freeEventLog adds el to freeEventLogs if there's room.
410
// This is non-blocking.
411
func freeEventLog(el *eventLog) {
412
	el.reset()
413
	select {
414
	case freeEventLogs <- el:
415
	default:
416
	}
417
}
418

419
var eventsTmplCache *template.Template
420
var eventsTmplOnce sync.Once
421

422
func eventsTmpl() *template.Template {
423
	eventsTmplOnce.Do(func() {
424
		eventsTmplCache = template.Must(template.New("events").Funcs(template.FuncMap{
425
			"elapsed":   elapsed,
426
			"trimSpace": strings.TrimSpace,
427
		}).Parse(eventsHTML))
428
	})
429
	return eventsTmplCache
430
}
431

432
const eventsHTML = `
433
<html>
434
	<head>
435
		<title>events</title>
436
	</head>
437
	<style type="text/css">
438
		body {
439
			font-family: sans-serif;
440
		}
441
		table#req-status td.family {
442
			padding-right: 2em;
443
		}
444
		table#req-status td.active {
445
			padding-right: 1em;
446
		}
447
		table#req-status td.empty {
448
			color: #aaa;
449
		}
450
		table#reqs {
451
			margin-top: 1em;
452
		}
453
		table#reqs tr.first {
454
			{{if $.Expanded}}font-weight: bold;{{end}}
455
		}
456
		table#reqs td {
457
			font-family: monospace;
458
		}
459
		table#reqs td.when {
460
			text-align: right;
461
			white-space: nowrap;
462
		}
463
		table#reqs td.elapsed {
464
			padding: 0 0.5em;
465
			text-align: right;
466
			white-space: pre;
467
			width: 10em;
468
		}
469
		address {
470
			font-size: smaller;
471
			margin-top: 5em;
472
		}
473
	</style>
474
	<body>
475

476
<h1>/debug/events</h1>
477

478
<table id="req-status">
479
	{{range $i, $fam := .Families}}
480
	<tr>
481
		<td class="family">{{$fam}}</td>
482

483
	        {{range $j, $bucket := $.Buckets}}
484
	        {{$n := index $.Counts $i $j}}
485
		<td class="{{if not $bucket.MaxErrAge}}active{{end}}{{if not $n}}empty{{end}}">
486
	                {{if $n}}<a href="?fam={{$fam}}&b={{$j}}{{if $.Expanded}}&exp=1{{end}}">{{end}}
487
		        [{{$n}} {{$bucket.String}}]
488
			{{if $n}}</a>{{end}}
489
		</td>
490
                {{end}}
491

492
	</tr>{{end}}
493
</table>
494

495
{{if $.EventLogs}}
496
<hr />
497
<h3>Family: {{$.Family}}</h3>
498

499
{{if $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}">{{end}}
500
[Summary]{{if $.Expanded}}</a>{{end}}
501

502
{{if not $.Expanded}}<a href="?fam={{$.Family}}&b={{$.Bucket}}&exp=1">{{end}}
503
[Expanded]{{if not $.Expanded}}</a>{{end}}
504

505
<table id="reqs">
506
	<tr><th>When</th><th>Elapsed</th></tr>
507
	{{range $el := $.EventLogs}}
508
	<tr class="first">
509
		<td class="when">{{$el.When}}</td>
510
		<td class="elapsed">{{$el.ElapsedTime}}</td>
511
		<td>{{$el.Title}}
512
	</tr>
513
	{{if $.Expanded}}
514
	<tr>
515
		<td class="when"></td>
516
		<td class="elapsed"></td>
517
		<td><pre>{{$el.Stack|trimSpace}}</pre></td>
518
	</tr>
519
	{{range $el.Events}}
520
	<tr>
521
		<td class="when">{{.WhenString}}</td>
522
		<td class="elapsed">{{elapsed .Elapsed}}</td>
523
		<td>.{{if .IsErr}}E{{else}}.{{end}}. {{.What}}</td>
524
	</tr>
525
	{{end}}
526
	{{end}}
527
	{{end}}
528
</table>
529
{{end}}
530
	</body>
531
</html>
532
`
533