From edadffa2f3464c48a234f3cf2fc092a03f91824f Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Fri, 30 Jan 2015 13:31:43 +0300 Subject: cmd/trace: add new command Trace command allows to visualize and analyze traces. Run as: $ go tool trace binary trace.file The commands opens web browser with the main page, which contains links for trace visualization, blocking profiler, network IO profiler and per-goroutine traces. Also move trace parser from runtime/pprof/trace_parser_test.go to internal/trace/parser.go, so that it can be shared between tests and the command. Change-Id: Ic97ed59ad6e4c7e1dc9eca5e979701a2b4aed7cf Reviewed-on: https://go-review.googlesource.com/3601 Reviewed-by: Andrew Gerrand --- src/cmd/trace/goroutines.go | 328 +++++++++++++++++++++++++++++++++ src/cmd/trace/main.go | 156 ++++++++++++++++ src/cmd/trace/pprof.go | 162 +++++++++++++++++ src/cmd/trace/trace.go | 434 ++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 1080 insertions(+) create mode 100644 src/cmd/trace/goroutines.go create mode 100644 src/cmd/trace/main.go create mode 100644 src/cmd/trace/pprof.go create mode 100644 src/cmd/trace/trace.go (limited to 'src/cmd/trace') diff --git a/src/cmd/trace/goroutines.go b/src/cmd/trace/goroutines.go new file mode 100644 index 0000000000..f8d1289c29 --- /dev/null +++ b/src/cmd/trace/goroutines.go @@ -0,0 +1,328 @@ +// Copyright 2014 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Goroutine-related profiles. + +package main + +import ( + "fmt" + "html/template" + "internal/trace" + "net/http" + "sort" + "strconv" +) + +func init() { + http.HandleFunc("/goroutines", httpGoroutines) + http.HandleFunc("/goroutine", httpGoroutine) +} + +// gtype describes a group of goroutines grouped by start PC. +type gtype struct { + ID uint64 // Unique identifier (PC). + Name string // Start function. + N int // Total number of goroutines in this group. + ExecTime int64 // Total execution time of all goroutines in this group. +} + +type gtypeList []gtype + +func (l gtypeList) Len() int { + return len(l) +} + +func (l gtypeList) Less(i, j int) bool { + return l[i].ExecTime > l[j].ExecTime +} + +func (l gtypeList) Swap(i, j int) { + l[i], l[j] = l[j], l[i] +} + +// gdesc desribes a single goroutine. +type gdesc struct { + ID uint64 + Name string + PC uint64 + CreateTime int64 + StartTime int64 + EndTime int64 + LastStart int64 + + ExecTime int64 + SchedWaitTime int64 + IOTime int64 + BlockTime int64 + SyscallTime int64 + GCTime int64 + SweepTime int64 + TotalTime int64 + + blockNetTime int64 + blockSyncTime int64 + blockSyscallTime int64 + blockSweepTime int64 + blockGCTime int64 + blockSchedTime int64 +} + +type gdescList []*gdesc + +func (l gdescList) Len() int { + return len(l) +} + +func (l gdescList) Less(i, j int) bool { + return l[i].TotalTime > l[j].TotalTime +} + +func (l gdescList) Swap(i, j int) { + l[i], l[j] = l[j], l[i] +} + +var gs = make(map[uint64]*gdesc) + +// analyzeGoroutines generates list gdesc's from the trace and stores it in gs. +func analyzeGoroutines(events []*trace.Event) { + if len(gs) > 0 { //!!! racy + return + } + var lastTs int64 + var gcStartTime int64 + for _, ev := range events { + lastTs = ev.Ts + switch ev.Type { + case trace.EvGoCreate: + g := &gdesc{CreateTime: ev.Ts} + g.blockSchedTime = ev.Ts + gs[ev.Args[0]] = g + case trace.EvGoStart: + g := gs[ev.G] + if g.PC == 0 { + g.PC = ev.Stk[0].PC + g.Name = ev.Stk[0].Fn + } + g.LastStart = ev.Ts + if g.StartTime == 0 { + g.StartTime = ev.Ts + } + if g.blockSchedTime != 0 { + g.SchedWaitTime += ev.Ts - g.blockSchedTime + g.blockSchedTime = 0 + } + case trace.EvGoEnd, trace.EvGoStop: + g := gs[ev.G] + g.ExecTime += ev.Ts - g.LastStart + g.TotalTime = ev.Ts - g.CreateTime + g.EndTime = ev.Ts + case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect, + trace.EvGoBlockSync, trace.EvGoBlockCond: + g := gs[ev.G] + g.ExecTime += ev.Ts - g.LastStart + g.blockSyncTime = ev.Ts + case trace.EvGoSched, trace.EvGoPreempt: + g := gs[ev.G] + g.ExecTime += ev.Ts - g.LastStart + g.blockSchedTime = ev.Ts + case trace.EvGoSleep, trace.EvGoBlock: + g := gs[ev.G] + g.ExecTime += ev.Ts - g.LastStart + case trace.EvGoBlockNet: + g := gs[ev.G] + g.ExecTime += ev.Ts - g.LastStart + g.blockNetTime = ev.Ts + case trace.EvGoUnblock: + g := gs[ev.Args[0]] + if g.blockNetTime != 0 { + g.IOTime += ev.Ts - g.blockNetTime + g.blockNetTime = 0 + } + if g.blockSyncTime != 0 { + g.BlockTime += ev.Ts - g.blockSyncTime + g.blockSyncTime = 0 + } + g.blockSchedTime = ev.Ts + case trace.EvGoSysBlock: + g := gs[ev.G] + g.ExecTime += ev.Ts - g.LastStart + g.blockSyscallTime = ev.Ts + case trace.EvGoSysExit: + g := gs[ev.G] + if g.blockSyscallTime != 0 { + g.SyscallTime += ev.Ts - g.blockSyscallTime + g.blockSyscallTime = 0 + } + g.blockSchedTime = ev.Ts + case trace.EvGCSweepStart: + g := gs[ev.G] + if g != nil { + // Sweep can happen during GC on system goroutine. + g.blockSweepTime = ev.Ts + } + case trace.EvGCSweepDone: + g := gs[ev.G] + if g != nil && g.blockSweepTime != 0 { + g.SweepTime += ev.Ts - g.blockSweepTime + g.blockSweepTime = 0 + } + case trace.EvGCStart: + gcStartTime = ev.Ts + case trace.EvGCDone: + for _, g := range gs { + if g.EndTime == 0 { + g.GCTime += ev.Ts - gcStartTime + } + } + } + } + + for _, g := range gs { + if g.TotalTime == 0 { + g.TotalTime = lastTs - g.CreateTime + } + if g.EndTime == 0 { + g.EndTime = lastTs + } + if g.blockNetTime != 0 { + g.IOTime += lastTs - g.blockNetTime + g.blockNetTime = 0 + } + if g.blockSyncTime != 0 { + g.BlockTime += lastTs - g.blockSyncTime + g.blockSyncTime = 0 + } + if g.blockSyscallTime != 0 { + g.SyscallTime += lastTs - g.blockSyscallTime + g.blockSyscallTime = 0 + } + if g.blockSchedTime != 0 { + g.SchedWaitTime += lastTs - g.blockSchedTime + g.blockSchedTime = 0 + } + } +} + +// httpGoroutines serves list of goroutine groups. +func httpGoroutines(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + analyzeGoroutines(events) + gss := make(map[uint64]gtype) + for _, g := range gs { + gs1 := gss[g.PC] + gs1.ID = g.PC + gs1.Name = g.Name + gs1.N++ + gs1.ExecTime += g.ExecTime + gss[g.PC] = gs1 + } + var glist gtypeList + for k, v := range gss { + v.ID = k + glist = append(glist, v) + } + sort.Sort(glist) + templGoroutines.Execute(w, glist) +} + +var templGoroutines = template.Must(template.New("").Parse(` + + +Goroutines:
+{{range $}} + {{.Name}} N={{.N}}
+{{end}} + + +`)) + +// httpGoroutine serves list of goroutines in a particular group. +func httpGoroutine(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + pc, err := strconv.ParseUint(r.FormValue("id"), 10, 64) + if err != nil { + http.Error(w, fmt.Sprintf("failed to parse id parameter '%v': %v", r.FormValue("id"), err), http.StatusInternalServerError) + return + } + analyzeGoroutines(events) + var glist gdescList + for gid, g := range gs { + if g.PC != pc || g.ExecTime == 0 { + continue + } + g.ID = gid + glist = append(glist, g) + } + sort.Sort(glist) + err = templGoroutine.Execute(w, glist) + if err != nil { + http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError) + return + } +} + +var templGoroutine = template.Must(template.New("").Parse(` + + + + + + + + + + + + + + +{{range $}} + + + + + + + + + + + +{{end}} +
Goroutine Total time, ns Execution 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
{{.ID}} {{.TotalTime}} {{.ExecTime}} {{.IOTime}} {{.BlockTime}} {{.SyscallTime}} {{.SchedWaitTime}} {{.SweepTime}} {{.GCTime}}
+ + +`)) + +// relatedGoroutines finds set of related goroutines that we need to include +// into trace for goroutine goid. +func relatedGoroutines(events []*trace.Event, goid uint64) map[uint64]bool { + // BFS of depth 2 over "unblock" edges + // (what goroutines unblock goroutine goid?). + gmap := make(map[uint64]bool) + gmap[goid] = true + for i := 0; i < 2; i++ { + gmap1 := make(map[uint64]bool) + for g := range gmap { + gmap1[g] = true + } + for _, ev := range events { + if ev.Type == trace.EvGoUnblock && gmap[ev.Args[0]] { + gmap1[ev.G] = true + } + } + gmap = gmap1 + } + gmap[0] = true // for GC events + return gmap +} diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go new file mode 100644 index 0000000000..ea6eef353f --- /dev/null +++ b/src/cmd/trace/main.go @@ -0,0 +1,156 @@ +// Copyright 2014 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +/* +Trace is a tool for viewing trace files. + +Trace files can be generated with: + - runtime/pprof.StartTrace + - net/http/pprof package + - go test -trace + +Example usage: +Generate a trace file with 'go test': + go test -trace trace.out pkg +View the trace in a web browser: + go tool trace pkg.test trace.out +*/ +package main + +import ( + "bufio" + "flag" + "fmt" + "internal/trace" + "net" + "net/http" + "os" + "os/exec" + "runtime" + "sync" +) + +const usageMessage = "" + + `Usage of 'go tool trace': +Given a trace file produced by 'go test': + go test -trace=trace.out pkg + +Open a web browser displaying trace: + go tool trace [flags] pkg.test trace.out + +Flags: + -http=addr: HTTP service address (e.g., ':6060') +` + +var ( + httpFlag = flag.String("http", "localhost:0", "HTTP service address (e.g., ':6060')") + + // The binary file name, left here for serveSVGProfile. + programBinary string + traceFile string +) + +func main() { + flag.Usage = func() { + fmt.Fprintln(os.Stderr, usageMessage) + os.Exit(2) + } + flag.Parse() + + // Usage information when no arguments. + if flag.NArg() != 2 { + flag.Usage() + } + programBinary = flag.Arg(0) + traceFile = flag.Arg(1) + + ln, err := net.Listen("tcp", *httpFlag) + if err != nil { + dief("failed to create server socket: %v\n", err) + } + // Open browser. + if !startBrowser("http://" + ln.Addr().String()) { + dief("failed to start browser\n") + } + + // Parse and symbolize trace asynchronously while browser opens. + go parseEvents() + + // Start http server. + http.HandleFunc("/", httpMain) + err = http.Serve(ln, nil) + dief("failed to start http server: %v\n", err) +} + +var loader struct { + once sync.Once + events []*trace.Event + err error +} + +func parseEvents() ([]*trace.Event, error) { + loader.once.Do(func() { + tracef, err := os.Open(flag.Arg(1)) + if err != nil { + loader.err = fmt.Errorf("failed to open trace file: %v", err) + return + } + defer tracef.Close() + + // Parse and symbolize. + events, err := trace.Parse(bufio.NewReader(tracef)) + if err != nil { + loader.err = fmt.Errorf("failed to parse trace: %v", err) + return + } + err = trace.Symbolize(events, programBinary) + if err != nil { + loader.err = fmt.Errorf("failed to symbolize trace: %v", err) + return + } + loader.events = events + }) + return loader.events, loader.err +} + +// httpMain serves the starting page. +func httpMain(w http.ResponseWriter, r *http.Request) { + w.Write(templMain) +} + +var templMain = []byte(` + + +View trace
+Goroutine analysis
+IO blocking profile
+Synchronization blocking profile
+Syscall blocking profile
+Scheduler latency profile
+ + +`) + +// startBrowser tries to open the URL in a browser +// and reports whether it succeeds. +// Note: copied from x/tools/cmd/cover/html.go +func startBrowser(url string) bool { + // try to start the browser + var args []string + switch runtime.GOOS { + case "darwin": + args = []string{"open"} + case "windows": + args = []string{"cmd", "/c", "start"} + default: + args = []string{"xdg-open"} + } + cmd := exec.Command(args[0], append(args[1:], url)...) + return cmd.Start() == nil +} + +func dief(msg string, args ...interface{}) { + fmt.Fprintf(os.Stderr, msg, args...) + os.Exit(1) +} diff --git a/src/cmd/trace/pprof.go b/src/cmd/trace/pprof.go new file mode 100644 index 0000000000..9e6f277978 --- /dev/null +++ b/src/cmd/trace/pprof.go @@ -0,0 +1,162 @@ +// Copyright 2014 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Serving of pprof-like profiles. + +package main + +import ( + "bufio" + "fmt" + "internal/trace" + "io/ioutil" + "net/http" + "os" + "os/exec" +) + +func init() { + http.HandleFunc("/io", httpIO) + http.HandleFunc("/block", httpBlock) + http.HandleFunc("/syscall", httpSyscall) + http.HandleFunc("/sched", httpSched) +} + +// Record represents one entry in pprof-like profiles. +type Record struct { + stk []*trace.Frame + n uint64 + time int64 +} + +// httpIO serves IO pprof-like profile (time spent in IO wait). +func httpIO(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + 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 + } + rec := prof[ev.StkID] + rec.stk = ev.Stk + rec.n++ + rec.time += ev.Link.Ts - ev.Ts + prof[ev.StkID] = rec + } + serveSVGProfile(w, r, prof) +} + +// httpBlock serves blocking pprof-like profile (time spent blocked on synchronization primitives). +func httpBlock(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + prof := make(map[uint64]Record) + for _, ev := range events { + switch ev.Type { + case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect, + trace.EvGoBlockSync, trace.EvGoBlockCond: + default: + continue + } + if ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 { + continue + } + rec := prof[ev.StkID] + rec.stk = ev.Stk + rec.n++ + rec.time += ev.Link.Ts - ev.Ts + prof[ev.StkID] = rec + } + serveSVGProfile(w, r, prof) +} + +// httpSyscall serves syscall pprof-like profile (time spent blocked in syscalls). +func httpSyscall(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + 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 + } + rec := prof[ev.StkID] + rec.stk = ev.Stk + rec.n++ + rec.time += ev.Link.Ts - ev.Ts + prof[ev.StkID] = rec + } + serveSVGProfile(w, r, prof) +} + +// httpSched serves scheduler latency pprof-like profile +// (time between a goroutine become runnable and actually scheduled for execution). +func httpSched(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + 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 + } + rec := prof[ev.StkID] + rec.stk = ev.Stk + rec.n++ + rec.time += ev.Link.Ts - ev.Ts + prof[ev.StkID] = rec + } + serveSVGProfile(w, r, prof) +} + +// generateSVGProfile generates pprof-like profile stored in prof and writes in to w. +func serveSVGProfile(w http.ResponseWriter, r *http.Request, prof map[uint64]Record) { + blockf, err := ioutil.TempFile("", "block") + if err != nil { + http.Error(w, fmt.Sprintf("failed to create temp file: %v", err), http.StatusInternalServerError) + return + } + defer os.Remove(blockf.Name()) + blockb := bufio.NewWriter(blockf) + fmt.Fprintf(blockb, "--- contention:\ncycles/second=1000000000\n") + for _, rec := range prof { + fmt.Fprintf(blockb, "%v %v @", rec.time, rec.n) + for _, f := range rec.stk { + fmt.Fprintf(blockb, " 0x%x", f.PC) + } + fmt.Fprintf(blockb, "\n") + } + err = blockb.Flush() + if err != nil { + http.Error(w, fmt.Sprintf("failed to flush temp file: %v", err), http.StatusInternalServerError) + return + } + err = blockf.Close() + if err != nil { + http.Error(w, fmt.Sprintf("failed to close temp file: %v", err), http.StatusInternalServerError) + return + } + + svgFilename := blockf.Name() + ".svg" + _, err = exec.Command("go", "tool", "pprof", "-svg", "-output", svgFilename, programBinary, blockf.Name()).CombinedOutput() + if err != nil { + http.Error(w, fmt.Sprintf("failed to execute go tool pprof: %v", err), http.StatusInternalServerError) + return + } + defer os.Remove(svgFilename) + w.Header().Set("Content-Type", "image/svg+xml") + http.ServeFile(w, r, svgFilename) +} diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go new file mode 100644 index 0000000000..8f8ef14687 --- /dev/null +++ b/src/cmd/trace/trace.go @@ -0,0 +1,434 @@ +// Copyright 2014 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package main + +import ( + "encoding/json" + "fmt" + "internal/trace" + "net/http" + "os" + "path/filepath" + "strconv" + "strings" +) + +func init() { + http.HandleFunc("/trace", httpTrace) + http.HandleFunc("/jsontrace", httpJsonTrace) + http.HandleFunc("/trace_viewer_html", httpTraceViewerHTML) +} + +// httpTrace serves either whole trace (goid==0) or trace for goid goroutine. +func httpTrace(w http.ResponseWriter, r *http.Request) { + _, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + + params := "" + if goids := r.FormValue("goid"); goids != "" { + goid, err := strconv.ParseUint(goids, 10, 64) + if err != nil { + http.Error(w, fmt.Sprintf("failed to parse goid parameter '%v': %v", goids, err), http.StatusInternalServerError) + return + } + params = fmt.Sprintf("?goid=%v", goid) + } + html := strings.Replace(templTrace, "{{PARAMS}}", params, -1) + w.Write([]byte(html)) + +} + +var templTrace = ` + + + + + + + + +` + +// httpTraceViewerHTML serves static part of trace-viewer. +// This URL is queried from templTrace HTML. +func httpTraceViewerHTML(w http.ResponseWriter, r *http.Request) { + http.ServeFile(w, r, filepath.Join(os.Getenv("GOROOT"), "misc", "trace", "trace_viewer_lean.html")) +} + +// httpJsonTrace serves json trace, requested from within templTrace HTML. +func httpJsonTrace(w http.ResponseWriter, r *http.Request) { + events, err := parseEvents() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + + params := &traceParams{ + events: events, + endTime: int64(1<<63 - 1), + } + + if goids := r.FormValue("goid"); goids != "" { + goid, err := strconv.ParseUint(goids, 10, 64) + if err != nil { + http.Error(w, fmt.Sprintf("failed to parse goid parameter '%v': %v", goids, err), http.StatusInternalServerError) + return + } + analyzeGoroutines(events) + g := gs[goid] + params.gtrace = true + params.startTime = g.StartTime + params.endTime = g.EndTime + params.maing = goid + params.gs = relatedGoroutines(events, goid) + } + + err = json.NewEncoder(w).Encode(generateTrace(params)) + if err != nil { + http.Error(w, fmt.Sprintf("failed to serialize trace: %v", err), http.StatusInternalServerError) + return + } +} + +type traceParams struct { + events []*trace.Event + gtrace bool + startTime int64 + endTime int64 + maing uint64 + gs map[uint64]bool +} + +type traceContext struct { + *traceParams + data ViewerData + frameTree frameNode + frameSeq int + arrowSeq uint64 + heapAlloc uint64 + nextGC uint64 + gcount uint64 + grunnable uint64 + grunning uint64 + insyscall uint64 + prunning uint64 +} + +type frameNode struct { + id int + children map[uint64]frameNode +} + +type ViewerData struct { + Events []*ViewerEvent `json:"traceEvents"` + Frames map[string]ViewerFrame `json:"stackFrames"` +} + +type ViewerEvent struct { + Name string `json:"name,omitempty"` + Phase string `json:"ph"` + Scope string `json:"s,omitempty"` + Time int64 `json:"ts"` + Dur int64 `json:"dur,omitempty"` + Pid uint64 `json:"pid"` + Tid uint64 `json:"tid"` + ID uint64 `json:"id,omitempty"` + Stack int `json:"sf,omitempty"` + EndStack int `json:"esf,omitempty"` + Arg interface{} `json:"args,omitempty"` +} + +type ViewerFrame struct { + Name string `json:"name"` + Parent int `json:"parent,omitempty"` +} + +type NameArg struct { + Name string `json:"name"` +} + +type SortIndexArg struct { + Index int `json:"sort_index"` +} + +// generateTrace generates json trace for trace-viewer: +// https://github.com/google/trace-viewer +// Trace format is described at: +// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view +// If gtrace=true, generate trace for goroutine goid, otherwise whole trace. +// startTime, endTime determine part of the trace that we are interested in. +// gset restricts goroutines that are included in the resulting trace. +func generateTrace(params *traceParams) ViewerData { + ctx := &traceContext{traceParams: params} + ctx.frameTree.children = make(map[uint64]frameNode) + ctx.data.Frames = make(map[string]ViewerFrame) + maxProc := 0 + gnames := make(map[uint64]string) + for _, ev := range ctx.events { + // Handle trace.EvGoStart separately, because we need the goroutine name + // even if ignore the event otherwise. + if ev.Type == trace.EvGoStart { + if _, ok := gnames[ev.G]; !ok { + if len(ev.Stk) > 0 { + gnames[ev.G] = fmt.Sprintf("G%v %s", ev.G, ev.Stk[0].Fn) + } else { + gnames[ev.G] = fmt.Sprintf("G%v", ev.G) + } + } + } + + // Ignore events that are from uninteresting goroutines + // or outside of the interesting timeframe. + if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] { + continue + } + if ev.Ts < ctx.startTime || ev.Ts > ctx.endTime { + continue + } + + if ev.P < trace.FakeP && ev.P > maxProc { + maxProc = ev.P + } + + switch ev.Type { + case trace.EvProcStart: + if ctx.gtrace { + continue + } + ctx.prunning++ + ctx.emitThreadCounters(ev) + ctx.emitInstant(ev, "proc start") + case trace.EvProcStop: + if ctx.gtrace { + continue + } + ctx.prunning-- + ctx.emitThreadCounters(ev) + ctx.emitInstant(ev, "proc stop") + case trace.EvGCStart: + ctx.emitSlice(ev, "GC") + case trace.EvGCDone: + case trace.EvGCScanStart: + if ctx.gtrace { + continue + } + ctx.emitSlice(ev, "MARK") + case trace.EvGCScanDone: + case trace.EvGCSweepStart: + ctx.emitSlice(ev, "SWEEP") + case trace.EvGCSweepDone: + case trace.EvGoStart: + ctx.grunnable-- + ctx.grunning++ + ctx.emitGoroutineCounters(ev) + ctx.emitSlice(ev, gnames[ev.G]) + case trace.EvGoCreate: + ctx.gcount++ + ctx.grunnable++ + ctx.emitGoroutineCounters(ev) + ctx.emitArrow(ev, "go") + case trace.EvGoEnd: + ctx.gcount-- + ctx.grunning-- + ctx.emitGoroutineCounters(ev) + case trace.EvGoUnblock: + ctx.grunnable++ + ctx.emitGoroutineCounters(ev) + ctx.emitArrow(ev, "unblock") + case trace.EvGoSysCall: + ctx.emitInstant(ev, "syscall") + case trace.EvGoSysExit: + ctx.grunnable++ + ctx.emitGoroutineCounters(ev) + ctx.insyscall-- + ctx.emitThreadCounters(ev) + ctx.emitArrow(ev, "sysexit") + case trace.EvGoSysBlock: + ctx.grunning-- + ctx.emitGoroutineCounters(ev) + ctx.insyscall++ + ctx.emitThreadCounters(ev) + case trace.EvGoSched, trace.EvGoPreempt: + ctx.grunnable++ + ctx.grunning-- + ctx.emitGoroutineCounters(ev) + case trace.EvGoStop, + trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv, + trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet: + ctx.grunning-- + ctx.emitGoroutineCounters(ev) + case trace.EvGoWaiting: + ctx.grunnable-- + ctx.emitGoroutineCounters(ev) + case trace.EvGoInSyscall: + ctx.insyscall++ + ctx.emitThreadCounters(ev) + case trace.EvHeapAlloc: + ctx.heapAlloc = ev.Args[0] + ctx.emitHeapCounters(ev) + case trace.EvNextGC: + ctx.nextGC = ev.Args[0] + ctx.emitHeapCounters(ev) + } + } + + ctx.emit(&ViewerEvent{Name: "process_name", Phase: "M", Pid: 0, Arg: &NameArg{"PROCS"}}) + ctx.emit(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: 0, Arg: &SortIndexArg{1}}) + + ctx.emit(&ViewerEvent{Name: "process_name", Phase: "M", Pid: 1, Arg: &NameArg{"STATS"}}) + ctx.emit(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: 1, Arg: &SortIndexArg{0}}) + + ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.NetpollP, Arg: &NameArg{"Network"}}) + ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.NetpollP, Arg: &SortIndexArg{-5}}) + + ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.TimerP, Arg: &NameArg{"Timers"}}) + ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.TimerP, Arg: &SortIndexArg{-4}}) + + ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &NameArg{"Syscalls"}}) + ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &SortIndexArg{-3}}) + + if !ctx.gtrace { + for i := 0; i <= maxProc; i++ { + ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}}) + } + } + + if ctx.gtrace && ctx.gs != nil { + for k, v := range gnames { + if !ctx.gs[k] { + continue + } + ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: k, Arg: &NameArg{v}}) + } + ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: ctx.maing, Arg: &SortIndexArg{-2}}) + ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: 0, Arg: &SortIndexArg{-1}}) + } + + return ctx.data +} + +func (ctx *traceContext) emit(e *ViewerEvent) { + ctx.data.Events = append(ctx.data.Events, e) +} + +func (ctx *traceContext) time(ev *trace.Event) int64 { + if ev.Ts < ctx.startTime || ev.Ts > ctx.endTime { + fmt.Printf("ts=%v startTime=%v endTime\n", ev.Ts, ctx.startTime, ctx.endTime) + panic("timestamp is outside of trace range") + } + // NOTE: trace viewer wants timestamps in microseconds and it does not + // handle fractional timestamps (rounds them). We give it timestamps + // in nanoseconds to avoid rounding. See: + // https://github.com/google/trace-viewer/issues/624 + return ev.Ts - ctx.startTime +} + +func (ctx *traceContext) proc(ev *trace.Event) uint64 { + if ctx.gtrace && ev.P < trace.FakeP { + return ev.G + } else { + return uint64(ev.P) + } +} + +func (ctx *traceContext) emitSlice(ev *trace.Event, name string) { + ctx.emit(&ViewerEvent{ + Name: name, + Phase: "X", + Time: ctx.time(ev), + Dur: ctx.time(ev.Link) - ctx.time(ev), + Tid: ctx.proc(ev), + //Stack: ctx.stack(ev.Stk), + EndStack: ctx.stack(ev.Link.Stk), + }) +} + +func (ctx *traceContext) emitHeapCounters(ev *trace.Event) { + type Arg struct { + Allocated uint64 + NextGC uint64 + } + if ctx.gtrace { + return + } + diff := uint64(0) + if ctx.nextGC > ctx.heapAlloc { + diff = ctx.nextGC - ctx.heapAlloc + } + ctx.emit(&ViewerEvent{Name: "Heap", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.heapAlloc, diff}}) +} + +func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) { + type Arg struct { + Running uint64 + Runnable uint64 + } + if ctx.gtrace { + return + } + ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.grunning, ctx.grunnable}}) +} + +func (ctx *traceContext) emitThreadCounters(ev *trace.Event) { + type Arg struct { + Running uint64 + InSyscall uint64 + } + if ctx.gtrace { + return + } + ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.prunning, ctx.insyscall}}) +} + +func (ctx *traceContext) emitInstant(ev *trace.Event, name string) { + ctx.emit(&ViewerEvent{Name: name, Phase: "I", Scope: "t", Time: ctx.time(ev), Tid: ctx.proc(ev), Stack: ctx.stack(ev.Stk)}) +} + +func (ctx *traceContext) emitArrow(ev *trace.Event, name string) { + if ev.Link == nil { + // The other end of the arrow is not captured in the trace. + // For example, a goroutine was unblocked but was not scheduled before trace stop. + return + } + if ctx.gtrace && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) { + return + } + + ctx.arrowSeq++ + ctx.emit(&ViewerEvent{Name: name, Phase: "s", Tid: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk)}) + ctx.emit(&ViewerEvent{Name: name, Phase: "t", Tid: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link)}) +} + +func (ctx *traceContext) stack(stk []*trace.Frame) int { + return ctx.buildBranch(ctx.frameTree, stk) +} + +// buildBranch builds one branch in the prefix tree rooted at ctx.frameTree. +func (ctx *traceContext) buildBranch(parent frameNode, stk []*trace.Frame) int { + if len(stk) == 0 { + return parent.id + } + last := len(stk) - 1 + frame := stk[last] + stk = stk[:last] + + node, ok := parent.children[frame.PC] + if !ok { + ctx.frameSeq++ + node.id = ctx.frameSeq + node.children = make(map[uint64]frameNode) + parent.children[frame.PC] = node + ctx.data.Frames[strconv.Itoa(node.id)] = ViewerFrame{fmt.Sprintf("%v:%v", frame.Fn, frame.Line), parent.id} + } + return ctx.buildBranch(node, stk) +} -- cgit v1.3-5-g9baa