cmd/trace: use new traceparser to parse the raw trace files

Change-Id: I8b224ae48a2f8acd5a64c9ff283e97821479a9a8
Reviewed-on: https://go-review.googlesource.com/c/145457
Run-TryBot: Peter Weinberger <[email protected]>
TryBot-Result: Gobot Gobot <[email protected]>
Reviewed-by: Hyang-Ah Hana Kim <[email protected]>

Author: pjweinbgo

src/cmd/trace/annotations.go

@@ -8,7 +8,6 @@ import (
 	"bytes"
 	"fmt"
 	"html/template"
-	"internal/trace"
 	"log"
 	"math"
 	"net/http"
@@ -17,6 +16,8 @@ import (
 	"strconv"
 	"strings"
 	"time"
+
+	trace "internal/traceparser"
 )
 
 func init() {
@@ -308,7 +309,7 @@ func analyzeAnnotations() (annotationAnalysisResult, error) {
 		}
 	}
 	// combine region info.
-	analyzeGoroutines(events)
+	analyzeGoroutines(res)
 	for goid, stats := range gs {
 		// gs is a global var defined in goroutines.go as a result
 		// of analyzeGoroutines. TODO(hyangah): fix this not to depend
@@ -321,7 +322,7 @@ func analyzeAnnotations() (annotationAnalysisResult, error) {
 			}
 			var frame trace.Frame
 			if s.Start != nil {
-				frame = *s.Start.Stk[0]
+				frame = *res.Stacks[s.Start.StkID][0]
 			}
 			id := regionTypeID{Frame: frame, Type: s.Name}
 			regions[id] = append(regions[id], regionDesc{UserRegionDesc: s, G: goid})

src/cmd/trace/annotations_test.go

@@ -11,7 +11,7 @@ import (
 	"context"
 	"flag"
 	"fmt"
-	traceparser "internal/trace"
+	"internal/traceparser"
 	"io/ioutil"
 	"reflect"
 	"runtime/debug"
@@ -338,10 +338,8 @@ func traceProgram(t *testing.T, f func(), name string) error {
 	trace.Stop()
 
 	saveTrace(buf, name)
-	res, err := traceparser.Parse(buf, name+".faketrace")
-	if err == traceparser.ErrTimeOrder {
-		t.Skipf("skipping due to golang.org/issue/16755: %v", err)
-	} else if err != nil {
+	res, err := traceparser.ParseBuffer(buf)
+	if err != nil {
 		return err
 	}
 
@@ -370,15 +368,15 @@ func childrenNames(task *taskDesc) (ret []string) {
 	return ret
 }
 
-func swapLoaderData(res traceparser.ParseResult, err error) {
+func swapLoaderData(res *traceparser.Parsed, err error) {
 	// swap loader's data.
 	parseTrace() // fool loader.once.
 
 	loader.res = res
 	loader.err = err
 
-	analyzeGoroutines(nil) // fool gsInit once.
-	gs = traceparser.GoroutineStats(res.Events)
+	analyzeGoroutines(res) // fool gsInit once.
+	gs = res.GoroutineStats()
 
 }
 

src/cmd/trace/goroutines.go

@@ -9,14 +9,15 @@ package main
 import (
 	"fmt"
 	"html/template"
-	"internal/trace"
 	"log"
 	"net/http"
 	"reflect"
 	"sort"
 	"strconv"
 	"sync"
 	"time"
+
+	trace "internal/traceparser"
 )
 
 func init() {
@@ -38,15 +39,15 @@ var (
 )
 
 // analyzeGoroutines generates statistics about execution of all goroutines and stores them in gs.
-func analyzeGoroutines(events []*trace.Event) {
+func analyzeGoroutines(res *trace.Parsed) {
 	gsInit.Do(func() {
-		gs = trace.GoroutineStats(events)
+		gs = res.GoroutineStats()
 	})
 }
 
 // httpGoroutines serves list of goroutine groups.
 func httpGoroutines(w http.ResponseWriter, r *http.Request) {
-	events, err := parseEvents()
+	events, err := parseTrace()
 	if err != nil {
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return
@@ -89,7 +90,7 @@ Goroutines: <br>
 func httpGoroutine(w http.ResponseWriter, r *http.Request) {
 	// TODO(hyangah): support format=csv (raw data)
 
-	events, err := parseEvents()
+	events, err := parseTrace()
 	if err != nil {
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return

src/cmd/trace/main.go

@@ -5,12 +5,12 @@
 package main
 
 import (
-	"bufio"
+	"bytes"
 	"cmd/internal/browser"
 	"flag"
 	"fmt"
 	"html/template"
-	"internal/trace"
+	trace "internal/traceparser"
 	"io"
 	"log"
 	"net"
@@ -115,8 +115,22 @@ func main() {
 		dief("%v\n", err)
 	}
 
-	if *debugFlag {
-		trace.Print(res.Events)
+	if *debugFlag { // match go tool trace -d (except for Offset and Seq)
+		f := func(ev *trace.Event) {
+			desc := trace.EventDescriptions[ev.Type]
+			w := new(bytes.Buffer)
+			fmt.Fprintf(w, "%v %v p=%v g=%v", ev.Ts, desc.Name, ev.P, ev.G)
+			for i, a := range desc.Args {
+				fmt.Fprintf(w, " %v=%v", a, ev.Args[i])
+			}
+			for i, a := range desc.SArgs {
+				fmt.Fprintf(w, " %v=%v", a, ev.SArgs[i])
+			}
+			fmt.Println(w.String())
+		}
+		for i := 0; i < len(res.Events); i++ {
+			f(res.Events[i])
+		}
 		os.Exit(0)
 	}
 	reportMemoryUsage("after parsing trace")
@@ -141,36 +155,23 @@ var ranges []Range
 
 var loader struct {
 	once sync.Once
-	res  trace.ParseResult
+	res  *trace.Parsed
 	err  error
 }
 
-// parseEvents is a compatibility wrapper that returns only
-// the Events part of trace.ParseResult returned by parseTrace.
-func parseEvents() ([]*trace.Event, error) {
-	res, err := parseTrace()
-	if err != nil {
-		return nil, err
-	}
-	return res.Events, err
-}
-
-func parseTrace() (trace.ParseResult, error) {
+func parseTrace() (*trace.Parsed, error) {
 	loader.once.Do(func() {
-		tracef, err := os.Open(traceFile)
+		x, err := trace.New(traceFile)
 		if err != nil {
-			loader.err = fmt.Errorf("failed to open trace file: %v", err)
+			loader.err = err
 			return
 		}
-		defer tracef.Close()
-
-		// Parse and symbolize.
-		res, err := trace.Parse(bufio.NewReader(tracef), programBinary)
+		err = x.Parse(0, x.MaxTs, nil)
 		if err != nil {
-			loader.err = fmt.Errorf("failed to parse trace: %v", err)
+			loader.err = err
 			return
 		}
-		loader.res = res
+		loader.res = x
 	})
 	return loader.res, loader.err
 }

src/cmd/trace/pprof.go

@@ -9,7 +9,6 @@ package main
 import (
 	"bufio"
 	"fmt"
-	"internal/trace"
 	"io"
 	"io/ioutil"
 	"net/http"
@@ -21,6 +20,8 @@ import (
 	"strconv"
 	"time"
 
+	trace "internal/traceparser"
+
 	"github.com/google/pprof/profile"
 )
 
@@ -60,22 +61,22 @@ 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 {
+func pprofByGoroutine(compute func(io.Writer, map[uint64][]interval, *trace.Parsed) 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()
+		res, err := parseTrace()
 		if err != nil {
 			return err
 		}
-		gToIntervals, err := pprofMatchingGoroutines(id, events)
+		gToIntervals, err := pprofMatchingGoroutines(id, res)
 		if err != nil {
 			return err
 		}
-		return compute(w, gToIntervals, events)
+		return compute(w, gToIntervals, res)
 	}
 }
 
-func pprofByRegion(compute func(io.Writer, map[uint64][]interval, []*trace.Event) error) func(w io.Writer, r *http.Request) error {
+func pprofByRegion(compute func(io.Writer, map[uint64][]interval, *trace.Parsed) error) func(w io.Writer, r *http.Request) error {
 	return func(w io.Writer, r *http.Request) error {
 		filter, err := newRegionFilter(r)
 		if err != nil {
@@ -85,7 +86,7 @@ func pprofByRegion(compute func(io.Writer, map[uint64][]interval, []*trace.Event
 		if err != nil {
 			return err
 		}
-		events, _ := parseEvents()
+		events, _ := parseTrace()
 
 		return compute(w, gToIntervals, events)
 	}
@@ -94,15 +95,15 @@ func pprofByRegion(compute func(io.Writer, map[uint64][]interval, []*trace.Event
 // pprofMatchingGoroutines parses the goroutine type id string (i.e. pc)
 // 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][]interval, error) {
+func pprofMatchingGoroutines(id string, p *trace.Parsed) (map[uint64][]interval, 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)
+	analyzeGoroutines(p)
 	var res map[uint64][]interval
 	for _, g := range gs {
 		if g.PC != pc {
@@ -171,17 +172,25 @@ func pprofMatchingRegions(filter *regionFilter) (map[uint64][]interval, error) {
 	return gToIntervals, nil
 }
 
+func stklen(p *trace.Parsed, ev *trace.Event) int {
+	if ev.StkID == 0 {
+		return 0
+	}
+	return len(p.Stacks[ev.StkID])
+}
+
 // 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)
+func computePprofIO(w io.Writer, gToIntervals map[uint64][]interval, res *trace.Parsed) error {
+	events := res.Events
+	prof := make(map[uint32]Record)
 	for _, ev := range events {
-		if ev.Type != trace.EvGoBlockNet || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
+		if ev.Type != trace.EvGoBlockNet || ev.Link == nil || ev.StkID == 0 || stklen(res, ev) == 0 {
 			continue
 		}
 		overlapping := pprofOverlappingDuration(gToIntervals, ev)
 		if overlapping > 0 {
 			rec := prof[ev.StkID]
-			rec.stk = ev.Stk
+			rec.stk = res.Stacks[ev.StkID]
 			rec.n++
 			rec.time += overlapping.Nanoseconds()
 			prof[ev.StkID] = rec
@@ -191,8 +200,9 @@ func computePprofIO(w io.Writer, gToIntervals map[uint64][]interval, events []*t
 }
 
 // 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)
+func computePprofBlock(w io.Writer, gToIntervals map[uint64][]interval, res *trace.Parsed) error {
+	events := res.Events
+	prof := make(map[uint32]Record)
 	for _, ev := range events {
 		switch ev.Type {
 		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect,
@@ -203,13 +213,13 @@ func computePprofBlock(w io.Writer, gToIntervals map[uint64][]interval, events [
 		default:
 			continue
 		}
-		if ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
+		if ev.Link == nil || ev.StkID == 0 || stklen(res, ev) == 0 {
 			continue
 		}
 		overlapping := pprofOverlappingDuration(gToIntervals, ev)
 		if overlapping > 0 {
 			rec := prof[ev.StkID]
-			rec.stk = ev.Stk
+			rec.stk = res.Stacks[ev.StkID]
 			rec.n++
 			rec.time += overlapping.Nanoseconds()
 			prof[ev.StkID] = rec
@@ -219,16 +229,17 @@ func computePprofBlock(w io.Writer, gToIntervals map[uint64][]interval, events [
 }
 
 // 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)
+func computePprofSyscall(w io.Writer, gToIntervals map[uint64][]interval, res *trace.Parsed) error {
+	events := res.Events
+	prof := make(map[uint32]Record)
 	for _, ev := range events {
-		if ev.Type != trace.EvGoSysCall || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
+		if ev.Type != trace.EvGoSysCall || ev.Link == nil || ev.StkID == 0 || stklen(res, ev) == 0 {
 			continue
 		}
 		overlapping := pprofOverlappingDuration(gToIntervals, ev)
 		if overlapping > 0 {
 			rec := prof[ev.StkID]
-			rec.stk = ev.Stk
+			rec.stk = res.Stacks[ev.StkID]
 			rec.n++
 			rec.time += overlapping.Nanoseconds()
 			prof[ev.StkID] = rec
@@ -239,17 +250,18 @@ func computePprofSyscall(w io.Writer, gToIntervals map[uint64][]interval, events
 
 // computePprofSched generates scheduler latency pprof-like profile
 // (time between a goroutine become runnable and actually scheduled for execution).
-func computePprofSched(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
-	prof := make(map[uint64]Record)
+func computePprofSched(w io.Writer, gToIntervals map[uint64][]interval, res *trace.Parsed) error {
+	events := res.Events
+	prof := make(map[uint32]Record)
 	for _, ev := range events {
 		if (ev.Type != trace.EvGoUnblock && ev.Type != trace.EvGoCreate) ||
-			ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
+			ev.Link == nil || ev.StkID == 0 || stklen(res, ev) == 0 {
 			continue
 		}
 		overlapping := pprofOverlappingDuration(gToIntervals, ev)
 		if overlapping > 0 {
 			rec := prof[ev.StkID]
-			rec.stk = ev.Stk
+			rec.stk = res.Stacks[ev.StkID]
 			rec.n++
 			rec.time += overlapping.Nanoseconds()
 			prof[ev.StkID] = rec
@@ -327,7 +339,7 @@ func serveSVGProfile(prof func(w io.Writer, r *http.Request) error) http.Handler
 	}
 }
 
-func buildProfile(prof map[uint64]Record) *profile.Profile {
+func buildProfile(prof map[uint32]Record) *profile.Profile {
 	p := &profile.Profile{
 		PeriodType: &profile.ValueType{Type: "trace", Unit: "count"},
 		Period:     1,