main.go

     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  
     5  package main
     6  
     7  import (
     8  	"cmd/internal/browser"
     9  	"cmd/internal/telemetry/counter"
    10  	"cmp"
    11  	"flag"
    12  	"fmt"
    13  	"internal/trace"
    14  	"internal/trace/raw"
    15  	"internal/trace/tracev2"
    16  	"internal/trace/traceviewer"
    17  	"io"
    18  	"log"
    19  	"net"
    20  	"net/http"
    21  	_ "net/http/pprof" // Required to use pprof
    22  	"net/netip"
    23  	"os"
    24  	"slices"
    25  	"sync/atomic"
    26  	"text/tabwriter"
    27  	"time"
    28  )
    29  
    30  const usageMessage = "" +
    31  	`Usage of 'go tool trace':
    32  Given a trace file produced by 'go test':
    33  	go test -trace=trace.out pkg
    34  
    35  Open a web browser displaying trace:
    36  	go tool trace [flags] [pkg.test] trace.out
    37  
    38  Generate a pprof-like profile from the trace:
    39      go tool trace -pprof=TYPE [pkg.test] trace.out
    40  
    41  [pkg.test] argument is required for traces produced by Go 1.6 and below.
    42  Go 1.7 does not require the binary argument.
    43  
    44  Supported profile types are:
    45      - net: network blocking profile
    46      - sync: synchronization blocking profile
    47      - syscall: syscall blocking profile
    48      - sched: scheduler latency profile
    49  
    50  Flags:
    51  	-http=addr: HTTP server listen address (e.g., ':6060')
    52  	-pprof=type: print a pprof-like profile instead
    53  	-d=mode: print debug info and exit (modes: wire, parsed, footprint)
    54  
    55  When providing only a port to -http (e.g., ':6060'), the tool listens only on localhost.
    56  To listen on all addresses, explicitly add the unspecified address (e.g., '0.0.0.0:6060').
    57  
    58  Note that while the various profiles available when launching
    59  'go tool trace' work on every browser, the trace viewer itself
    60  (the 'view trace' page) comes from the Chrome/Chromium project
    61  and is only actively tested on that browser.
    62  `
    63  
    64  var (
    65  	httpFlag  = flag.String("http", "localhost:0", "HTTP server listen address (e.g., ':6060')")
    66  	pprofFlag = flag.String("pprof", "", "print a pprof-like profile instead")
    67  	debugFlag = flag.String("d", "", "print debug info and exit (modes: wire, parsed, footprint)")
    68  
    69  	// The binary file name, left here for serveSVGProfile.
    70  	programBinary string
    71  	traceFile     string
    72  )
    73  
    74  func main() {
    75  	counter.Open()
    76  	flag.Usage = func() {
    77  		fmt.Fprint(os.Stderr, usageMessage)
    78  		os.Exit(2)
    79  	}
    80  	flag.Parse()
    81  	counter.Inc("trace/invocations")
    82  	counter.CountFlags("trace/flag:", *flag.CommandLine)
    83  
    84  	// Go 1.7 traces embed symbol info and does not require the binary.
    85  	// But we optionally accept binary as first arg for Go 1.5 traces.
    86  	switch flag.NArg() {
    87  	case 1:
    88  		traceFile = flag.Arg(0)
    89  	case 2:
    90  		programBinary = flag.Arg(0)
    91  		traceFile = flag.Arg(1)
    92  	default:
    93  		flag.Usage()
    94  	}
    95  
    96  	tracef, err := os.Open(traceFile)
    97  	if err != nil {
    98  		logAndDie(fmt.Errorf("failed to read trace file: %w", err))
    99  	}
   100  	defer tracef.Close()
   101  
   102  	// Get the size of the trace file.
   103  	fi, err := tracef.Stat()
   104  	if err != nil {
   105  		logAndDie(fmt.Errorf("failed to stat trace file: %v", err))
   106  	}
   107  	traceSize := fi.Size()
   108  
   109  	// Handle requests for profiles.
   110  	if *pprofFlag != "" {
   111  		parsed, err := parseTrace(tracef, traceSize)
   112  		if err != nil {
   113  			logAndDie(err)
   114  		}
   115  		var f traceviewer.ProfileFunc
   116  		switch *pprofFlag {
   117  		case "net":
   118  			f = pprofByGoroutine(computePprofIO(), parsed)
   119  		case "sync":
   120  			f = pprofByGoroutine(computePprofBlock(), parsed)
   121  		case "syscall":
   122  			f = pprofByGoroutine(computePprofSyscall(), parsed)
   123  		case "sched":
   124  			f = pprofByGoroutine(computePprofSched(), parsed)
   125  		default:
   126  			logAndDie(fmt.Errorf("unknown pprof type %s\n", *pprofFlag))
   127  		}
   128  		records, err := f(&http.Request{})
   129  		if err != nil {
   130  			logAndDie(fmt.Errorf("failed to generate pprof: %v\n", err))
   131  		}
   132  		if err := traceviewer.BuildProfile(records).Write(os.Stdout); err != nil {
   133  			logAndDie(fmt.Errorf("failed to generate pprof: %v\n", err))
   134  		}
   135  		logAndDie(nil)
   136  	}
   137  
   138  	// Debug flags.
   139  	if *debugFlag != "" {
   140  		switch *debugFlag {
   141  		case "parsed":
   142  			logAndDie(debugProcessedEvents(tracef))
   143  		case "wire":
   144  			logAndDie(debugRawEvents(tracef))
   145  		case "footprint":
   146  			logAndDie(debugEventsFootprint(tracef))
   147  		default:
   148  			logAndDie(fmt.Errorf("invalid debug mode %s, want one of: parsed, wire, footprint", *debugFlag))
   149  		}
   150  	}
   151  
   152  	addr, err := listenAddr(*httpFlag)
   153  	if err != nil {
   154  		logAndDie(fmt.Errorf("malformed -http value %q: %v", *httpFlag, err))
   155  	}
   156  
   157  	ln, err := net.Listen("tcp", addr)
   158  	if err != nil {
   159  		logAndDie(fmt.Errorf("failed to create server socket: %w", err))
   160  	}
   161  
   162  	addr = ln.Addr().String()
   163  	url, simplified, err := addrURL(addr)
   164  	if err != nil {
   165  		logAndDie(fmt.Errorf("failed to compute server URL: %v", err))
   166  	}
   167  
   168  	log.Print("Preparing trace for viewer...")
   169  	parsed, err := parseTraceInteractive(tracef, traceSize)
   170  	if err != nil {
   171  		logAndDie(err)
   172  	}
   173  	// N.B. tracef not needed after this point.
   174  	// We might double-close, but that's fine; we ignore the error.
   175  	tracef.Close()
   176  
   177  	// Print a nice message for a partial trace.
   178  	if parsed.err != nil {
   179  		log.Printf("Encountered error, but able to proceed. Error: %v", parsed.err)
   180  
   181  		lost := parsed.size - parsed.valid
   182  		pct := float64(lost) / float64(parsed.size) * 100
   183  		log.Printf("Lost %.2f%% of the latest trace data due to error (%s of %s)", pct, byteCount(lost), byteCount(parsed.size))
   184  	}
   185  
   186  	log.Print("Splitting trace for viewer...")
   187  	ranges, err := splitTrace(parsed)
   188  	if err != nil {
   189  		logAndDie(err)
   190  	}
   191  
   192  	if simplified {
   193  		// Warn that the URL below is simplified. i.e., we are actually
   194  		// listening on more addresses than the URL implies.
   195  		log.Printf("Full server listen address: %s", addr)
   196  	}
   197  	// N.B. gopls depends on the format of this log message. See
   198  	// golang.org/x/tools/gopls/internal/debug.startFlightRecorder.
   199  	log.Printf("Opening browser. Trace viewer is listening on %s", url)
   200  	browser.Open(addr)
   201  
   202  	mutatorUtil := func(flags trace.UtilFlags) ([][]trace.MutatorUtil, error) {
   203  		return trace.MutatorUtilizationV2(parsed.events, flags), nil
   204  	}
   205  
   206  	mux := http.NewServeMux()
   207  
   208  	// Main endpoint.
   209  	mux.Handle("/", traceviewer.MainHandler([]traceviewer.View{
   210  		{Type: traceviewer.ViewProc, Ranges: ranges},
   211  		// N.B. Use the same ranges for threads. It takes a long time to compute
   212  		// the split a second time, but the makeup of the events are similar enough
   213  		// that this is still a good split.
   214  		{Type: traceviewer.ViewThread, Ranges: ranges},
   215  	}))
   216  
   217  	// Catapult handlers.
   218  	mux.Handle("/trace", traceviewer.TraceHandler())
   219  	mux.Handle("/jsontrace", JSONTraceHandler(parsed))
   220  	mux.Handle("/static/", traceviewer.StaticHandler())
   221  
   222  	// Goroutines handlers.
   223  	mux.HandleFunc("/goroutines", GoroutinesHandlerFunc(parsed.summary.Goroutines))
   224  	mux.HandleFunc("/goroutine", GoroutineHandler(parsed.summary.Goroutines))
   225  
   226  	// MMU handler.
   227  	mux.HandleFunc("/mmu", traceviewer.MMUHandlerFunc(ranges, mutatorUtil))
   228  
   229  	// Basic pprof endpoints.
   230  	mux.HandleFunc("/io", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofIO(), parsed)))
   231  	mux.HandleFunc("/block", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofBlock(), parsed)))
   232  	mux.HandleFunc("/syscall", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofSyscall(), parsed)))
   233  	mux.HandleFunc("/sched", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofSched(), parsed)))
   234  
   235  	// Region-based pprof endpoints.
   236  	mux.HandleFunc("/regionio", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofIO(), parsed)))
   237  	mux.HandleFunc("/regionblock", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofBlock(), parsed)))
   238  	mux.HandleFunc("/regionsyscall", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofSyscall(), parsed)))
   239  	mux.HandleFunc("/regionsched", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofSched(), parsed)))
   240  
   241  	// Region endpoints.
   242  	mux.HandleFunc("/userregions", UserRegionsHandlerFunc(parsed))
   243  	mux.HandleFunc("/userregion", UserRegionHandlerFunc(parsed))
   244  
   245  	// Task endpoints.
   246  	mux.HandleFunc("/usertasks", UserTasksHandlerFunc(parsed))
   247  	mux.HandleFunc("/usertask", UserTaskHandlerFunc(parsed))
   248  
   249  	err = http.Serve(ln, mux)
   250  	logAndDie(fmt.Errorf("failed to start http server: %w", err))
   251  }
   252  
   253  func logAndDie(err error) {
   254  	if err == nil {
   255  		os.Exit(0)
   256  	}
   257  	fmt.Fprintf(os.Stderr, "%s\n", err)
   258  	os.Exit(1)
   259  }
   260  
   261  // listenAddr returns the address to listen on given the addr address flag.
   262  //
   263  // If addr does not specify a host (e.g., ":8080"), then default to listening
   264  // only on localhost rather than all addresses. To listen on all addresses,
   265  // explicitly set the unspecified address (e.g., "0.0.0.0:8080").
   266  func listenAddr(addr string) (string, error) {
   267  	host, port, err := net.SplitHostPort(addr)
   268  	if err != nil {
   269  		return "", err
   270  	}
   271  	if host == "" {
   272  		host = "localhost"
   273  	}
   274  	return net.JoinHostPort(host, port), nil
   275  }
   276  
   277  // addrURL returns an HTTP URL that may be used to connect to addr.
   278  //
   279  // It also returns a bool indicating if the returned URL uses a rewritten address.
   280  func addrURL(addr string) (string, bool, error) {
   281  	host, port, err := net.SplitHostPort(addr)
   282  	if err != nil {
   283  		return "", false, err
   284  	}
   285  
   286  	if host == "" {
   287  		// No host implies unspecified address, so rewrite to
   288  		// localhost, as below.
   289  		//
   290  		// addr should come from a net.Listener and thus always include
   291  		// a host, but handle this just in case.
   292  		host = "localhost"
   293  		return "http://" + net.JoinHostPort(host, port), true, nil
   294  	}
   295  
   296  	ipaddr, err := netip.ParseAddr(host)
   297  	if err != nil {
   298  		// Not an IP address, no change required.
   299  		return "http://" + net.JoinHostPort(host, port), false, nil
   300  	}
   301  
   302  	if ipaddr.IsUnspecified() {
   303  		// An unspecified address means (e.g., 0.0.0.0) this addr is
   304  		// listening on all addresses. It doesn't make sense to connect
   305  		// to the unspecified address [1], so rewrite to localhost. A
   306  		// connection to localhost with route to the same place.
   307  		//
   308  		// [1] Linux happens to treat connect to the unspecified
   309  		// address as loopback, but other OSes, such as Windows, treat
   310  		// it as an error.
   311  		host = "localhost"
   312  		return "http://" + net.JoinHostPort(host, port), true, nil
   313  	}
   314  
   315  	return "http://" + net.JoinHostPort(host, port), false, nil
   316  }
   317  
   318  func parseTraceInteractive(tr io.Reader, size int64) (parsed *parsedTrace, err error) {
   319  	done := make(chan struct{})
   320  	cr := countingReader{r: tr}
   321  	go func() {
   322  		parsed, err = parseTrace(&cr, size)
   323  		done <- struct{}{}
   324  	}()
   325  	ticker := time.NewTicker(5 * time.Second)
   326  progressLoop:
   327  	for {
   328  		select {
   329  		case <-ticker.C:
   330  		case <-done:
   331  			ticker.Stop()
   332  			break progressLoop
   333  		}
   334  		progress := cr.bytesRead.Load()
   335  		pct := float64(progress) / float64(size) * 100
   336  		log.Printf("%s of %s (%.1f%%) processed...", byteCount(progress), byteCount(size), pct)
   337  	}
   338  	return
   339  }
   340  
   341  type parsedTrace struct {
   342  	events      []trace.Event
   343  	summary     *trace.Summary
   344  	size, valid int64
   345  	err         error
   346  }
   347  
   348  func parseTrace(rr io.Reader, size int64) (*parsedTrace, error) {
   349  	// Set up the reader.
   350  	cr := countingReader{r: rr}
   351  	r, err := trace.NewReader(&cr)
   352  	if err != nil {
   353  		return nil, fmt.Errorf("failed to create trace reader: %w", err)
   354  	}
   355  
   356  	// Set up state.
   357  	s := trace.NewSummarizer()
   358  	t := new(parsedTrace)
   359  	var validBytes int64
   360  	var validEvents int
   361  	for {
   362  		ev, err := r.ReadEvent()
   363  		if err == io.EOF {
   364  			validBytes = cr.bytesRead.Load()
   365  			validEvents = len(t.events)
   366  			break
   367  		}
   368  		if err != nil {
   369  			t.err = err
   370  			break
   371  		}
   372  		t.events = append(t.events, ev)
   373  		s.Event(&t.events[len(t.events)-1])
   374  
   375  		if ev.Kind() == trace.EventSync {
   376  			validBytes = cr.bytesRead.Load()
   377  			validEvents = len(t.events)
   378  		}
   379  	}
   380  
   381  	// Check to make sure we got at least one good generation.
   382  	if validEvents == 0 {
   383  		return nil, fmt.Errorf("failed to parse any useful part of the trace: %v", t.err)
   384  	}
   385  
   386  	// Finish off the parsedTrace.
   387  	t.summary = s.Finalize()
   388  	t.valid = validBytes
   389  	t.size = size
   390  	t.events = t.events[:validEvents]
   391  	return t, nil
   392  }
   393  
   394  func (t *parsedTrace) startTime() trace.Time {
   395  	return t.events[0].Time()
   396  }
   397  
   398  func (t *parsedTrace) endTime() trace.Time {
   399  	return t.events[len(t.events)-1].Time()
   400  }
   401  
   402  // splitTrace splits the trace into a number of ranges, each resulting in approx 100 MiB of
   403  // json output (the trace viewer can hardly handle more).
   404  func splitTrace(parsed *parsedTrace) ([]traceviewer.Range, error) {
   405  	// TODO(mknyszek): Split traces by generation by doing a quick first pass over the
   406  	// trace to identify all the generation boundaries.
   407  	s, c := traceviewer.SplittingTraceConsumer(100 << 20) // 100 MiB
   408  	if err := generateTrace(parsed, defaultGenOpts(), c); err != nil {
   409  		return nil, err
   410  	}
   411  	return s.Ranges, nil
   412  }
   413  
   414  func debugProcessedEvents(trc io.Reader) error {
   415  	tr, err := trace.NewReader(trc)
   416  	if err != nil {
   417  		return err
   418  	}
   419  	for {
   420  		ev, err := tr.ReadEvent()
   421  		if err == io.EOF {
   422  			return nil
   423  		} else if err != nil {
   424  			return err
   425  		}
   426  		fmt.Println(ev.String())
   427  	}
   428  }
   429  
   430  func debugRawEvents(trc io.Reader) error {
   431  	rr, err := raw.NewReader(trc)
   432  	if err != nil {
   433  		return err
   434  	}
   435  	for {
   436  		ev, err := rr.ReadEvent()
   437  		if err == io.EOF {
   438  			return nil
   439  		} else if err != nil {
   440  			return err
   441  		}
   442  		fmt.Println(ev.String())
   443  	}
   444  }
   445  
   446  func debugEventsFootprint(trc io.Reader) error {
   447  	cr := countingReader{r: trc}
   448  	tr, err := raw.NewReader(&cr)
   449  	if err != nil {
   450  		return err
   451  	}
   452  	type eventStats struct {
   453  		typ   tracev2.EventType
   454  		count int
   455  		bytes int
   456  	}
   457  	var stats [256]eventStats
   458  	for i := range stats {
   459  		stats[i].typ = tracev2.EventType(i)
   460  	}
   461  	eventsRead := 0
   462  	for {
   463  		e, err := tr.ReadEvent()
   464  		if err == io.EOF {
   465  			break
   466  		}
   467  		if err != nil {
   468  			return err
   469  		}
   470  		s := &stats[e.Ev]
   471  		s.count++
   472  		s.bytes += e.EncodedSize()
   473  		eventsRead++
   474  	}
   475  	slices.SortFunc(stats[:], func(a, b eventStats) int {
   476  		return cmp.Compare(b.bytes, a.bytes)
   477  	})
   478  	specs := tr.Version().Specs()
   479  	w := tabwriter.NewWriter(os.Stdout, 3, 8, 2, ' ', 0)
   480  	fmt.Fprintf(w, "Event\tBytes\t%%\tCount\t%%\n")
   481  	fmt.Fprintf(w, "-\t-\t-\t-\t-\n")
   482  	for i := range stats {
   483  		stat := &stats[i]
   484  		name := ""
   485  		if int(stat.typ) >= len(specs) {
   486  			name = fmt.Sprintf("<unknown (%d)>", stat.typ)
   487  		} else {
   488  			name = specs[stat.typ].Name
   489  		}
   490  		bytesPct := float64(stat.bytes) / float64(cr.bytesRead.Load()) * 100
   491  		countPct := float64(stat.count) / float64(eventsRead) * 100
   492  		fmt.Fprintf(w, "%s\t%d\t%.2f%%\t%d\t%.2f%%\n", name, stat.bytes, bytesPct, stat.count, countPct)
   493  	}
   494  	w.Flush()
   495  	return nil
   496  }
   497  
   498  type countingReader struct {
   499  	r         io.Reader
   500  	bytesRead atomic.Int64
   501  }
   502  
   503  func (c *countingReader) Read(buf []byte) (n int, err error) {
   504  	n, err = c.r.Read(buf)
   505  	c.bytesRead.Add(int64(n))
   506  	return n, err
   507  }
   508  
   509  type byteCount int64
   510  
   511  func (b byteCount) String() string {
   512  	var suffix string
   513  	var divisor int64
   514  	switch {
   515  	case b < 1<<10:
   516  		suffix = "B"
   517  		divisor = 1
   518  	case b < 1<<20:
   519  		suffix = "KiB"
   520  		divisor = 1 << 10
   521  	case b < 1<<30:
   522  		suffix = "MiB"
   523  		divisor = 1 << 20
   524  	case b < 1<<40:
   525  		suffix = "GiB"
   526  		divisor = 1 << 30
   527  	}
   528  	if divisor == 1 {
   529  		return fmt.Sprintf("%d %s", b, suffix)
   530  	}
   531  	return fmt.Sprintf("%.1f %s", float64(b)/float64(divisor), suffix)
   532  }
   533
View as plain text