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/75710
Reviewed-by: Sameer Ajmani <sameer@golang.org>

diff --git a/src/cmd/trace/goroutines.go b/src/cmd/trace/goroutines.go
index f5a4ddb05641186d6589faad9dd4840a012aab6b..d0d428cbe2f4d490f0f0176d5d29c1f76086ecf9 100644 (file)
--- a/src/cmd/trace/goroutines.go
+++ b/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>

diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go
index c8bd082d0dcd4cc7ae83883f34cb045563cb2858..32e16dfb47639a0bb96c6d05e6be7e2330cbb5d1 100644 (file)
--- a/src/cmd/trace/main.go
+++ b/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>
 `))

diff --git a/src/cmd/trace/pprof.go b/src/cmd/trace/pprof.go
index 47be2a6d1c55e5c85328c3ec9b0e40bef0ee9678..cac36e801047b33024a7bb9acd252885ea24d744 100644 (file)
--- a/src/cmd/trace/pprof.go
+++ b/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
                }