From 5bd66e5e1e815f25b1a3973220ba803cfeeb98e4 Mon Sep 17 00:00:00 2001 From: "Hana (Hyang-Ah) Kim" Date: Thu, 2 Nov 2017 19:17:39 -0400 Subject: [PATCH] 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 --- src/cmd/trace/goroutines.go | 17 ++++--- src/cmd/trace/main.go | 12 ++--- src/cmd/trace/pprof.go | 92 ++++++++++++++++++++++++++++++++++--- 3 files changed, 101 insertions(+), 20 deletions(-) diff --git a/src/cmd/trace/goroutines.go b/src/cmd/trace/goroutines.go index f5a4ddb056..d0d428cbe2 100644 --- 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(` Goroutine Total time, ns Execution time, ns - Network wait time, ns - Sync block time, ns - Blocking syscall time, ns - Scheduler wait time, ns + Network wait time, ns⬇ + Sync block time, ns⬇ + Blocking syscall time, ns⬇ + Scheduler wait time, ns⬇ GC sweeping time, ns GC pause time, ns -{{range $}} +{{range .GList}} {{.ID}} {{.TotalTime}} diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go index c8bd082d0d..32e16dfb47 100644 --- 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(` View trace
{{end}} Goroutine analysis
-Network blocking profile
-Synchronization blocking profile
-Syscall blocking profile
-Scheduler latency profile
+Network blocking profile (⬇)
+Synchronization blocking profile (⬇)
+Syscall blocking profile (⬇)
+Scheduler latency profile (⬇)
`)) diff --git a/src/cmd/trace/pprof.go b/src/cmd/trace/pprof.go index 47be2a6d1c..cac36e8010 100644 --- 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 } -- 2.50.0