cmd/trace: pprof computation for span types

/spanio, /spanblock, /spansched, /spansyscall provide
the pprof-style summary of span execution's
io, block, scheduling, syscall latency distributions
respectively.

The computation logic for /io, /block, /sched, /syscall
analysis was refactored and extended for reuse in these
new types of analysis. Upon the analysis query, we create
a map of goroutine id to time intervals based on the query
parameter, that represents the interesting time intervals
of matching goroutines. Only the events from the matching
goroutines that fall into the intervals are considered
in the pprof computation.

The new endpoints are not yet hooked into other span
analysis page (e.g. /userspan) yet.

Change-Id: I80c3396e45a2d6631758710de67d132e5832c7ce
Reviewed-on: https://go-review.googlesource.com/105822
Reviewed-by: Heschi Kreinick <heschi@google.com>
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>

Author: hyangah

src/cmd/trace/main.go

@@ -83,19 +83,19 @@ func main() {
 		flag.Usage()
 	}
 
-	var pprofFunc func(io.Writer, string) error
+	var pprofFunc func(io.Writer, *http.Request) error
 	switch *pprofFlag {
 	case "net":
-		pprofFunc = pprofIO
+		pprofFunc = pprofByGoroutine(computePprofIO)
 	case "sync":
-		pprofFunc = pprofBlock
+		pprofFunc = pprofByGoroutine(computePprofBlock)
 	case "syscall":
-		pprofFunc = pprofSyscall
+		pprofFunc = pprofByGoroutine(computePprofSyscall)
 	case "sched":
-		pprofFunc = pprofSched
+		pprofFunc = pprofByGoroutine(computePprofSched)
 	}
 	if pprofFunc != nil {
-		if err := pprofFunc(os.Stdout, ""); err != nil {
+		if err := pprofFunc(os.Stdout, &http.Request{}); err != nil {
 			dief("failed to generate pprof: %v\n", err)
 		}
 		os.Exit(0)

src/cmd/trace/pprof.go

@@ -17,7 +17,9 @@ import (
 	"os/exec"
 	"path/filepath"
 	"runtime"
+	"sort"
 	"strconv"
+	"time"
 
 	"github.com/google/pprof/profile"
 )
@@ -35,10 +37,15 @@ func goCmd() string {
 }
 
 func init() {
-	http.HandleFunc("/io", serveSVGProfile(pprofIO))
-	http.HandleFunc("/block", serveSVGProfile(pprofBlock))
-	http.HandleFunc("/syscall", serveSVGProfile(pprofSyscall))
-	http.HandleFunc("/sched", serveSVGProfile(pprofSched))
+	http.HandleFunc("/io", serveSVGProfile(pprofByGoroutine(computePprofIO)))
+	http.HandleFunc("/block", serveSVGProfile(pprofByGoroutine(computePprofBlock)))
+	http.HandleFunc("/syscall", serveSVGProfile(pprofByGoroutine(computePprofSyscall)))
+	http.HandleFunc("/sched", serveSVGProfile(pprofByGoroutine(computePprofSched)))
+
+	http.HandleFunc("/spanio", serveSVGProfile(pprofBySpan(computePprofIO)))
+	http.HandleFunc("/spanblock", serveSVGProfile(pprofBySpan(computePprofBlock)))
+	http.HandleFunc("/spansyscall", serveSVGProfile(pprofBySpan(computePprofSyscall)))
+	http.HandleFunc("/spansched", serveSVGProfile(pprofBySpan(computePprofSched)))
 }
 
 // Record represents one entry in pprof-like profiles.
@@ -48,10 +55,46 @@ type Record struct {
 	time int64
 }
 
+// interval represents a time interval in the trace.
+type interval struct {
+	begin, end int64 // nanoseconds.
+}
+
+func pprofByGoroutine(compute func(io.Writer, map[uint64][]interval, []*trace.Event) error) func(w io.Writer, r *http.Request) error {
+	return func(w io.Writer, r *http.Request) error {
+		id := r.FormValue("id")
+		events, err := parseEvents()
+		if err != nil {
+			return err
+		}
+		gToIntervals, err := pprofMatchingGoroutines(id, events)
+		if err != nil {
+			return err
+		}
+		return compute(w, gToIntervals, events)
+	}
+}
+
+func pprofBySpan(compute func(io.Writer, map[uint64][]interval, []*trace.Event) error) func(w io.Writer, r *http.Request) error {
+	return func(w io.Writer, r *http.Request) error {
+		filter, err := newSpanFilter(r)
+		if err != nil {
+			return err
+		}
+		gToIntervals, err := pprofMatchingSpans(filter)
+		if err != nil {
+			return err
+		}
+		events, _ := parseEvents()
+
+		return compute(w, gToIntervals, events)
+	}
+}
+
 // pprofMatchingGoroutines parses the goroutine type id string (i.e. pc)
-// and returns the ids of goroutines of the matching type.
+// and returns the ids of goroutines of the matching type and its interval.
 // If the id string is empty, returns nil without an error.
-func pprofMatchingGoroutines(id string, events []*trace.Event) (map[uint64]bool, error) {
+func pprofMatchingGoroutines(id string, events []*trace.Event) (map[uint64][]interval, error) {
 	if id == "" {
 		return nil, nil
 	}
@@ -60,62 +103,95 @@ func pprofMatchingGoroutines(id string, events []*trace.Event) (map[uint64]bool,
 		return nil, fmt.Errorf("invalid goroutine type: %v", id)
 	}
 	analyzeGoroutines(events)
-	var res map[uint64]bool
+	var res map[uint64][]interval
 	for _, g := range gs {
 		if g.PC != pc {
 			continue
 		}
 		if res == nil {
-			res = make(map[uint64]bool)
+			res = make(map[uint64][]interval)
+		}
+		endTime := g.EndTime
+		if g.EndTime == 0 {
+			endTime = lastTimestamp() // the trace doesn't include the goroutine end event. Use the trace end time.
 		}
-		res[g.ID] = true
+		res[g.ID] = []interval{{begin: g.StartTime, end: endTime}}
 	}
 	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()
+// pprofMatchingSpans returns the time intervals of matching spans
+// grouped by the goroutine id. If the filter is nil, returns nil without an error.
+func pprofMatchingSpans(filter *spanFilter) (map[uint64][]interval, error) {
+	res, err := analyzeAnnotations()
 	if err != nil {
-		return err
+		return nil, err
 	}
-	goroutines, err := pprofMatchingGoroutines(id, events)
-	if err != nil {
-		return err
+	if filter == nil {
+		return nil, nil
+	}
+
+	gToIntervals := make(map[uint64][]interval)
+	for id, spans := range res.spans {
+		for _, s := range spans {
+			if filter.match(id, s) {
+				gToIntervals[s.G] = append(gToIntervals[s.G], interval{begin: s.firstTimestamp(), end: s.lastTimestamp()})
+			}
+		}
+	}
+
+	for g, intervals := range gToIntervals {
+		// in order to remove nested spans and
+		// consider only the outermost spans,
+		// first, we sort based on the start time
+		// and then scan through to select only the outermost spans.
+		sort.Slice(intervals, func(i, j int) bool {
+			x := intervals[i].begin
+			y := intervals[j].begin
+			if x == y {
+				return intervals[i].end < intervals[j].end
+			}
+			return x < y
+		})
+		var lastTimestamp int64
+		var n int
+		// select only the outermost spans.
+		for _, i := range intervals {
+			if lastTimestamp <= i.begin {
+				intervals[n] = i // new non-overlapping span starts.
+				lastTimestamp = i.end
+				n++
+			} // otherwise, skip because this span overlaps with a previous span.
+		}
+		gToIntervals[g] = intervals[:n]
 	}
+	return gToIntervals, nil
+}
 
+// computePprofIO generates IO pprof-like profile (time spent in IO wait, currently only network blocking event).
+func computePprofIO(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
 	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
+		overlapping := pprofOverlappingDuration(gToIntervals, ev)
+		if overlapping > 0 {
+			rec := prof[ev.StkID]
+			rec.stk = ev.Stk
+			rec.n++
+			rec.time += overlapping.Nanoseconds()
+			prof[ev.StkID] = rec
 		}
-		rec := prof[ev.StkID]
-		rec.stk = ev.Stk
-		rec.n++
-		rec.time += ev.Link.Ts - ev.Ts
-		prof[ev.StkID] = rec
 	}
 	return buildProfile(prof).Write(w)
 }
 
-// pprofBlock generates blocking pprof-like profile (time spent blocked on synchronization primitives).
-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
-	}
-
+// computePprofBlock generates blocking pprof-like profile (time spent blocked on synchronization primitives).
+func computePprofBlock(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
 	prof := make(map[uint64]Record)
 	for _, ev := range events {
 		switch ev.Type {
@@ -130,84 +206,86 @@ func pprofBlock(w io.Writer, id string) error {
 		if ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
 			continue
 		}
-		if goroutines != nil && !goroutines[ev.G] {
-			continue
+		overlapping := pprofOverlappingDuration(gToIntervals, ev)
+		if overlapping > 0 {
+			rec := prof[ev.StkID]
+			rec.stk = ev.Stk
+			rec.n++
+			rec.time += overlapping.Nanoseconds()
+			prof[ev.StkID] = rec
 		}
-		rec := prof[ev.StkID]
-		rec.stk = ev.Stk
-		rec.n++
-		rec.time += ev.Link.Ts - ev.Ts
-		prof[ev.StkID] = rec
 	}
 	return buildProfile(prof).Write(w)
 }
 
-// pprofSyscall generates syscall pprof-like profile (time spent blocked in syscalls).
-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
-	}
-
+// computePprofSyscall generates syscall pprof-like profile (time spent blocked in syscalls).
+func computePprofSyscall(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
 	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
+		overlapping := pprofOverlappingDuration(gToIntervals, ev)
+		if overlapping > 0 {
+			rec := prof[ev.StkID]
+			rec.stk = ev.Stk
+			rec.n++
+			rec.time += overlapping.Nanoseconds()
+			prof[ev.StkID] = rec
 		}
-		rec := prof[ev.StkID]
-		rec.stk = ev.Stk
-		rec.n++
-		rec.time += ev.Link.Ts - ev.Ts
-		prof[ev.StkID] = rec
 	}
 	return buildProfile(prof).Write(w)
 }
 
-// pprofSched generates scheduler latency pprof-like profile
+// computePprofSched generates scheduler latency pprof-like profile
 // (time between a goroutine become runnable and actually scheduled for execution).
-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
-	}
-
+func computePprofSched(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
 	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
+		overlapping := pprofOverlappingDuration(gToIntervals, ev)
+		if overlapping > 0 {
+			rec := prof[ev.StkID]
+			rec.stk = ev.Stk
+			rec.n++
+			rec.time += overlapping.Nanoseconds()
+			prof[ev.StkID] = rec
 		}
-		rec := prof[ev.StkID]
-		rec.stk = ev.Stk
-		rec.n++
-		rec.time += ev.Link.Ts - ev.Ts
-		prof[ev.StkID] = rec
 	}
 	return buildProfile(prof).Write(w)
 }
 
+// pprofOverlappingDuration returns the overlapping duration between
+// the time intervals in gToIntervals and the specified event.
+// If gToIntervals is nil, this simply returns the event's duration.
+func pprofOverlappingDuration(gToIntervals map[uint64][]interval, ev *trace.Event) time.Duration {
+	if gToIntervals == nil { // No filtering.
+		return time.Duration(ev.Link.Ts-ev.Ts) * time.Nanosecond
+	}
+	intervals := gToIntervals[ev.G]
+	if len(intervals) == 0 {
+		return 0
+	}
+
+	var overlapping time.Duration
+	for _, i := range intervals {
+		if o := overlappingDuration(i.begin, i.end, ev.Ts, ev.Link.Ts); o > 0 {
+			overlapping += o
+		}
+	}
+	return overlapping
+}
+
 // serveSVGProfile serves pprof-like profile generated by prof as svg.
-func serveSVGProfile(prof func(w io.Writer, id string) error) http.HandlerFunc {
+func serveSVGProfile(prof func(w io.Writer, r *http.Request) 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 {
+			if err := prof(w, r); 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)
@@ -226,7 +304,7 @@ func serveSVGProfile(prof func(w io.Writer, id string) error) http.HandlerFunc {
 			os.Remove(blockf.Name())
 		}()
 		blockb := bufio.NewWriter(blockf)
-		if err := prof(blockb, r.FormValue("id")); err != nil {
+		if err := prof(blockb, r); err != nil {
 			http.Error(w, fmt.Sprintf("failed to generate profile: %v", err), http.StatusInternalServerError)
 			return
 		}