main.go

Documentation: cmd/trace

     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  	"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  
    25  const usageMessage = "" +
    26  	`Usage of 'go tool trace':
    27  Given a trace file produced by 'go test':
    28  	go test -trace=trace.out pkg
    29  
    30  Open a web browser displaying trace:
    31  	go tool trace [flags] [pkg.test] trace.out
    32  
    33  Generate 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.
    37  Go 1.7 does not require the binary argument.
    38  
    39  Supported profile types are:
    40      - net: network blocking profile
    41      - sync: synchronization blocking profile
    42      - syscall: syscall blocking profile
    43      - sched: scheduler latency profile
    44  
    45  Flags:
    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  
    50  Note 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
    53  and is only actively tested on that browser.
    54  `
    55  
    56  var (
    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  
    66  func 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  
   222  func 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  
   230  func 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)
   238  progressLoop:
   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  
   253  type parsedTrace struct {
   254  	events      []trace.Event
   255  	summary     *trace.Summary
   256  	size, valid int64
   257  	err         error
   258  }
   259  
   260  func 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  
   306  func (t *parsedTrace) startTime() trace.Time {
   307  	return t.events[0].Time()
   308  }
   309  
   310  func (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).
   316  func 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  
   326  func 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  
   342  func 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  
   358  type countingReader struct {
   359  	r         io.Reader
   360  	bytesRead atomic.Int64
   361  }
   362  
   363  func (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  
   369  type byteCount int64
   370  
   371  func (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
View as plain text