cmd/trace/v2: add goroutine analysis pages

This is a complete fork and most of a rewrite of the goroutine analysis pages for v2 traces. It fixes an issue with the old page where GC time didn't really make any sense, generalizes the page and breaks things down further, and adds clarifying text. This change also modifies the SummarizeGoroutines API to not stream the trace. This is unfortunate, but we're already reading and holding the entire trace in memory for the trace viewer. We can revisit this decision in the future. Also, we want to do this now because the GoroutineSummary holds on to pointers to events, and these events will be used by the user region and user task analyses. While tracev2 events are values and they should be equivalent no matter how many times we parse a trace, this lets us reference the event in the slice directly. For #60773. For #63960. Fixes #62443. Change-Id: I1c5ab68141869378843f4f2826686038e4533090 Reviewed-on: https://go-review.googlesource.com/c/go/+/541257 Reviewed-by: Michael Pratt <mpratt@google.com> Auto-Submit: Michael Knyszek <mknyszek@google.com> LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
author: Michael Anthony Knyszek <mknyszek@google.com> 2023-11-12 21:48:31 +0000
committer: Michael Knyszek <mknyszek@google.com> 2023-11-21 21:27:34 +0000
commit: 48a6362dff840cfe75d5f1a674157af1f5d9ee85 (patch)
tree: 8043360f6f38f467982bd0c5322614a512406177 /src/cmd/trace
parent: 351d8520a6e55cbadc1714ad62405699ee172c5e (diff)
download: go-48a6362dff840cfe75d5f1a674157af1f5d9ee85.tar.xz
2 files changed, 443 insertions, 3 deletions
diff --git a/src/cmd/trace/v2/goroutines.go b/src/cmd/trace/v2/goroutines.go
new file mode 100644
index 0000000000..8fbfc9c22d
--- /dev/null
+++ b/src/cmd/trace/v2/goroutines.go
@@ -0,0 +1,435 @@
+// Copyright 2023 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// Goroutine-related profiles.
+
+package trace
+
+import (
+	"cmp"
+	"fmt"
+	"html/template"
+	"internal/trace"
+	"internal/trace/traceviewer"
+	tracev2 "internal/trace/v2"
+	"log"
+	"net/http"
+	"slices"
+	"sort"
+	"strconv"
+	"strings"
+	"time"
+)
+
+// GoroutinesHandlerFunc returns a HandlerFunc that serves list of goroutine groups.
+func GoroutinesHandlerFunc(summaries map[tracev2.GoID]*trace.GoroutineSummary) http.HandlerFunc {
+	return func(w http.ResponseWriter, r *http.Request) {
+		// goroutineGroup describes a group of goroutines grouped by start PC.
+		type goroutineGroup struct {
+			ID       uint64        // Unique identifier (PC).
+			Name     string        // Start function.
+			N        int           // Total number of goroutines in this group.
+			ExecTime time.Duration // Total execution time of all goroutines in this group.
+		}
+		// Accumulate groups by PC.
+		groupsByPC := make(map[uint64]goroutineGroup)
+		for _, summary := range summaries {
+			group := groupsByPC[summary.PC]
+			group.ID = summary.PC
+			group.Name = summary.Name
+			group.N++
+			group.ExecTime += summary.ExecTime
+			groupsByPC[summary.PC] = group
+		}
+		var groups []goroutineGroup
+		for pc, group := range groupsByPC {
+			group.ID = pc
+			// If goroutine didn't run during the trace (no sampled PC),
+			// the v.ID and v.Name will be zero value.
+			if group.ID == 0 && group.Name == "" {
+				group.Name = "(Inactive, no stack trace sampled)"
+			}
+			groups = append(groups, group)
+		}
+		slices.SortFunc(groups, func(a, b goroutineGroup) int {
+			return cmp.Compare(b.ExecTime, a.ExecTime)
+		})
+		w.Header().Set("Content-Type", "text/html;charset=utf-8")
+		if err := templGoroutines.Execute(w, groups); err != nil {
+			log.Printf("failed to execute template: %v", err)
+			return
+		}
+	}
+}
+
+var templGoroutines = template.Must(template.New("").Parse(`
+<html>
+<style>` + traceviewer.CommonStyle + `
+table {
+    border-collapse: collapse;
+}
+td,
+th {
+  border: 1px solid black;
+  padding-left: 8px;
+  padding-right: 8px;
+  padding-top: 4px;
+  padding-bottom: 4px;
+}
+</style>
+<body>
+<h1>Goroutines</h1>
+Below is a table of all goroutines in the trace grouped by start location and sorted by the total execution time of the group.<br>
+<br>
+Click a start location to view more details about that group.<br>
+<br>
+<table>
+  <tr>
+    <th>Start location</th>
+	<th>Count</th>
+	<th>Total execution time</th>
+  </tr>
+{{range $}}
+  <tr>
+    <td><code><a href="/goroutine?id={{.ID}}">{{.Name}}</a></code></td>
+	<td>{{.N}}</td>
+	<td>{{.ExecTime}}</td>
+  </tr>
+{{end}}
+</table>
+</body>
+</html>
+`))
+
+// GoroutineHandler creates a handler that serves information about
+// goroutines in a particular group.
+func GoroutineHandler(summaries map[tracev2.GoID]*trace.GoroutineSummary) http.HandlerFunc {
+	return func(w http.ResponseWriter, r *http.Request) {
+		pc, err := strconv.ParseUint(r.FormValue("id"), 10, 64)
+		if err != nil {
+			http.Error(w, fmt.Sprintf("failed to parse id parameter '%v': %v", r.FormValue("id"), err), http.StatusInternalServerError)
+			return
+		}
+
+		type goroutine struct {
+			*trace.GoroutineSummary
+			NonOverlappingStats map[string]time.Duration
+			HasRangeTime        bool
+		}
+
+		// Collect all the goroutines in the group.
+		var (
+			goroutines              []goroutine
+			name                    string
+			totalExecTime, execTime time.Duration
+			maxTotalTime            time.Duration
+		)
+		validNonOverlappingStats := make(map[string]struct{})
+		validRangeStats := make(map[string]struct{})
+		for _, summary := range summaries {
+			totalExecTime += summary.ExecTime
+
+			if summary.PC != pc {
+				continue
+			}
+			nonOverlappingStats := summary.NonOverlappingStats()
+			for name := range nonOverlappingStats {
+				validNonOverlappingStats[name] = struct{}{}
+			}
+			var totalRangeTime time.Duration
+			for name, dt := range summary.RangeTime {
+				validRangeStats[name] = struct{}{}
+				totalRangeTime += dt
+			}
+			goroutines = append(goroutines, goroutine{
+				GoroutineSummary:    summary,
+				NonOverlappingStats: nonOverlappingStats,
+				HasRangeTime:        totalRangeTime != 0,
+			})
+			name = summary.Name
+			execTime += summary.ExecTime
+			if maxTotalTime < summary.TotalTime {
+				maxTotalTime = summary.TotalTime
+			}
+		}
+
+		// Compute the percent of total execution time these goroutines represent.
+		execTimePercent := ""
+		if totalExecTime > 0 {
+			execTimePercent = fmt.Sprintf("%.2f%%", float64(execTime)/float64(totalExecTime)*100)
+		}
+
+		// Sort.
+		sortBy := r.FormValue("sortby")
+		if _, ok := validNonOverlappingStats[sortBy]; ok {
+			slices.SortFunc(goroutines, func(a, b goroutine) int {
+				return cmp.Compare(b.NonOverlappingStats[sortBy], a.NonOverlappingStats[sortBy])
+			})
+		} else {
+			// Sort by total time by default.
+			slices.SortFunc(goroutines, func(a, b goroutine) int {
+				return cmp.Compare(b.TotalTime, a.TotalTime)
+			})
+		}
+
+		// Write down all the non-overlapping stats and sort them.
+		allNonOverlappingStats := make([]string, 0, len(validNonOverlappingStats))
+		for name := range validNonOverlappingStats {
+			allNonOverlappingStats = append(allNonOverlappingStats, name)
+		}
+		slices.SortFunc(allNonOverlappingStats, func(a, b string) int {
+			if a == b {
+				return 0
+			}
+			if a == "Execution time" {
+				return -1
+			}
+			if b == "Execution time" {
+				return 1
+			}
+			return cmp.Compare(a, b)
+		})
+
+		// Write down all the range stats and sort them.
+		allRangeStats := make([]string, 0, len(validRangeStats))
+		for name := range validRangeStats {
+			allRangeStats = append(allRangeStats, name)
+		}
+		sort.Strings(allRangeStats)
+
+		err = templGoroutine.Execute(w, struct {
+			Name                string
+			PC                  uint64
+			N                   int
+			ExecTimePercent     string
+			MaxTotal            time.Duration
+			Goroutines          []goroutine
+			NonOverlappingStats []string
+			RangeStats          []string
+		}{
+			Name:                name,
+			PC:                  pc,
+			N:                   len(goroutines),
+			ExecTimePercent:     execTimePercent,
+			MaxTotal:            maxTotalTime,
+			Goroutines:          goroutines,
+			NonOverlappingStats: allNonOverlappingStats,
+			RangeStats:          allRangeStats,
+		})
+		if err != nil {
+			http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
+			return
+		}
+	}
+}
+
+func stat2Color(statName string) string {
+	color := "#636363"
+	if strings.HasPrefix(statName, "Block time") {
+		color = "#d01c8b"
+	}
+	switch statName {
+	case "Sched wait time":
+		color = "#2c7bb6"
+	case "Syscall execution time":
+		color = "#7b3294"
+	case "Execution time":
+		color = "#d7191c"
+	}
+	return color
+}
+
+var templGoroutine = template.Must(template.New("").Funcs(template.FuncMap{
+	"percent": func(dividend, divisor time.Duration) template.HTML {
+		if divisor == 0 {
+			return ""
+		}
+		return template.HTML(fmt.Sprintf("(%.1f%%)", float64(dividend)/float64(divisor)*100))
+	},
+	"headerStyle": func(statName string) template.HTMLAttr {
+		return template.HTMLAttr(fmt.Sprintf("style=\"background-color: %s;\"", stat2Color(statName)))
+	},
+	"barStyle": func(statName string, dividend, divisor time.Duration) template.HTMLAttr {
+		width := "0"
+		if divisor != 0 {
+			width = fmt.Sprintf("%.2f%%", float64(dividend)/float64(divisor)*100)
+		}
+		return template.HTMLAttr(fmt.Sprintf("style=\"width: %s; background-color: %s;\"", width, stat2Color(statName)))
+	},
+}).Parse(`
+<!DOCTYPE html>
+<title>Goroutine {{.Name}}</title>
+<style>` + traceviewer.CommonStyle + `
+th {
+  background-color: #050505;
+  color: #fff;
+}
+th.link {
+  cursor: pointer;
+}
+table {
+  border-collapse: collapse;
+}
+td,
+th {
+  padding-left: 8px;
+  padding-right: 8px;
+  padding-top: 4px;
+  padding-bottom: 4px;
+}
+.details tr:hover {
+  background-color: #f2f2f2;
+}
+.details td {
+  text-align: right;
+  border: 1px solid black;
+}
+.details td.id {
+  text-align: left;
+}
+.stacked-bar-graph {
+  width: 300px;
+  height: 10px;
+  color: #414042;
+  white-space: nowrap;
+  font-size: 5px;
+}
+.stacked-bar-graph span {
+  display: inline-block;
+  width: 100%;
+  height: 100%;
+  box-sizing: border-box;
+  float: left;
+  padding: 0;
+}
+</style>
+
+<script>
+function reloadTable(key, value) {
+  let params = new URLSearchParams(window.location.search);
+  params.set(key, value);
+  window.location.search = params.toString();
+}
+</script>
+
+<h1>Goroutine breakdown</h1>
+
+Table of contents
+<ul>
+	<li><a href="#summary">Summary</a></li>
+	<li><a href="#breakdown">Breakdown</a></li>
+	<li><a href="#ranges">Special ranges</a></li>
+</ul>
+
+<h3 id="summary">Summary</h3>
+
+<table class="summary">
+	<tr>
+		<td>Goroutine start location:</td>
+		<td><code>{{.Name}}</code></td>
+	</tr>
+	<tr>
+		<td>Count:</td>
+		<td>{{.N}}</td>
+	</tr>
+	<tr>
+		<td>Execution Time:</td>
+		<td>{{.ExecTimePercent}} of total program execution time </td>
+	</tr>
+	<tr>
+		<td>Network wait profile:</td>
+		<td> <a href="/io?id={{.PC}}">graph</a> <a href="/io?id={{.PC}}&raw=1" download="io.profile">(download)</a></td>
+	</tr>
+	<tr>
+		<td>Sync block profile:</td>
+		<td> <a href="/block?id={{.PC}}">graph</a> <a href="/block?id={{.PC}}&raw=1" download="block.profile">(download)</a></td>
+	</tr>
+	<tr>
+		<td>Syscall block profile:</td>
+		<td> <a href="/syscall?id={{.PC}}">graph</a> <a href="/syscall?id={{.PC}}&raw=1" download="syscall.profile">(download)</a></td>
+		</tr>
+	<tr>
+		<td>Scheduler wait profile:</td>
+		<td> <a href="/sched?id={{.PC}}">graph</a> <a href="/sched?id={{.PC}}&raw=1" download="sched.profile">(download)</a></td>
+	</tr>
+</table>
+
+<h3 id="breakdown">Breakdown</h3>
+
+The table below breaks down where each goroutine is spent its time during the
+traced period.
+All of the columns except total time are non-overlapping.
+<br>
+<br>
+
+<table class="details">
+<tr>
+<th> Goroutine</th>
+<th class="link" onclick="reloadTable('sortby', 'Total time')"> Total</th>
+<th></th>
+{{range $.NonOverlappingStats}}
+<th class="link" onclick="reloadTable('sortby', '{{.}}')" {{headerStyle .}}> {{.}}</th>
+{{end}}
+</tr>
+{{range .Goroutines}}
+	<tr>
+		<td> <a href="/trace?goid={{.ID}}">{{.ID}}</a> </td>
+		<td> {{ .TotalTime.String }} </td>
+		<td>
+			<div class="stacked-bar-graph">
+			{{$Goroutine := .}}
+			{{range $.NonOverlappingStats}}
+				{{$Time := index $Goroutine.NonOverlappingStats .}}
+				{{if $Time}}
+					<span {{barStyle . $Time $.MaxTotal}}>&nbsp;</span>
+				{{end}}
+			{{end}}
+			</div>
+		</td>
+		{{$Goroutine := .}}
+		{{range $.NonOverlappingStats}}
+			{{$Time := index $Goroutine.NonOverlappingStats .}}
+			<td> {{$Time.String}}</td>
+		{{end}}
+	</tr>
+{{end}}
+</table>
+
+<h3 id="ranges">Special ranges</h3>
+
+The table below describes how much of the traced period each goroutine spent in
+certain special time ranges.
+If a goroutine has spent no time in any special time ranges, it is excluded from
+the table.
+For example, how much time it spent helping the GC. Note that these times do
+overlap with the times from the first table.
+In general the goroutine may not be executing in these special time ranges.
+For example, it may have blocked while trying to help the GC.
+This must be taken into account when interpreting the data.
+<br>
+<br>
+
+<table class="details">
+<tr>
+<th> Goroutine</th>
+<th> Total</th>
+{{range $.RangeStats}}
+<th {{headerStyle .}}> {{.}}</th>
+{{end}}
+</tr>
+{{range .Goroutines}}
+	{{if .HasRangeTime}}
+		<tr>
+			<td> <a href="/trace?goid={{.ID}}">{{.ID}}</a> </td>
+			<td> {{ .TotalTime.String }} </td>
+			{{$Goroutine := .}}
+			{{range $.RangeStats}}
+				{{$Time := index $Goroutine.RangeTime .}}
+				<td> {{$Time.String}}</td>
+			{{end}}
+		</tr>
+	{{end}}
+{{end}}
+</table>
+`))
diff --git a/src/cmd/trace/v2/main.go b/src/cmd/trace/v2/main.go
index 93c9d89c20..b355d81ce6 100644
--- a/src/cmd/trace/v2/main.go
+++ b/src/cmd/trace/v2/main.go
@@ -6,6 +6,7 @@ package trace
 
 import (
 	"fmt"
+	"internal/trace"
 	"internal/trace/traceviewer"
 	tracev2 "internal/trace/v2"
 	"io"
@@ -39,9 +40,9 @@ func Main(traceFile, httpAddr, pprof string, debug int) error {
 	if err != nil {
 		return fmt.Errorf("failed to create server socket: %w", err)
 	}
-
 	addr := "http://" + ln.Addr().String()
-	log.Print("Parsing trace...")
+
+	log.Print("Preparing trace for viewer...")
 	parsed, err := parseTrace(tracef)
 	if err != nil {
 		return err
@@ -50,11 +51,13 @@ func Main(traceFile, httpAddr, pprof string, debug int) error {
 	// We might double-close, but that's fine; we ignore the error.
 	tracef.Close()
 
-	log.Print("Splitting trace...")
+	log.Print("Splitting trace for viewer...")
 	ranges, err := splitTrace(parsed)
 	if err != nil {
 		return err
 	}
+	log.Printf("Analyzing goroutines...")
+	gSummaries := trace.SummarizeGoroutines(parsed.events)
 
 	log.Printf("Opening browser. Trace viewer is listening on %s", addr)
 	browser.Open(addr)
@@ -64,6 +67,8 @@ func Main(traceFile, httpAddr, pprof string, debug int) error {
 	mux.Handle("/trace", traceviewer.TraceHandler())
 	mux.Handle("/jsontrace", JSONTraceHandler(parsed))
 	mux.Handle("/static/", traceviewer.StaticHandler())
+	mux.HandleFunc("/goroutines", GoroutinesHandlerFunc(gSummaries))
+	mux.HandleFunc("/goroutine", GoroutineHandler(gSummaries))
 
 	err = http.Serve(ln, mux)
 	return fmt.Errorf("failed to start http server: %w", err)
author	Michael Anthony Knyszek <mknyszek@google.com>	2023-11-12 21:48:31 +0000
committer	Michael Knyszek <mknyszek@google.com>	2023-11-21 21:27:34 +0000
commit	48a6362dff840cfe75d5f1a674157af1f5d9ee85 (patch)
tree	8043360f6f38f467982bd0c5322614a512406177 /src/cmd/trace
parent	351d8520a6e55cbadc1714ad62405699ee172c5e (diff)
download	go-48a6362dff840cfe75d5f1a674157af1f5d9ee85.tar.xz