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