1// Copyright 2014 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
5package main
6
7import (
8	"cmd/internal/browser"
9	"cmd/internal/telemetry/counter"
10	"flag"
11	"fmt"
12	"internal/trace"
13	"internal/trace/raw"
14	"internal/trace/traceviewer"
15	"io"
16	"log"
17	"net"
18	"net/http"
19	_ "net/http/pprof" // Required to use pprof
20	"os"
21	"sync/atomic"
22	"time"
23)
24
25const usageMessage = "" +
26	`Usage of 'go tool trace':
27Given a trace file produced by 'go test':
28	go test -trace=trace.out pkg
29
30Open a web browser displaying trace:
31	go tool trace [flags] [pkg.test] trace.out
32
33Generate a pprof-like profile from the trace:
34    go tool trace -pprof=TYPE [pkg.test] trace.out
35
36[pkg.test] argument is required for traces produced by Go 1.6 and below.
37Go 1.7 does not require the binary argument.
38
39Supported profile types are:
40    - net: network blocking profile
41    - sync: synchronization blocking profile
42    - syscall: syscall blocking profile
43    - sched: scheduler latency profile
44
45Flags:
46	-http=addr: HTTP service address (e.g., ':6060')
47	-pprof=type: print a pprof-like profile instead
48	-d=int: print debug info such as parsed events (1 for high-level, 2 for low-level)
49
50Note that while the various profiles available when launching
51'go tool trace' work on every browser, the trace viewer itself
52(the 'view trace' page) comes from the Chrome/Chromium project
53and is only actively tested on that browser.
54`
55
56var (
57	httpFlag  = flag.String("http", "localhost:0", "HTTP service address (e.g., ':6060')")
58	pprofFlag = flag.String("pprof", "", "print a pprof-like profile instead")
59	debugFlag = flag.Int("d", 0, "print debug information (1 for basic debug info, 2 for lower-level info)")
60
61	// The binary file name, left here for serveSVGProfile.
62	programBinary string
63	traceFile     string
64)
65
66func main() {
67	counter.Open()
68	flag.Usage = func() {
69		fmt.Fprint(os.Stderr, usageMessage)
70		os.Exit(2)
71	}
72	flag.Parse()
73	counter.Inc("trace/invocations")
74	counter.CountFlags("trace/flag:", *flag.CommandLine)
75
76	// Go 1.7 traces embed symbol info and does not require the binary.
77	// But we optionally accept binary as first arg for Go 1.5 traces.
78	switch flag.NArg() {
79	case 1:
80		traceFile = flag.Arg(0)
81	case 2:
82		programBinary = flag.Arg(0)
83		traceFile = flag.Arg(1)
84	default:
85		flag.Usage()
86	}
87
88	tracef, err := os.Open(traceFile)
89	if err != nil {
90		logAndDie(fmt.Errorf("failed to read trace file: %w", err))
91	}
92	defer tracef.Close()
93
94	// Get the size of the trace file.
95	fi, err := tracef.Stat()
96	if err != nil {
97		logAndDie(fmt.Errorf("failed to stat trace file: %v", err))
98	}
99	traceSize := fi.Size()
100
101	// Handle requests for profiles.
102	if *pprofFlag != "" {
103		parsed, err := parseTrace(tracef, traceSize)
104		if err != nil {
105			logAndDie(err)
106		}
107		var f traceviewer.ProfileFunc
108		switch *pprofFlag {
109		case "net":
110			f = pprofByGoroutine(computePprofIO(), parsed)
111		case "sync":
112			f = pprofByGoroutine(computePprofBlock(), parsed)
113		case "syscall":
114			f = pprofByGoroutine(computePprofSyscall(), parsed)
115		case "sched":
116			f = pprofByGoroutine(computePprofSched(), parsed)
117		default:
118			logAndDie(fmt.Errorf("unknown pprof type %s\n", *pprofFlag))
119		}
120		records, err := f(&http.Request{})
121		if err != nil {
122			logAndDie(fmt.Errorf("failed to generate pprof: %v\n", err))
123		}
124		if err := traceviewer.BuildProfile(records).Write(os.Stdout); err != nil {
125			logAndDie(fmt.Errorf("failed to generate pprof: %v\n", err))
126		}
127		logAndDie(nil)
128	}
129
130	// Debug flags.
131	switch *debugFlag {
132	case 1:
133		logAndDie(debugProcessedEvents(tracef))
134	case 2:
135		logAndDie(debugRawEvents(tracef))
136	}
137
138	ln, err := net.Listen("tcp", *httpFlag)
139	if err != nil {
140		logAndDie(fmt.Errorf("failed to create server socket: %w", err))
141	}
142	addr := "http://" + ln.Addr().String()
143
144	log.Print("Preparing trace for viewer...")
145	parsed, err := parseTraceInteractive(tracef, traceSize)
146	if err != nil {
147		logAndDie(err)
148	}
149	// N.B. tracef not needed after this point.
150	// We might double-close, but that's fine; we ignore the error.
151	tracef.Close()
152
153	// Print a nice message for a partial trace.
154	if parsed.err != nil {
155		log.Printf("Encountered error, but able to proceed. Error: %v", parsed.err)
156
157		lost := parsed.size - parsed.valid
158		pct := float64(lost) / float64(parsed.size) * 100
159		log.Printf("Lost %.2f%% of the latest trace data due to error (%s of %s)", pct, byteCount(lost), byteCount(parsed.size))
160	}
161
162	log.Print("Splitting trace for viewer...")
163	ranges, err := splitTrace(parsed)
164	if err != nil {
165		logAndDie(err)
166	}
167
168	log.Printf("Opening browser. Trace viewer is listening on %s", addr)
169	browser.Open(addr)
170
171	mutatorUtil := func(flags trace.UtilFlags) ([][]trace.MutatorUtil, error) {
172		return trace.MutatorUtilizationV2(parsed.events, flags), nil
173	}
174
175	mux := http.NewServeMux()
176
177	// Main endpoint.
178	mux.Handle("/", traceviewer.MainHandler([]traceviewer.View{
179		{Type: traceviewer.ViewProc, Ranges: ranges},
180		// N.B. Use the same ranges for threads. It takes a long time to compute
181		// the split a second time, but the makeup of the events are similar enough
182		// that this is still a good split.
183		{Type: traceviewer.ViewThread, Ranges: ranges},
184	}))
185
186	// Catapult handlers.
187	mux.Handle("/trace", traceviewer.TraceHandler())
188	mux.Handle("/jsontrace", JSONTraceHandler(parsed))
189	mux.Handle("/static/", traceviewer.StaticHandler())
190
191	// Goroutines handlers.
192	mux.HandleFunc("/goroutines", GoroutinesHandlerFunc(parsed.summary.Goroutines))
193	mux.HandleFunc("/goroutine", GoroutineHandler(parsed.summary.Goroutines))
194
195	// MMU handler.
196	mux.HandleFunc("/mmu", traceviewer.MMUHandlerFunc(ranges, mutatorUtil))
197
198	// Basic pprof endpoints.
199	mux.HandleFunc("/io", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofIO(), parsed)))
200	mux.HandleFunc("/block", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofBlock(), parsed)))
201	mux.HandleFunc("/syscall", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofSyscall(), parsed)))
202	mux.HandleFunc("/sched", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofSched(), parsed)))
203
204	// Region-based pprof endpoints.
205	mux.HandleFunc("/regionio", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofIO(), parsed)))
206	mux.HandleFunc("/regionblock", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofBlock(), parsed)))
207	mux.HandleFunc("/regionsyscall", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofSyscall(), parsed)))
208	mux.HandleFunc("/regionsched", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofSched(), parsed)))
209
210	// Region endpoints.
211	mux.HandleFunc("/userregions", UserRegionsHandlerFunc(parsed))
212	mux.HandleFunc("/userregion", UserRegionHandlerFunc(parsed))
213
214	// Task endpoints.
215	mux.HandleFunc("/usertasks", UserTasksHandlerFunc(parsed))
216	mux.HandleFunc("/usertask", UserTaskHandlerFunc(parsed))
217
218	err = http.Serve(ln, mux)
219	logAndDie(fmt.Errorf("failed to start http server: %w", err))
220}
221
222func logAndDie(err error) {
223	if err == nil {
224		os.Exit(0)
225	}
226	fmt.Fprintf(os.Stderr, "%s\n", err)
227	os.Exit(1)
228}
229
230func parseTraceInteractive(tr io.Reader, size int64) (parsed *parsedTrace, err error) {
231	done := make(chan struct{})
232	cr := countingReader{r: tr}
233	go func() {
234		parsed, err = parseTrace(&cr, size)
235		done <- struct{}{}
236	}()
237	ticker := time.NewTicker(5 * time.Second)
238progressLoop:
239	for {
240		select {
241		case <-ticker.C:
242		case <-done:
243			ticker.Stop()
244			break progressLoop
245		}
246		progress := cr.bytesRead.Load()
247		pct := float64(progress) / float64(size) * 100
248		log.Printf("%s of %s (%.1f%%) processed...", byteCount(progress), byteCount(size), pct)
249	}
250	return
251}
252
253type parsedTrace struct {
254	events      []trace.Event
255	summary     *trace.Summary
256	size, valid int64
257	err         error
258}
259
260func parseTrace(rr io.Reader, size int64) (*parsedTrace, error) {
261	// Set up the reader.
262	cr := countingReader{r: rr}
263	r, err := trace.NewReader(&cr)
264	if err != nil {
265		return nil, fmt.Errorf("failed to create trace reader: %w", err)
266	}
267
268	// Set up state.
269	s := trace.NewSummarizer()
270	t := new(parsedTrace)
271	var validBytes int64
272	var validEvents int
273	for {
274		ev, err := r.ReadEvent()
275		if err == io.EOF {
276			validBytes = cr.bytesRead.Load()
277			validEvents = len(t.events)
278			break
279		}
280		if err != nil {
281			t.err = err
282			break
283		}
284		t.events = append(t.events, ev)
285		s.Event(&t.events[len(t.events)-1])
286
287		if ev.Kind() == trace.EventSync {
288			validBytes = cr.bytesRead.Load()
289			validEvents = len(t.events)
290		}
291	}
292
293	// Check to make sure we got at least one good generation.
294	if validEvents == 0 {
295		return nil, fmt.Errorf("failed to parse any useful part of the trace: %v", t.err)
296	}
297
298	// Finish off the parsedTrace.
299	t.summary = s.Finalize()
300	t.valid = validBytes
301	t.size = size
302	t.events = t.events[:validEvents]
303	return t, nil
304}
305
306func (t *parsedTrace) startTime() trace.Time {
307	return t.events[0].Time()
308}
309
310func (t *parsedTrace) endTime() trace.Time {
311	return t.events[len(t.events)-1].Time()
312}
313
314// splitTrace splits the trace into a number of ranges, each resulting in approx 100 MiB of
315// json output (the trace viewer can hardly handle more).
316func splitTrace(parsed *parsedTrace) ([]traceviewer.Range, error) {
317	// TODO(mknyszek): Split traces by generation by doing a quick first pass over the
318	// trace to identify all the generation boundaries.
319	s, c := traceviewer.SplittingTraceConsumer(100 << 20) // 100 MiB
320	if err := generateTrace(parsed, defaultGenOpts(), c); err != nil {
321		return nil, err
322	}
323	return s.Ranges, nil
324}
325
326func debugProcessedEvents(trc io.Reader) error {
327	tr, err := trace.NewReader(trc)
328	if err != nil {
329		return err
330	}
331	for {
332		ev, err := tr.ReadEvent()
333		if err == io.EOF {
334			return nil
335		} else if err != nil {
336			return err
337		}
338		fmt.Println(ev.String())
339	}
340}
341
342func debugRawEvents(trc io.Reader) error {
343	rr, err := raw.NewReader(trc)
344	if err != nil {
345		return err
346	}
347	for {
348		ev, err := rr.ReadEvent()
349		if err == io.EOF {
350			return nil
351		} else if err != nil {
352			return err
353		}
354		fmt.Println(ev.String())
355	}
356}
357
358type countingReader struct {
359	r         io.Reader
360	bytesRead atomic.Int64
361}
362
363func (c *countingReader) Read(buf []byte) (n int, err error) {
364	n, err = c.r.Read(buf)
365	c.bytesRead.Add(int64(n))
366	return n, err
367}
368
369type byteCount int64
370
371func (b byteCount) String() string {
372	var suffix string
373	var divisor int64
374	switch {
375	case b < 1<<10:
376		suffix = "B"
377		divisor = 1
378	case b < 1<<20:
379		suffix = "KiB"
380		divisor = 1 << 10
381	case b < 1<<30:
382		suffix = "MiB"
383		divisor = 1 << 20
384	case b < 1<<40:
385		suffix = "GiB"
386		divisor = 1 << 30
387	}
388	if divisor == 1 {
389		return fmt.Sprintf("%d %s", b, suffix)
390	}
391	return fmt.Sprintf("%.1f %s", float64(b)/float64(divisor), suffix)
392}
393