Commit edadffa2 authored by Dmitry Vyukov's avatar Dmitry Vyukov

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/3601Reviewed-by: 's avatarAndrew Gerrand <adg@golang.org>
parent 58125ffe
This directory contains helper file for trace viewer (go tool trace).
trace_viewer_lean.html was generated following instructions in:
https://github.com/google/trace-viewer/wiki/Embedding
on revision 895aa74558d19d91906fb720df6458244ef160c6 using:
trace-viewer$ ./vulcanize_trace_viewer --config=lean
This source diff could not be displayed because it is too large. You can view the blob instead.
......@@ -400,6 +400,7 @@ var goTools = map[string]targetDir{
"cmd/objdump": toTool,
"cmd/pack": toTool,
"cmd/pprof": toTool,
"cmd/trace": toTool,
"cmd/yacc": toTool,
"golang.org/x/tools/cmd/cover": toTool,
"golang.org/x/tools/cmd/godoc": toBin,
......
// 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(`
<html>
<body>
Goroutines: <br>
{{range $}}
<a href="/goroutine?id={{.ID}}">{{.Name}}</a> N={{.N}} <br>
{{end}}
</body>
</html>
`))
// 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(`
<html>
<body>
<table border="1" sortable="1">
<tr>
<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> GC sweeping time, ns </th>
<th> GC pause time, ns </th>
</tr>
{{range $}}
<tr>
<td> <a href="/trace?goid={{.ID}}">{{.ID}}</a> </td>
<td> {{.TotalTime}} </td>
<td> {{.ExecTime}} </td>
<td> {{.IOTime}} </td>
<td> {{.BlockTime}} </td>
<td> {{.SyscallTime}} </td>
<td> {{.SchedWaitTime}} </td>
<td> {{.SweepTime}} </td>
<td> {{.GCTime}} </td>
</tr>
{{end}}
</table>
</body>
</html>
`))
// 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
}
// 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(`
<html>
<body>
<a href="/trace">View trace</a><br>
<a href="/goroutines">Goroutine analysis</a><br>
<a href="/io">IO 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>
</body>
</html>
`)
// 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)
}
// 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)
}
// 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 = `
<html>
<head>
<link href="/trace_viewer_html" rel="import">
<script>
document.addEventListener("DOMContentLoaded", function(event) {
var viewer = new tv.TraceViewer('/jsontrace{{PARAMS}}');
document.body.appendChild(viewer);
});
</script>
</head>
<body>
</body>
</html>
`
// 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)
}
......@@ -2,13 +2,14 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package pprof_test
package trace
import (
"bufio"
"bytes"
"fmt"
"io"
"os"
"os/exec"
"sort"
"strconv"
......@@ -17,14 +18,14 @@ import (
// Event describes one event in the trace.
type Event struct {
off int // offset in input file (for debugging and error reporting)
typ byte // one of traceEv*
ts int64 // timestamp in nanoseconds
p int // P on which the event happened (can be one of timerP, netpollP, syscallP)
g uint64 // G on which the event happened
stkID uint64 // unique stack ID
stk []*Frame // stack trace (can be empty)
args [2]uint64 // event-type-specific arguments
Off int // offset in input file (for debugging and error reporting)
Type byte // one of Ev*
Ts int64 // timestamp in nanoseconds
P int // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
G uint64 // G on which the event happened
StkID uint64 // unique stack ID
Stk []*Frame // stack trace (can be empty)
Args [2]uint64 // event-type-specific arguments
// linked event (can be nil), depends on event type:
// for GCStart: the GCStop
// for GCScanStart: the GCScanDone
......@@ -36,26 +37,27 @@ type Event struct {
// for GoUnblock: the associated GoStart
// for blocking GoSysCall: the associated GoSysExit
// for GoSysExit: the next GoStart
link *Event
Link *Event
}
// Frame is a frame in stack traces.
type Frame struct {
pc uint64
fn string
file string
line int
PC uint64
Fn string
File string
Line int
}
const (
// Special P identifiers:
timerP = 1000000 + iota // depicts timer unblocks
netpollP // depicts network unblocks
syscallP // depicts returns from syscalls
FakeP = 1000000 + iota
TimerP // depicts timer unblocks
NetpollP // depicts network unblocks
SyscallP // depicts returns from syscalls
)
// parseTrace parses, post-processes and verifies the trace.
func parseTrace(r io.Reader) ([]*Event, error) {
func Parse(r io.Reader) ([]*Event, error) {
rawEvents, err := readTrace(r)
if err != nil {
return nil, err
......@@ -71,8 +73,8 @@ func parseTrace(r io.Reader) ([]*Event, error) {
return events, nil
}
// RawEvent is a helper type used during parsing.
type RawEvent struct {
// rawEvent is a helper type used during parsing.
type rawEvent struct {
off int
typ byte
args []uint64
......@@ -80,7 +82,7 @@ type RawEvent struct {
// readTrace does wire-format parsing and verification.
// It does not care about specific event types and argument meaning.
func readTrace(r io.Reader) ([]RawEvent, error) {
func readTrace(r io.Reader) ([]rawEvent, error) {
// Read and validate trace header.
var buf [8]byte
off, err := r.Read(buf[:])
......@@ -92,7 +94,7 @@ func readTrace(r io.Reader) ([]RawEvent, error) {
}
// Read events.
var events []RawEvent
var events []rawEvent
for {
// Read event type and number of arguments (1 byte).
off0 := off
......@@ -106,7 +108,7 @@ func readTrace(r io.Reader) ([]RawEvent, error) {
off += n
typ := buf[0] << 2 >> 2
narg := buf[0]>>6 + 1
ev := RawEvent{typ: typ, off: off0}
ev := rawEvent{typ: typ, off: off0}
if narg <= 3 {
for i := 0; i < int(narg); i++ {
var v uint64
......@@ -143,60 +145,60 @@ func readTrace(r io.Reader) ([]RawEvent, error) {
// Parse events transforms raw events into events.
// It does analyze and verify per-event-type arguments.
func parseEvents(rawEvents []RawEvent) (events []*Event, err error) {
func parseEvents(rawEvents []rawEvent) (events []*Event, err error) {
var ticksPerSec, lastTs int64
var lastG, timerGoid uint64
var lastP int
lastGs := make(map[int]uint64) // last goroutine running on P
stacks := make(map[uint64][]*Frame)
for _, raw := range rawEvents {
if raw.typ == traceEvNone || raw.typ >= traceEvCount {
if raw.typ == EvNone || raw.typ >= EvCount {
err = fmt.Errorf("unknown event type %v at offset 0x%x", raw.typ, raw.off)
return
}
desc := evDescriptions[raw.typ]
if desc.name == "" {
desc := EventDescriptions[raw.typ]
if desc.Name == "" {
err = fmt.Errorf("missing description for event type %v", raw.typ)
return
}
if raw.typ != traceEvStack {
narg := len(desc.args)
if desc.stack {
if raw.typ != EvStack {
narg := len(desc.Args)
if desc.Stack {
narg++
}
if raw.typ != traceEvBatch && raw.typ != traceEvFrequency && raw.typ != traceEvTimerGoroutine {
if raw.typ != EvBatch && raw.typ != EvFrequency && raw.typ != EvTimerGoroutine {
narg++ // timestamp
}
if len(raw.args) != narg {
err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v",
desc.name, raw.off, narg, len(raw.args))
desc.Name, raw.off, narg, len(raw.args))
return
}
}
switch raw.typ {
case traceEvBatch:
case EvBatch:
lastGs[lastP] = lastG
lastP = int(raw.args[0])
lastG = lastGs[lastP]
lastTs = int64(raw.args[1])
case traceEvFrequency:
case EvFrequency:
ticksPerSec = int64(raw.args[0])
if ticksPerSec <= 0 {
err = fmt.Errorf("traceEvFrequency contains invalid frequency %v at offset 0x%x",
err = fmt.Errorf("EvFrequency contains invalid frequency %v at offset 0x%x",
ticksPerSec, raw.off)
return
}
case traceEvTimerGoroutine:
case EvTimerGoroutine:
timerGoid = raw.args[0]
case traceEvStack:
case EvStack:
if len(raw.args) < 2 {
err = fmt.Errorf("traceEvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v",
err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v",
raw.off, len(raw.args))
return
}
size := raw.args[1]
if size > 1000 {
err = fmt.Errorf("traceEvStack has bad number of frames at offset 0x%x: %v",
err = fmt.Errorf("EvStack has bad number of frames at offset 0x%x: %v",
raw.off, size)
return
}
......@@ -204,30 +206,30 @@ func parseEvents(rawEvents []RawEvent) (events []*Event, err error) {
if id != 0 && size > 0 {
stk := make([]*Frame, size)
for i := 0; i < int(size); i++ {
stk[i] = &Frame{pc: raw.args[i+2]}
stk[i] = &Frame{PC: raw.args[i+2]}
}
stacks[id] = stk
}
default:
e := &Event{off: raw.off, typ: raw.typ, p: lastP, g: lastG}
e.ts = lastTs + int64(raw.args[0])
lastTs = e.ts
for i := range desc.args {
e.args[i] = raw.args[i+1]
e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG}
e.Ts = lastTs + int64(raw.args[0])
lastTs = e.Ts
for i := range desc.Args {
e.Args[i] = raw.args[i+1]
}
if desc.stack {
e.stkID = raw.args[len(desc.args)+1]
if desc.Stack {
e.StkID = raw.args[len(desc.Args)+1]
}
switch raw.typ {
case traceEvGoStart:
lastG = e.args[0]
e.g = lastG
case traceEvGCStart, traceEvGCDone, traceEvGCScanStart, traceEvGCScanDone:
e.g = 0
case traceEvGoEnd, traceEvGoStop, traceEvGoSched, traceEvGoPreempt,
traceEvGoSleep, traceEvGoBlock, traceEvGoBlockSend, traceEvGoBlockRecv,
traceEvGoBlockSelect, traceEvGoBlockSync, traceEvGoBlockCond, traceEvGoBlockNet,
traceEvGoSysBlock:
case EvGoStart:
lastG = e.Args[0]
e.G = lastG
case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone:
e.G = 0
case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet,
EvGoSysBlock:
lastG = 0
}
events = append(events, e)
......@@ -236,27 +238,27 @@ func parseEvents(rawEvents []RawEvent) (events []*Event, err error) {
// Attach stack traces.
for _, ev := range events {
if ev.stkID != 0 {
ev.stk = stacks[ev.stkID]
if ev.StkID != 0 {
ev.Stk = stacks[ev.StkID]
}
}
// Sort by time and translate cpu ticks to real time.
sort.Sort(EventList(events))
sort.Sort(eventList(events))
if ticksPerSec == 0 {
err = fmt.Errorf("no traceEvFrequency event")
err = fmt.Errorf("no EvFrequency event")
return
}
minTs := events[0].ts
minTs := events[0].Ts
for _, ev := range events {
ev.ts = (ev.ts - minTs) * 1e9 / ticksPerSec
ev.Ts = (ev.Ts - minTs) * 1e9 / ticksPerSec
// Move timers and syscalls to separate fake Ps.
if timerGoid != 0 && ev.g == timerGoid && ev.typ == traceEvGoUnblock {
ev.p = timerP
if timerGoid != 0 && ev.G == timerGoid && ev.Type == EvGoUnblock {
ev.P = TimerP
}
if ev.typ == traceEvGoSysExit {
ev.p = syscallP
ev.g = ev.args[0]
if ev.Type == EvGoSysExit {
ev.P = SyscallP
ev.G = ev.Args[0]
}
}
......@@ -292,186 +294,189 @@ func postProcessTrace(events []*Event) error {
gs[0] = gdesc{state: gRunning}
checkRunning := func(p pdesc, g gdesc, ev *Event) error {
name := evDescriptions[ev.typ].name
name := EventDescriptions[ev.Type].Name
if g.state != gRunning {
return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.g, name, ev.off, ev.ts)
return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts)
}
if p.g != ev.g {
return fmt.Errorf("p %v is not running g %v while %v (offset %v, time %v)", ev.p, ev.g, name, ev.off, ev.ts)
if p.g != ev.G {
return fmt.Errorf("p %v is not running g %v while %v (offset %v, time %v)", ev.P, ev.G, name, ev.Off, ev.Ts)
}
return nil
}
for _, ev := range events {
g := gs[ev.g]
p := ps[ev.p]
g := gs[ev.G]
p := ps[ev.P]
switch ev.typ {
case traceEvProcStart:
switch ev.Type {
case EvProcStart:
if p.running {
return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.p, ev.off, ev.ts)
return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts)
}
p.running = true
case traceEvProcStop:
case EvProcStop:
if !p.running {
return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.p, ev.off, ev.ts)
return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts)
}
if p.g != 0 {
return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.p, p.g, ev.off, ev.ts)
return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts)
}
p.running = false
case traceEvGCStart:
case EvGCStart:
if p.evGC != nil {
return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.off, ev.ts)
return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
}
p.evGC = ev
case traceEvGCDone:
case EvGCDone:
if p.evGC == nil {
return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.off, ev.ts)
return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts)
}
p.evGC.link = ev
p.evGC.Link = ev
p.evGC = nil
case traceEvGCScanStart:
case EvGCScanStart:
if p.evScan != nil {
return fmt.Errorf("previous scanning is not ended before a new one (offset %v, time %v)", ev.off, ev.ts)
return fmt.Errorf("previous scanning is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
}
p.evScan = ev
case traceEvGCScanDone:
case EvGCScanDone:
if p.evScan == nil {
return fmt.Errorf("bogus scanning end (offset %v, time %v)", ev.off, ev.ts)
return fmt.Errorf("bogus scanning end (offset %v, time %v)", ev.Off, ev.Ts)
}
p.evScan.link = ev
p.evScan.Link = ev
p.evScan = nil
case traceEvGCSweepStart:
case EvGCSweepStart:
if p.evSweep != nil {
return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.off, ev.ts)
return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
}
p.evSweep = ev
case traceEvGCSweepDone:
case EvGCSweepDone:
if p.evSweep == nil {
return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.off, ev.ts)
return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts)
}
p.evSweep.link = ev
p.evSweep.Link = ev
p.evSweep = nil
case traceEvGoWaiting:
g1 := gs[ev.args[0]]
case EvGoWaiting:
g1 := gs[ev.Args[0]]
if g1.state != gRunnable {
return fmt.Errorf("g %v is not runnable before traceEvGoWaiting (offset %v, time %v)", ev.args[0], ev.off, ev.ts)
return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
}
g1.state = gWaiting
gs[ev.args[0]] = g1
case traceEvGoInSyscall:
gs[ev.Args[0]] = g1
case EvGoInSyscall:
// this case is intentionally left blank
case traceEvGoCreate:
case EvGoCreate:
if err := checkRunning(p, g, ev); err != nil {
return err
}
if _, ok := gs[ev.args[0]]; ok {
return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.args[0], ev.off, ev.ts)
if _, ok := gs[ev.Args[0]]; ok {
return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
}
gs[ev.args[0]] = gdesc{state: gRunnable, ev: ev}
case traceEvGoStart:
gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev}
case EvGoStart:
if g.state != gRunnable {
return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.g, ev.off, ev.ts)
return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
}
if p.g != 0 {
return fmt.Errorf("p %v is already running g %v while start g %v (offset %v, time %v)", ev.p, p.g, ev.g, ev.off, ev.ts)
return fmt.Errorf("p %v is already running g %v while start g %v (offset %v, time %v)", ev.P, p.g, ev.G, ev.Off, ev.Ts)
}
g.state = gRunning
g.evStart = ev
p.g = ev.g
p.g = ev.G
if g.ev != nil {
if g.ev.typ == traceEvGoCreate {
if g.ev.Type == EvGoCreate {
// +1 because symblizer expects return pc.
ev.stk = []*Frame{&Frame{pc: g.ev.args[1] + 1}}
ev.Stk = []*Frame{&Frame{PC: g.ev.Args[1] + 1}}
}
g.ev.link = ev
g.ev.Link = ev
g.ev = nil
}
case traceEvGoEnd, traceEvGoStop:
case EvGoEnd, EvGoStop:
if err := checkRunning(p, g, ev); err != nil {
return err
}
g.evStart.link = ev
g.evStart.Link = ev
g.evStart = nil
g.state = gDead
p.g = 0
case traceEvGoSched, traceEvGoPreempt:
case EvGoSched, EvGoPreempt:
if err := checkRunning(p, g, ev); err != nil {
return err
}
g.state = gRunnable
g.evStart.link = ev
g.evStart.Link = ev
g.evStart = nil
p.g = 0
g.ev = ev
case traceEvGoUnblock:
case EvGoUnblock:
if g.state != gRunning {
return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.g, ev.off, ev.ts)
return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
}
if ev.p != timerP && p.g != ev.g {
return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.p, ev.g, ev.off, ev.ts)
if ev.P != TimerP && p.g != ev.G {
return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts)
}
g1 := gs[ev.args[0]]
g1 := gs[ev.Args[0]]
if g1.state != gWaiting {
return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.args[0], ev.off, ev.ts)
return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
}
if g1.ev != nil && g1.ev.typ == traceEvGoBlockNet && ev.p != timerP {
ev.p = netpollP
if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP {
ev.P = NetpollP
}
if g1.ev != nil {
g1.ev.link = ev
g1.ev.Link = ev
}
g1.state = gRunnable
g1.ev = ev
gs[ev.args[0]] = g1
case traceEvGoSysCall:
gs[ev.Args[0]] = g1
case EvGoSysCall:
if err := checkRunning(p, g, ev); err != nil {
return err
}
g.ev = ev
case traceEvGoSysBlock:
case EvGoSysBlock:
if err := checkRunning(p, g, ev); err != nil {
return err
}
g.state = gRunnable
g.evStart.link = ev
g.evStart.Link = ev
g.evStart = nil
p.g = 0
case traceEvGoSysExit:
case EvGoSysExit:
if g.state != gRunnable {
return fmt.Errorf("g %v is not runnable during syscall exit (offset %v, time %v)", ev.g, ev.off, ev.ts)
return fmt.Errorf("g %v is not runnable during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
}
if g.ev != nil && g.ev.typ == traceEvGoSysCall {
g.ev.link = ev
if g.ev != nil && g.ev.Type == EvGoSysCall {
g.ev.Link = ev
}
g.ev = ev
case traceEvGoSleep, traceEvGoBlock, traceEvGoBlockSend, traceEvGoBlockRecv,
traceEvGoBlockSelect, traceEvGoBlockSync, traceEvGoBlockCond, traceEvGoBlockNet:
case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet:
if err := checkRunning(p, g, ev); err != nil {
return err
}
g.state = gWaiting
g.ev = ev
g.evStart.link = ev
g.evStart.Link = ev
g.evStart = nil
p.g = 0
}
gs[ev.g] = g
ps[ev.p] = p
gs[ev.G] = g
ps[ev.P] = p
}
// TODO(dvyukov): restore stacks for EvGoStart events.
// TODO(dvyukov): test that all EvGoStart events has non-nil Link.
return nil
}
// symbolizeTrace attaches func/file/line info to stack traces.
func symbolizeTrace(events []*Event, bin string) error {
func Symbolize(events []*Event, bin string) error {
// First, collect and dedup all pcs.
pcs := make(map[uint64]*Frame)
for _, ev := range events {
for _, f := range ev.stk {
pcs[f.pc] = nil
for _, f := range ev.Stk {
pcs[f.PC] = nil
}
}
......@@ -481,6 +486,7 @@ func symbolizeTrace(events []*Event, bin string) error {
if err != nil {
return fmt.Errorf("failed to pipe addr2line stdin: %v", err)
}
cmd.Stderr = os.Stderr
out, err := cmd.StdoutPipe()
if err != nil {
return fmt.Errorf("failed to pipe addr2line stdout: %v", err)
......@@ -513,14 +519,14 @@ func symbolizeTrace(events []*Event, bin string) error {
if err != nil {
return fmt.Errorf("failed to read from addr2line: %v", err)
}
f := &Frame{pc: pc}
f.fn = fn[:len(fn)-1]
f.file = file[:len(file)-1]
if colon := strings.LastIndex(f.file, ":"); colon != -1 {
ln, err := strconv.Atoi(f.file[colon+1:])
f := &Frame{PC: pc}
f.Fn = fn[:len(fn)-1]
f.File = file[:len(file)-1]
if colon := strings.LastIndex(f.File, ":"); colon != -1 {
ln, err := strconv.Atoi(f.File[colon+1:])
if err == nil {
f.file = f.file[:colon]
f.line = ln
f.File = f.File[:colon]
f.Line = ln
}
}
pcs[pc] = f
......@@ -529,8 +535,8 @@ func symbolizeTrace(events []*Event, bin string) error {
// Replace frames in events array.
for _, ev := range events {
for i, f := range ev.stk {
ev.stk[i] = pcs[f.pc]
for i, f := range ev.Stk {
ev.Stk[i] = pcs[f.PC]
}
}
......@@ -556,101 +562,101 @@ func readVal(r io.Reader, off0 int) (v uint64, off int, err error) {
return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0)
}
type EventList []*Event
type eventList []*Event
func (l EventList) Len() int {
func (l eventList) Len() int {
return len(l)
}
func (l EventList) Less(i, j int) bool {
return l[i].ts < l[j].ts
func (l eventList) Less(i, j int) bool {
return l[i].Ts < l[j].Ts
}
func (l EventList) Swap(i, j int) {
func (l eventList) Swap(i, j int) {
l[i], l[j] = l[j], l[i]
}
// Event types in the trace.
// Verbatim copy from src/runtime/trace.go.
const (
traceEvNone = 0 // unused
traceEvBatch = 1 // start of per-P batch of events [pid, timestamp]
traceEvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)]
traceEvStack = 3 // stack [stack id, number of PCs, array of PCs]
traceEvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id]
traceEvProcStart = 5 // start of P [timestamp]
traceEvProcStop = 6 // stop of P [timestamp]
traceEvGCStart = 7 // GC start [timestamp, stack id]
traceEvGCDone = 8 // GC done [timestamp]
traceEvGCScanStart = 9 // GC scan start [timestamp]
traceEvGCScanDone = 10 // GC scan done [timestamp]
traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
traceEvGCSweepDone = 12 // GC sweep done [timestamp]
traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id]
traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id]
traceEvGoEnd = 15 // goroutine ends [timestamp]
traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack]
traceEvGoSched = 17 // goroutine calls Gosched [timestamp, stack]
traceEvGoPreempt = 18 // goroutine is preempted [timestamp, stack]
traceEvGoSleep = 19 // goroutine calls Sleep [timestamp, stack]
traceEvGoBlock = 20 // goroutine blocks [timestamp, stack]
traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack]
traceEvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack]
traceEvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack]
traceEvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack]
traceEvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack]
traceEvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack]
traceEvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack]
traceEvGoSysCall = 28 // syscall enter [timestamp, stack]
traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id]
traceEvGoSysBlock = 30 // syscall blocks [timestamp, stack]
traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id]
traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id]
traceEvHeapAlloc = 33 // memstats.heap_alloc change [timestamp, heap_alloc]
traceEvNextGC = 34 // memstats.next_gc change [timestamp, next_gc]
traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id]
traceEvCount = 36
EvNone = 0 // unused
EvBatch = 1 // start of per-P batch of events [pid, timestamp]
EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)]
EvStack = 3 // stack [stack id, number of PCs, array of PCs]
EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id]
EvProcStart = 5 // start of P [timestamp]
EvProcStop = 6 // stop of P [timestamp]
EvGCStart = 7 // GC start [timestamp, stack id]
EvGCDone = 8 // GC done [timestamp]
EvGCScanStart = 9 // GC scan start [timestamp]
EvGCScanDone = 10 // GC scan done [timestamp]
EvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
EvGCSweepDone = 12 // GC sweep done [timestamp]
EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id]
EvGoStart = 14 // goroutine starts running [timestamp, goroutine id]
EvGoEnd = 15 // goroutine ends [timestamp]
EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack]
EvGoSched = 17 // goroutine calls Gosched [timestamp, stack]
EvGoPreempt = 18 // goroutine is preempted [timestamp, stack]
EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack]
EvGoBlock = 20 // goroutine blocks [timestamp, stack]
EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack]
EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack]
EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack]
EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack]
EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack]
EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack]
EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack]
EvGoSysCall = 28 // syscall enter [timestamp, stack]
EvGoSysExit = 29 // syscall exit [timestamp, goroutine id]
EvGoSysBlock = 30 // syscall blocks [timestamp, stack]
EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id]
EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id]
EvHeapAlloc = 33 // memstats.heap_alloc change [timestamp, heap_alloc]
EvNextGC = 34 // memstats.next_gc change [timestamp, next_gc]
EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id]
EvCount = 36
)
var evDescriptions = [traceEvCount]struct {
name string
stack bool
args []string
var EventDescriptions = [EvCount]struct {
Name string
Stack bool
Args []string
}{
traceEvNone: {"None", false, []string{}},
traceEvBatch: {"Batch", false, []string{"p", "ticks"}},
traceEvFrequency: {"Frequency", false, []string{"freq"}},
traceEvStack: {"Stack", false, []string{"id", "siz"}},
traceEvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}},
traceEvProcStart: {"ProcStart", false, []string{}},
traceEvProcStop: {"ProcStop", false, []string{}},
traceEvGCStart: {"GCStart", true, []string{}},
traceEvGCDone: {"GCDone", false, []string{}},
traceEvGCScanStart: {"GCScanStart", false, []string{}},
traceEvGCScanDone: {"GCScanDone", false, []string{}},
traceEvGCSweepStart: {"GCSweepStart", true, []string{}},
traceEvGCSweepDone: {"GCSweepDone", false, []string{}},
traceEvGoCreate: {"GoCreate", true, []string{"g", "pc"}},
traceEvGoStart: {"GoStart", false, []string{"g"}},
traceEvGoEnd: {"GoEnd", false, []string{}},
traceEvGoStop: {"GoStop", true, []string{}},
traceEvGoSched: {"GoSched", true, []string{}},
traceEvGoPreempt: {"GoPreempt", true, []string{}},
traceEvGoSleep: {"GoSleep", true, []string{}},
traceEvGoBlock: {"GoBlock", true, []string{}},
traceEvGoUnblock: {"GoUnblock", true, []string{"g"}},
traceEvGoBlockSend: {"GoBlockSend", true, []string{}},
traceEvGoBlockRecv: {"GoBlockRecv", true, []string{}},
traceEvGoBlockSelect: {"GoBlockSelect", true, []string{}},
traceEvGoBlockSync: {"GoBlockSync", true, []string{}},
traceEvGoBlockCond: {"GoBlockCond", true, []string{}},
traceEvGoBlockNet: {"GoBlockNet", true, []string{}},
traceEvGoSysCall: {"GoSysCall", true, []string{}},
traceEvGoSysExit: {"GoSysExit", false, []string{"g"}},
traceEvGoSysBlock: {"GoSysBlock", true, []string{}},
traceEvGoWaiting: {"GoWaiting", false, []string{"g"}},
traceEvGoInSyscall: {"GoInSyscall", false, []string{"g"}},
traceEvHeapAlloc: {"HeapAlloc", false, []string{"mem"}},
traceEvNextGC: {"NextGC", false, []string{"mem"}},
traceEvTimerGoroutine: {"TimerGoroutine", false, []string{"g"}},
EvNone: {"None", false, []string{}},
EvBatch: {"Batch", false, []string{"p", "ticks"}},
EvFrequency: {"Frequency", false, []string{"freq"}},
EvStack: {"Stack", false, []string{"id", "siz"}},
EvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}},
EvProcStart: {"ProcStart", false, []string{}},
EvProcStop: {"ProcStop", false, []string{}},
EvGCStart: {"GCStart", true, []string{}},
EvGCDone: {"GCDone", false, []string{}},
EvGCScanStart: {"GCScanStart", false, []string{}},
EvGCScanDone: {"GCScanDone", false, []string{}},
EvGCSweepStart: {"GCSweepStart", true, []string{}},
EvGCSweepDone: {"GCSweepDone", false, []string{}},
EvGoCreate: {"GoCreate", true, []string{"g", "pc"}},
EvGoStart: {"GoStart", false, []string{"g"}},
EvGoEnd: {"GoEnd", false, []string{}},
EvGoStop: {"GoStop", true, []string{}},
EvGoSched: {"GoSched", true, []string{}},
EvGoPreempt: {"GoPreempt", true, []string{}},
EvGoSleep: {"GoSleep", true, []string{}},
EvGoBlock: {"GoBlock", true, []string{}},
EvGoUnblock: {"GoUnblock", true, []string{"g"}},
EvGoBlockSend: {"GoBlockSend", true, []string{}},
EvGoBlockRecv: {"GoBlockRecv", true, []string{}},
EvGoBlockSelect: {"GoBlockSelect", true, []string{}},
EvGoBlockSync: {"GoBlockSync", true, []string{}},
EvGoBlockCond: {"GoBlockCond", true, []string{}},
EvGoBlockNet: {"GoBlockNet", true, []string{}},
EvGoSysCall: {"GoSysCall", true, []string{}},
EvGoSysExit: {"GoSysExit", false, []string{"g"}},
EvGoSysBlock: {"GoSysBlock", true, []string{}},
EvGoWaiting: {"GoWaiting", false, []string{"g"}},
EvGoInSyscall: {"GoInSyscall", false, []string{"g"}},
EvHeapAlloc: {"HeapAlloc", false, []string{"mem"}},
EvNextGC: {"NextGC", false, []string{"mem"}},
EvTimerGoroutine: {"TimerGoroutine", false, []string{"g"}},
}
......@@ -6,6 +6,7 @@ package pprof_test
import (
"bytes"
"internal/trace"
"net"
"os"
"runtime"
......@@ -66,7 +67,7 @@ func TestTrace(t *testing.T) {
t.Fatalf("failed to start tracing: %v", err)
}
StopTrace()
_, err := parseTrace(buf)
_, err := trace.Parse(buf)
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
......@@ -198,12 +199,153 @@ func TestTraceStress(t *testing.T) {
runtime.GOMAXPROCS(procs)
StopTrace()
_, err = parseTrace(buf)
_, err = trace.Parse(buf)
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
}
// Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
// And concurrently with all that start/stop trace 3 times.
func TestTraceStressStartStop(t *testing.T) {
skipTraceTestsIfNeeded(t)
defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
outerDone := make(chan bool)
go func() {
defer func() {
outerDone <- true
}()
var wg sync.WaitGroup
done := make(chan bool)
wg.Add(1)
go func() {
<-done
wg.Done()
}()
rp, wp, err := os.Pipe()
if err != nil {
t.Fatalf("failed to create pipe: %v", err)
}
defer func() {
rp.Close()
wp.Close()
}()
wg.Add(1)
go func() {
var tmp [1]byte
rp.Read(tmp[:])
<-done
wg.Done()
}()
time.Sleep(time.Millisecond)
go func() {
runtime.LockOSThread()
for {
select {
case <-done:
return
default:
runtime.Gosched()
}
}
}()
runtime.GC()
// Trigger GC from malloc.
for i := 0; i < 1e3; i++ {
_ = make([]byte, 1<<20)
}
// Create a bunch of busy goroutines to load all Ps.
for p := 0; p < 10; p++ {
wg.Add(1)
go func() {
// Do something useful.
tmp := make([]byte, 1<<16)
for i := range tmp {
tmp[i]++
}
_ = tmp
<-done
wg.Done()
}()
}
// Block in syscall.
wg.Add(1)
go func() {
var tmp [1]byte
rp.Read(tmp[:])
<-done
wg.Done()
}()
runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
// Test timers.
timerDone := make(chan bool)
go func() {
time.Sleep(time.Millisecond)
timerDone <- true
}()
<-timerDone
// A bit of network.
ln, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil {
t.Fatalf("listen failed: %v", err)
}
defer ln.Close()
go func() {
c, err := ln.Accept()
if err != nil {
return
}
time.Sleep(time.Millisecond)
var buf [1]byte
c.Write(buf[:])
c.Close()
}()
c, err := net.Dial("tcp", ln.Addr().String())
if err != nil {
t.Fatalf("dial failed: %v", err)
}
var tmp [1]byte
c.Read(tmp[:])
c.Close()
go func() {
runtime.Gosched()
select {}
}()
// Unblock helper goroutines and wait them to finish.
wp.Write(tmp[:])
wp.Write(tmp[:])
close(done)
wg.Wait()
}()
for i := 0; i < 3; i++ {
buf := new(bytes.Buffer)
if err := StartTrace(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
time.Sleep(time.Millisecond)
StopTrace()
if _, err := trace.Parse(buf); err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
}
<-outerDone
}
func TestTraceSymbolize(t *testing.T) {
skipTraceTestsIfNeeded(t)
if runtime.GOOS == "nacl" {
......@@ -215,24 +357,24 @@ func TestTraceSymbolize(t *testing.T) {
}
runtime.GC()
StopTrace()
events, err := parseTrace(buf)
events, err := trace.Parse(buf)
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
err = symbolizeTrace(events, os.Args[0])
err = trace.Symbolize(events, os.Args[0])
if err != nil {
t.Fatalf("failed to symbolize trace: %v", err)
}
found := false
eventLoop:
for _, ev := range events {
if ev.typ != traceEvGCStart {
if ev.Type != trace.EvGCStart {
continue
}
for _, f := range ev.stk {
if strings.HasSuffix(f.file, "trace_test.go") &&
strings.HasSuffix(f.fn, "pprof_test.TestTraceSymbolize") &&
f.line == 216 {
for _, f := range ev.Stk {
if strings.HasSuffix(f.File, "trace_test.go") &&
strings.HasSuffix(f.Fn, "pprof_test.TestTraceSymbolize") &&
f.Line == 358 {
found = true
break eventLoop
}
......
......@@ -190,7 +190,6 @@ func StopTrace() {
}
traceGoSched()
traceGoStart()
for _, p := range &allp {
if p == nil {
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment