cmd/trace: add almost full support for v2 traces in the trace viewer

This change refactors the cmd/trace package and adds most of the support
for v2 traces.

The following features of note are missing in this CL and will be
implemented in follow-up CLs:
- The focustask filter for the trace viewer
- The taskid filter for the trace viewer
- The goid filter for the trace viewer
- Pprof profiles
- The MMU graph
- The goroutine analysis pages
- The task analysis pages
- The region analysis pages

This CL makes one notable change to the trace CLI: it makes the -d flag
accept an integer to set the debug mode. For old traces -d != 0 works
just like -d. For new traces -d=1 means the high-level events and -d=2
means the low-level events.

Thanks to Felix Geisendörfer ([email protected]) for
doing a lot of work on this CL; I picked this up from him and got a
massive headstart as a result.

For #60773.
For #63960.

Change-Id: I3626e22473227c5980134a85f1bb6a845f567b1b
Reviewed-on: https://go-review.googlesource.com/c/go/+/542218
Reviewed-by: Michael Pratt <[email protected]>
Auto-Submit: Michael Knyszek <[email protected]>
TryBot-Bypass: Michael Knyszek <[email protected]>

Author: mknyszek

src/cmd/go/internal/trace/trace.go

@@ -5,10 +5,10 @@
 package trace
 
 import (
-	"cmd/internal/traceviewer"
 	"context"
 	"encoding/json"
 	"errors"
+	"internal/trace/traceviewer/format"
 	"os"
 	"strings"
 	"sync/atomic"
@@ -47,7 +47,7 @@ func StartSpan(ctx context.Context, name string) (context.Context, *Span) {
 		return ctx, nil
 	}
 	childSpan := &Span{t: tc.t, name: name, tid: tc.tid, start: time.Now()}
-	tc.t.writeEvent(&traceviewer.Event{
+	tc.t.writeEvent(&format.Event{
 		Name:  childSpan.name,
 		Time:  float64(childSpan.start.UnixNano()) / float64(time.Microsecond),
 		TID:   childSpan.tid,
@@ -77,15 +77,15 @@ func Flow(ctx context.Context, from *Span, to *Span) {
 	}
 
 	id := tc.t.getNextFlowID()
-	tc.t.writeEvent(&traceviewer.Event{
+	tc.t.writeEvent(&format.Event{
 		Name:     from.name + " -> " + to.name,
 		Category: "flow",
 		ID:       id,
 		Time:     float64(from.end.UnixNano()) / float64(time.Microsecond),
 		Phase:    phaseFlowStart,
 		TID:      from.tid,
 	})
-	tc.t.writeEvent(&traceviewer.Event{
+	tc.t.writeEvent(&format.Event{
 		Name:      from.name + " -> " + to.name,
 		Category:  "flow", // TODO(matloob): Add Category to Flow?
 		ID:        id,
@@ -110,7 +110,7 @@ func (s *Span) Done() {
 		return
 	}
 	s.end = time.Now()
-	s.t.writeEvent(&traceviewer.Event{
+	s.t.writeEvent(&format.Event{
 		Name:  s.name,
 		Time:  float64(s.end.UnixNano()) / float64(time.Microsecond),
 		TID:   s.tid,
@@ -125,7 +125,7 @@ type tracer struct {
 	nextFlowID atomic.Uint64
 }
 
-func (t *tracer) writeEvent(ev *traceviewer.Event) error {
+func (t *tracer) writeEvent(ev *format.Event) error {
 	f := <-t.file
 	defer func() { t.file <- f }()
 	var err error

src/cmd/trace/main.go

@@ -7,10 +7,11 @@ package main
 import (
 	"bufio"
 	"cmd/internal/browser"
+	cmdv2 "cmd/trace/v2"
 	"flag"
 	"fmt"
-	"html/template"
 	"internal/trace"
+	"internal/trace/traceviewer"
 	"io"
 	"log"
 	"net"
@@ -46,7 +47,7 @@ Supported profile types are:
 Flags:
 	-http=addr: HTTP service address (e.g., ':6060')
 	-pprof=type: print a pprof-like profile instead
-	-d: print debug info such as parsed events
+	-d=int: print debug info such as parsed events (1 for high-level, 2 for low-level)
 
 Note that while the various profiles available when launching
 'go tool trace' work on every browser, the trace viewer itself
@@ -57,7 +58,7 @@ and is only actively tested on that browser.
 var (
 	httpFlag  = flag.String("http", "localhost:0", "HTTP service address (e.g., ':6060')")
 	pprofFlag = flag.String("pprof", "", "print a pprof-like profile instead")
-	debugFlag = flag.Bool("d", false, "print debug information such as parsed events list")
+	debugFlag = flag.Int("d", 0, "print debug information (1 for basic debug info, 2 for lower-level info)")
 
 	// The binary file name, left here for serveSVGProfile.
 	programBinary string
@@ -83,6 +84,13 @@ func main() {
 		flag.Usage()
 	}
 
+	if isTraceV2(traceFile) {
+		if err := cmdv2.Main(traceFile, *httpFlag, *pprofFlag, *debugFlag); err != nil {
+			dief("%s\n", err)
+		}
+		return
+	}
+
 	var pprofFunc func(io.Writer, *http.Request) error
 	switch *pprofFlag {
 	case "net":
@@ -115,7 +123,7 @@ func main() {
 		dief("%v\n", err)
 	}
 
-	if *debugFlag {
+	if *debugFlag != 0 {
 		trace.Print(res.Events)
 		os.Exit(0)
 	}
@@ -132,12 +140,27 @@ func main() {
 	browser.Open(addr)
 
 	// Start http server.
-	http.HandleFunc("/", httpMain)
+	http.Handle("/", traceviewer.MainHandler(ranges))
 	err = http.Serve(ln, nil)
 	dief("failed to start http server: %v\n", err)
 }
 
-var ranges []Range
+// isTraceV2 returns true if filename holds a v2 trace.
+func isTraceV2(filename string) bool {
+	file, err := os.Open(filename)
+	if err != nil {
+		return false
+	}
+	defer file.Close()
+
+	ver, _, err := trace.ReadVersion(file)
+	if err != nil {
+		return false
+	}
+	return ver >= 1022
+}
+
+var ranges []traceviewer.Range
 
 var loader struct {
 	once sync.Once
@@ -175,209 +198,6 @@ func parseTrace() (trace.ParseResult, error) {
 	return loader.res, loader.err
 }
 
-// httpMain serves the starting page.
-func httpMain(w http.ResponseWriter, r *http.Request) {
-	if err := templMain.Execute(w, ranges); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
-}
-
-var templMain = template.Must(template.New("").Parse(`
-<html>
-<style>
-/* See https://github.com/golang/pkgsite/blob/master/static/shared/typography/typography.css */
-body {
-  font-family:	-apple-system, BlinkMacSystemFont, 'Segoe UI', Helvetica, Arial, sans-serif, 'Apple Color Emoji', 'Segoe UI Emoji';
-  font-size:	1rem;
-  line-height:	normal;
-  max-width:	9in;
-  margin:	1em;
-}
-h1 { font-size: 1.5rem; }
-h2 { font-size: 1.375rem; }
-h1,h2 {
-  font-weight: 600;
-  line-height: 1.25em;
-  word-break: break-word;
-}
-p  { color: grey85; font-size:85%; }
-</style>
-<body>
-<h1>cmd/trace: the Go trace event viewer</h1>
-<p>
-  This web server provides various visualizations of an event log gathered during
-  the execution of a Go program that uses the <a href='https://pkg.go.dev/runtime/trace'>runtime/trace</a> package.
-</p>
-
-<h2>Event timelines for running goroutines</h2>
-{{if $}}
-<p>
-  Large traces are split into multiple sections of equal data size
-  (not duration) to avoid overwhelming the visualizer.
-</p>
-<ul>
-	{{range $e := $}}
-		<li><a href="{{$e.URL}}">View trace ({{$e.Name}})</a></li>
-	{{end}}
-</ul>
-{{else}}
-<ul>
-	<li><a href="/trace">View trace</a></li>
-</ul>
-{{end}}
-<p>
-  This view displays a timeline for each of the GOMAXPROCS logical
-  processors, showing which goroutine (if any) was running on that
-  logical processor at each moment.
-
-  Each goroutine has an identifying number (e.g. G123), main function,
-  and color.
-
-  A colored bar represents an uninterrupted span of execution.
-
-  Execution of a goroutine may migrate from one logical processor to another,
-  causing a single colored bar to be horizontally continuous but
-  vertically displaced.
-</p>
-<p>
-  Clicking on a span reveals information about it, such as its
-  duration, its causal predecessors and successors, and the stack trace
-  at the final moment when it yielded the logical processor, for example
-  because it made a system call or tried to acquire a mutex.
-
-  Directly underneath each bar, a smaller bar or more commonly a fine
-  vertical line indicates an event occurring during its execution.
-  Some of these are related to garbage collection; most indicate that
-  a goroutine yielded its logical processor but then immediately resumed execution
-  on the same logical processor. Clicking on the event displays the stack trace
-  at the moment it occurred.
-</p>
-<p>
-  The causal relationships between spans of goroutine execution
-  can be displayed by clicking the Flow Events button at the top.
-</p>
-<p>
-  At the top ("STATS"), there are three additional timelines that
-  display statistical information.
-
-  "Goroutines" is a time series of the count of existing goroutines;
-  clicking on it displays their breakdown by state at that moment:
-  running, runnable, or waiting.
-
-  "Heap" is a time series of the amount of heap memory allocated (in orange)
-  and (in green) the allocation limit at which the next GC cycle will begin.
-
-  "Threads" shows the number of kernel threads in existence: there is
-  always one kernel thread per logical processor, and additional threads
-  are created for calls to non-Go code such as a system call or a
-  function written in C.
-</p>
-<p>
-  Above the event trace for the first logical processor are
-  traces for various runtime-internal events.
-
-  The "GC" bar shows when the garbage collector is running, and in which stage.
-  Garbage collection may temporarily affect all the logical processors
-  and the other metrics.
-
-  The "Network", "Timers", and "Syscalls" traces indicate events in
-  the runtime that cause goroutines to wake up.
-</p>
-<p>
-  The visualization allows you to navigate events at scales ranging from several
-  seconds to a handful of nanoseconds.
-
-  Consult the documentation for the Chromium <a href='https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/'>Trace Event Profiling Tool<a/>
-  for help navigating the view.
-</p>
-
-<ul>
-<li><a href="/goroutines">Goroutine analysis</a></li>
-</ul>
-<p>
-  This view displays information about each set of goroutines that
-  shares the same main function.
-
-  Clicking on a main function shows links to the four types of
-  blocking profile (see below) applied to that subset of goroutines.
-
-  It also shows a table of specific goroutine instances, with various
-  execution statistics and a link to the event timeline for each one.
-
-  The timeline displays only the selected goroutine and any others it
-  interacts with via block/unblock events. (The timeline is
-  goroutine-oriented rather than logical processor-oriented.)
-</p>
-
-<h2>Profiles</h2>
-<p>
-  Each link below displays a global profile in zoomable graph form as
-  produced by <a href='https://go.dev/blog/pprof'>pprof</a>'s "web" command.
-
-  In addition there is a link to download the profile for offline
-  analysis with pprof.
-
-  All four profiles represent causes of delay that prevent a goroutine
-  from running on a logical processor: because it was waiting for the network,
-  for a synchronization operation on a mutex or channel, for a system call,
-  or for a logical processor to become available.
-</p>
-<ul>
-<li><a href="/io">Network blocking profile</a> (<a href="/io?raw=1" download="io.profile">⬇</a>)</li>
-<li><a href="/block">Synchronization blocking profile</a> (<a href="/block?raw=1" download="block.profile">⬇</a>)</li>
-<li><a href="/syscall">Syscall blocking profile</a> (<a href="/syscall?raw=1" download="syscall.profile">⬇</a>)</li>
-<li><a href="/sched">Scheduler latency profile</a> (<a href="/sche?raw=1" download="sched.profile">⬇</a>)</li>
-</ul>
-
-<h2>User-defined tasks and regions</h2>
-<p>
-  The trace API allows a target program to annotate a <a
-  href='https://pkg.go.dev/runtime/trace#Region'>region</a> of code
-  within a goroutine, such as a key function, so that its performance
-  can be analyzed.
-
-  <a href='https://pkg.go.dev/runtime/trace#Log'>Log events</a> may be
-  associated with a region to record progress and relevant values.
-
-  The API also allows annotation of higher-level
-  <a href='https://pkg.go.dev/runtime/trace#Task'>tasks</a>,
-  which may involve work across many goroutines.
-</p>
-<p>
-  The links below display, for each region and task, a histogram of its execution times.
-
-  Each histogram bucket contains a sample trace that records the
-  sequence of events such as goroutine creations, log events, and
-  subregion start/end times.
-
-  For each task, you can click through to a logical-processor or
-  goroutine-oriented view showing the tasks and regions on the
-  timeline.
-
-  Such information may help uncover which steps in a region are
-  unexpectedly slow, or reveal relationships between the data values
-  logged in a request and its running time.
-</p>
-<ul>
-<li><a href="/usertasks">User-defined tasks</a></li>
-<li><a href="/userregions">User-defined regions</a></li>
-</ul>
-
-<h2>Garbage collection metrics</h2>
-<ul>
-<li><a href="/mmu">Minimum mutator utilization</a></li>
-</ul>
-<p>
-  This chart indicates the maximum GC pause time (the largest x value
-  for which y is zero), and more generally, the fraction of time that
-  the processors are available to application goroutines ("mutators"),
-  for any time window of a specified size, in the worst case.
-</p>
-</body>
-</html>
-`))
-
 func dief(msg string, args ...any) {
 	fmt.Fprintf(os.Stderr, msg, args...)
 	os.Exit(1)

src/cmd/trace/mmu.go

@@ -29,6 +29,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"internal/trace"
+	"internal/trace/traceviewer"
 	"log"
 	"math"
 	"net/http"
@@ -393,7 +394,7 @@ type linkedUtilWindow struct {
 
 func newLinkedUtilWindow(ui trace.UtilWindow, window time.Duration) linkedUtilWindow {
 	// Find the range containing this window.
-	var r Range
+	var r traceviewer.Range
 	for _, r = range ranges {
 		if r.EndTime > ui.Time {
 			break