cmd/trace: compute pprof-style output per goroutine type

The trace command computes IO, Schedule, Block, and Syscall profiles
by following the unblocking links in the execution trace and summing
up the duration.  This change offers variations of those profiles
that include only selected goroutine types. The id parameter takes the
goroutine type - i.e. pc of the goroutine.

The output is available from the /goroutine view. So, users can see
where the goroutines of interest typically block.

Also, these profiles are available for download so users can use
pprof or other tools to interpret the output. This change adds links
for download of global profile in the main page.

Change-Id: I35699252056d164e60de282b0406caf96d629c85
Reviewed-on: https://go-review.googlesource.com/75710Reviewed-by: Sameer Ajmani <sameer@golang.org>

src/cmd/trace/goroutines.go

@@ -121,13 +121,16 @@ func httpGoroutine(w http.ResponseWriter, r *http.Request) {
 	analyzeGoroutines(events)
 	var glist gdescList
 	for _, g := range gs {
-		if g.PC != pc || g.ExecTime == 0 {
+		if g.PC != pc {
 			continue
 		}
 		glist = append(glist, g)
 	}
 	sort.Sort(glist)
-	err = templGoroutine.Execute(w, glist)
+	err = templGoroutine.Execute(w, struct {
+		PC    uint64
+		GList gdescList
+	}{pc, glist})
 	if err != nil {
 		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
 		return
@@ -142,14 +145,14 @@ var templGoroutine = template.Must(template.New("").Parse(`
 <th> Goroutine </th>
 <th> Total time, ns </th>
 <th> Execution time, ns </th>
-<th> Network wait time, ns </th>
-<th> Sync block time, ns </th>
-<th> Blocking syscall time, ns </th>
-<th> Scheduler wait time, ns </th>
+<th> <a href="/io?id={{.PC}}">Network wait time, ns</a><a href="/io?id={{.PC}}&raw=1" download="io.profile">⬇</a> </th>
+<th> <a href="/block?id={{.PC}}">Sync block time, ns</a><a href="/block?id={{.PC}}&raw=1" download="block.profile">⬇</a> </th>
+<th> <a href="/syscall?id={{.PC}}">Blocking syscall time, ns</a><a href="/syscall?id={{.PC}}&raw=1" download="syscall.profile">⬇</a> </th>
+<th> <a href="/sched?id={{.PC}}">Scheduler wait time, ns</a><a href="/sched?id={{.PC}}&raw=1" download="sched.profile">⬇</a> </th>
 <th> GC sweeping time, ns </th>
 <th> GC pause time, ns </th>
 </tr>
-{{range $}}
+{{range .GList}}
   <tr>
     <td> <a href="/trace?goid={{.ID}}">{{.ID}}</a> </td>
     <td> {{.TotalTime}} </td>

src/cmd/trace/main.go

@@ -79,7 +79,7 @@ func main() {
 		flag.Usage()
 	}
 
-	var pprofFunc func(io.Writer) error
+	var pprofFunc func(io.Writer, string) error
 	switch *pprofFlag {
 	case "net":
 		pprofFunc = pprofIO
@@ -91,7 +91,7 @@ func main() {
 		pprofFunc = pprofSched
 	}
 	if pprofFunc != nil {
-		if err := pprofFunc(os.Stdout); err != nil {
+		if err := pprofFunc(os.Stdout, ""); err != nil {
 			dief("failed to generate pprof: %v\n", err)
 		}
 		os.Exit(0)
@@ -187,10 +187,10 @@ var templMain = template.Must(template.New("").Parse(`
 	<a href="/trace">View trace</a><br>
 {{end}}
 <a href="/goroutines">Goroutine analysis</a><br>
-<a href="/io">Network blocking profile</a><br>
-<a href="/block">Synchronization blocking profile</a><br>
-<a href="/syscall">Syscall blocking profile</a><br>
-<a href="/sched">Scheduler latency profile</a><br>
+<a href="/io">Network blocking profile</a> (<a href="/io?raw=1" download="io.profile">⬇</a>)<br>
+<a href="/block">Synchronization blocking profile</a> (<a href="/block?raw=1" download="block.profile">⬇</a>)<br>
+<a href="/syscall">Syscall blocking profile</a> (<a href="/syscall?raw=1" download="syscall.profile">⬇</a>)<br>
+<a href="/sched">Scheduler latency profile</a> (<a href="/sche?raw=1" download="sched.profile">⬇</a>)<br>
 </body>
 </html>
 `))

src/cmd/trace/pprof.go

@@ -17,6 +17,7 @@ import (
 	"os/exec"
 	"path/filepath"
 	"runtime"
+	"strconv"
 
 	"github.com/google/pprof/profile"
 )
@@ -47,17 +48,54 @@ type Record struct {
 	time int64
 }
 
-// pprofIO generates IO pprof-like profile (time spent in IO wait).
-func pprofIO(w io.Writer) error {
+// pprofMatchingGoroutines parses the goroutine type id string (i.e. pc)
+// and returns the ids of goroutines of the matching type.
+// If the id string is empty, returns nil without an error.
+func pprofMatchingGoroutines(id string, events []*trace.Event) (map[uint64]bool, error) {
+	if id == "" {
+		return nil, nil
+	}
+	pc, err := strconv.ParseUint(id, 10, 64) // id is string
+	if err != nil {
+		return nil, fmt.Errorf("invalid goroutine type: %v", id)
+	}
+	analyzeGoroutines(events)
+	var res map[uint64]bool
+	for _, g := range gs {
+		if g.PC != pc {
+			continue
+		}
+		if res == nil {
+			res = make(map[uint64]bool)
+		}
+		res[g.ID] = true
+	}
+	if len(res) == 0 && id != "" {
+		return nil, fmt.Errorf("failed to find matching goroutines for id: %s", id)
+	}
+	return res, nil
+}
+
+// pprofIO generates IO pprof-like profile (time spent in IO wait,
+// currently only network blocking event).
+func pprofIO(w io.Writer, id string) error {
 	events, err := parseEvents()
 	if err != nil {
 		return err
 	}
+	goroutines, err := pprofMatchingGoroutines(id, events)
+	if err != nil {
+		return err
+	}
+
 	prof := make(map[uint64]Record)
 	for _, ev := range events {
 		if ev.Type != trace.EvGoBlockNet || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
 			continue
 		}
+		if goroutines != nil && !goroutines[ev.G] {
+			continue
+		}
 		rec := prof[ev.StkID]
 		rec.stk = ev.Stk
 		rec.n++
@@ -68,22 +106,33 @@ func pprofIO(w io.Writer) error {
 }
 
 // pprofBlock generates blocking pprof-like profile (time spent blocked on synchronization primitives).
-func pprofBlock(w io.Writer) error {
+func pprofBlock(w io.Writer, id string) error {
 	events, err := parseEvents()
 	if err != nil {
 		return err
 	}
+	goroutines, err := pprofMatchingGoroutines(id, events)
+	if err != nil {
+		return err
+	}
+
 	prof := make(map[uint64]Record)
 	for _, ev := range events {
 		switch ev.Type {
 		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect,
 			trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockGC:
+			// TODO(hyangah): figure out why EvGoBlockGC should be here.
+			// EvGoBlockGC indicates the goroutine blocks on GC assist, not
+			// on synchronization primitives.
 		default:
 			continue
 		}
 		if ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
 			continue
 		}
+		if goroutines != nil && !goroutines[ev.G] {
+			continue
+		}
 		rec := prof[ev.StkID]
 		rec.stk = ev.Stk
 		rec.n++
@@ -94,16 +143,25 @@ func pprofBlock(w io.Writer) error {
 }
 
 // pprofSyscall generates syscall pprof-like profile (time spent blocked in syscalls).
-func pprofSyscall(w io.Writer) error {
+func pprofSyscall(w io.Writer, id string) error {
+
 	events, err := parseEvents()
 	if err != nil {
 		return err
 	}
+	goroutines, err := pprofMatchingGoroutines(id, events)
+	if err != nil {
+		return err
+	}
+
 	prof := make(map[uint64]Record)
 	for _, ev := range events {
 		if ev.Type != trace.EvGoSysCall || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
 			continue
 		}
+		if goroutines != nil && !goroutines[ev.G] {
+			continue
+		}
 		rec := prof[ev.StkID]
 		rec.stk = ev.Stk
 		rec.n++
@@ -115,17 +173,25 @@ func pprofSyscall(w io.Writer) error {
 
 // pprofSched generates scheduler latency pprof-like profile
 // (time between a goroutine become runnable and actually scheduled for execution).
-func pprofSched(w io.Writer) error {
+func pprofSched(w io.Writer, id string) error {
 	events, err := parseEvents()
 	if err != nil {
 		return err
 	}
+	goroutines, err := pprofMatchingGoroutines(id, events)
+	if err != nil {
+		return err
+	}
+
 	prof := make(map[uint64]Record)
 	for _, ev := range events {
 		if (ev.Type != trace.EvGoUnblock && ev.Type != trace.EvGoCreate) ||
 			ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
 			continue
 		}
+		if goroutines != nil && !goroutines[ev.G] {
+			continue
+		}
 		rec := prof[ev.StkID]
 		rec.stk = ev.Stk
 		rec.n++
@@ -136,8 +202,20 @@ func pprofSched(w io.Writer) error {
 }
 
 // serveSVGProfile serves pprof-like profile generated by prof as svg.
-func serveSVGProfile(prof func(w io.Writer) error) http.HandlerFunc {
+func serveSVGProfile(prof func(w io.Writer, id string) error) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
+
+		if r.FormValue("raw") != "" {
+			w.Header().Set("Content-Type", "application/octet-stream")
+			if err := prof(w, r.FormValue("id")); err != nil {
+				w.Header().Set("Content-Type", "text/plain; charset=utf-8")
+				w.Header().Set("X-Go-Pprof", "1")
+				http.Error(w, fmt.Sprintf("failed to get profile: %v", err), http.StatusInternalServerError)
+				return
+			}
+			return
+		}
+
 		blockf, err := ioutil.TempFile("", "block")
 		if err != nil {
 			http.Error(w, fmt.Sprintf("failed to create temp file: %v", err), http.StatusInternalServerError)
@@ -148,7 +226,7 @@ func serveSVGProfile(prof func(w io.Writer) error) http.HandlerFunc {
 			os.Remove(blockf.Name())
 		}()
 		blockb := bufio.NewWriter(blockf)
-		if err := prof(blockb); err != nil {
+		if err := prof(blockb, r.FormValue("id")); err != nil {
 			http.Error(w, fmt.Sprintf("failed to generate profile: %v", err), http.StatusInternalServerError)
 			return
 		}