}
log.Print("Parsing trace...")
- events, err := parseEvents()
+ res, err := parseTrace()
if err != nil {
dief("%v\n", err)
}
if *debugFlag {
- trace.Print(events)
+ trace.Print(res.Events)
os.Exit(0)
}
log.Print("Serializing trace...")
params := &traceParams{
- events: events,
+ parsed: res,
endTime: int64(1<<63 - 1),
}
data, err := generateTrace(params)
var ranges []Range
var loader struct {
- once sync.Once
- events []*trace.Event
- err error
+ once sync.Once
+ res trace.ParseResult
+ 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) {
loader.once.Do(func() {
tracef, err := os.Open(traceFile)
if err != nil {
defer tracef.Close()
// Parse and symbolize.
- events, err := trace.Parse(bufio.NewReader(tracef), programBinary)
+ res, err := trace.Parse(bufio.NewReader(tracef), programBinary)
if err != nil {
loader.err = fmt.Errorf("failed to parse trace: %v", err)
return
}
- loader.events = events
+ loader.res = res
})
- return loader.events, loader.err
+ return loader.res, loader.err
}
// httpMain serves the starting page.
// httpTrace serves either whole trace (goid==0) or trace for goid goroutine.
func httpTrace(w http.ResponseWriter, r *http.Request) {
- _, err := parseEvents()
+ _, err := parseTrace()
if err != nil {
http.Error(w, err.Error(), http.StatusInternalServerError)
return
// httpJsonTrace serves json trace, requested from within templTrace HTML.
func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
// This is an AJAX handler, so instead of http.Error we use log.Printf to log errors.
- events, err := parseEvents()
+ res, err := parseTrace()
if err != nil {
log.Printf("failed to parse trace: %v", err)
return
}
params := &traceParams{
- events: events,
+ parsed: res,
endTime: int64(1<<63 - 1),
}
log.Printf("failed to parse goid parameter '%v': %v", goids, err)
return
}
- analyzeGoroutines(events)
+ analyzeGoroutines(res.Events)
g := gs[goid]
params.gtrace = true
params.startTime = g.StartTime
params.endTime = g.EndTime
params.maing = goid
- params.gs = trace.RelatedGoroutines(events, goid)
+ params.gs = trace.RelatedGoroutines(res.Events, goid)
}
data, err := generateTrace(params)
}
type traceParams struct {
- events []*trace.Event
+ parsed trace.ParseResult
gtrace bool
startTime int64
endTime int64
ctx.data.TimeUnit = "ns"
maxProc := 0
ginfos := make(map[uint64]*gInfo)
+ stacks := params.parsed.Stacks
getGInfo := func(g uint64) *gInfo {
info, ok := ginfos[g]
info.state = newState
}
- for _, ev := range ctx.events {
+ for _, ev := range ctx.parsed.Events {
// Handle state transitions before we filter out events.
switch ev.Type {
case trace.EvGoStart, trace.EvGoStartLabel:
setGState(ev, ev.G, gRunnable, gRunning)
info := getGInfo(ev.G)
- if info.name == "" {
- if len(ev.Stk) == 0 {
- info.name = fmt.Sprintf("G%v", ev.G)
- } else {
- fname := ev.Stk[0].Fn
- info.name = fmt.Sprintf("G%v %s", ev.G, fname)
- info.isSystemG = strings.HasPrefix(fname, "runtime.") && fname != "runtime.main"
- }
- }
info.start = ev
case trace.EvProcStart:
ctx.threadStats.prunning++
case trace.EvProcStop:
ctx.threadStats.prunning--
case trace.EvGoCreate:
+ newG := ev.Args[0]
+ info := getGInfo(newG)
+ if info.name != "" {
+ return ctx.data, fmt.Errorf("duplicate go create event for go id=%d detected at offset %d", newG, ev.Off)
+ }
+
+ stk, ok := stacks[ev.Args[1]]
+ if !ok || len(stk) == 0 {
+ return ctx.data, fmt.Errorf("invalid go create event: missing stack information for go id=%d at offset %d", newG, ev.Off)
+ }
+
+ fname := stk[0].Fn
+ info.name = fmt.Sprintf("G%v %s", newG, fname)
+ info.isSystemG = strings.HasPrefix(fname, "runtime.") && fname != "runtime.main"
+
ctx.gcount++
- setGState(ev, ev.Args[0], gDead, gRunnable)
+ setGState(ev, newG, gDead, gRunnable)
case trace.EvGoEnd:
ctx.gcount--
setGState(ev, ev.G, gRunning, gDead)
+// Copyright 2016 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 (
"testing"
)
+// stacks is a fake stack map populated for test.
+type stacks map[uint64][]*trace.Frame
+
+// add adds a stack with a single frame whose Fn field is
+// set to the provided fname and returns a unique stack id.
+func (s *stacks) add(fname string) uint64 {
+ if *s == nil {
+ *s = make(map[uint64][]*trace.Frame)
+ }
+
+ id := uint64(len(*s))
+ (*s)[id] = []*trace.Frame{{Fn: fname}}
+ return id
+}
+
// TestGoroutineCount tests runnable/running goroutine counts computed by generateTrace
// remain in the valid range.
// - the counts must not be negative. generateTrace will return an error.
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]
+ var s stacks
+
// In this test, we assume a valid trace contains EvGoWaiting or EvGoInSyscall
// event for every blocked goroutine.
// goroutine 10: blocked
- w.Emit(trace.EvGoCreate, 1, 10, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
- w.Emit(trace.EvGoWaiting, 1, 10) // [timestamp, goroutine id]
+ w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
+ w.Emit(trace.EvGoWaiting, 1, 10) // [timestamp, goroutine id]
// goroutine 20: in syscall
- w.Emit(trace.EvGoCreate, 1, 20, 2, 1)
+ w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
w.Emit(trace.EvGoInSyscall, 1, 20) // [timestamp, goroutine id]
// goroutine 30: runnable
- w.Emit(trace.EvGoCreate, 1, 30, 5, 1)
+ w.Emit(trace.EvGoCreate, 1, 30, s.add("pkg.f3"), s.add("main.f3"))
w.Emit(trace.EvProcStart, 2, 0) // [timestamp, thread id]
// goroutine 40: runnable->running->runnable
- w.Emit(trace.EvGoCreate, 1, 40, 7, 1)
- w.Emit(trace.EvGoStartLocal, 1, 40) // [timestamp, goroutine id]
- w.Emit(trace.EvGoSched, 1, 8) // [timestamp, stack]
+ w.Emit(trace.EvGoCreate, 1, 40, s.add("pkg.f4"), s.add("main.f4"))
+ w.Emit(trace.EvGoStartLocal, 1, 40) // [timestamp, goroutine id]
+ w.Emit(trace.EvGoSched, 1, s.add("main.f4")) // [timestamp, stack]
- events, err := trace.Parse(w, "")
+ res, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}
+ res.Stacks = s // use fake stacks.
params := &traceParams{
- events: events,
+ parsed: res,
endTime: int64(1<<63 - 1),
}
// Test that we handle state changes to selected goroutines
// caused by events on goroutines that are not selected.
+ var s stacks
+
w := trace.NewWriter()
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]
// goroutine 10: blocked
- w.Emit(trace.EvGoCreate, 1, 10, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
- w.Emit(trace.EvGoWaiting, 1, 10) // [timestamp, goroutine id]
+ w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
+ w.Emit(trace.EvGoWaiting, 1, 10) // [timestamp, goroutine id]
// goroutine 20: runnable->running->unblock 10
- w.Emit(trace.EvGoCreate, 1, 20, 7, 1)
- w.Emit(trace.EvGoStartLocal, 1, 20) // [timestamp, goroutine id]
- w.Emit(trace.EvGoUnblockLocal, 1, 10, 8) // [timestamp, goroutine id, stack]
- w.Emit(trace.EvGoEnd, 1) // [timestamp]
+ w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
+ w.Emit(trace.EvGoStartLocal, 1, 20) // [timestamp, goroutine id]
+ w.Emit(trace.EvGoUnblockLocal, 1, 10, s.add("pkg.f2")) // [timestamp, goroutine id, stack]
+ w.Emit(trace.EvGoEnd, 1) // [timestamp]
// goroutine 10: runnable->running->block
- w.Emit(trace.EvGoStartLocal, 1, 10) // [timestamp, goroutine id]
- w.Emit(trace.EvGoBlock, 1, 9) // [timestamp, stack]
+ w.Emit(trace.EvGoStartLocal, 1, 10) // [timestamp, goroutine id]
+ w.Emit(trace.EvGoBlock, 1, s.add("pkg.f3")) // [timestamp, stack]
- events, err := trace.Parse(w, "")
+ res, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}
+ res.Stacks = s // use fake stacks
params := &traceParams{
- events: events,
+ parsed: res,
endTime: int64(1<<63 - 1),
gs: map[uint64]bool{10: true},
}
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]
+ var s stacks
// goroutine 9999: running -> mark assisting -> preempted -> assisting -> running -> block
- w.Emit(trace.EvGoCreate, 1, 9999, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
- w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
- w.Emit(trace.EvGCMarkAssistStart, 1, 2) // [timestamp, stack]
- w.Emit(trace.EvGoPreempt, 1, 3) // [timestamp, stack]
- w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
- w.Emit(trace.EvGCMarkAssistDone, 1) // [timestamp]
- w.Emit(trace.EvGoBlock, 1, 4) // [timestamp, stack]
-
- events, err := trace.Parse(w, "")
+ w.Emit(trace.EvGoCreate, 1, 9999, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
+ w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
+ w.Emit(trace.EvGCMarkAssistStart, 1, s.add("main.f1")) // [timestamp, stack]
+ w.Emit(trace.EvGoPreempt, 1, s.add("main.f1")) // [timestamp, stack]
+ w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
+ w.Emit(trace.EvGCMarkAssistDone, 1) // [timestamp]
+ w.Emit(trace.EvGoBlock, 1, s.add("main.f2")) // [timestamp, stack]
+
+ res, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}
+ res.Stacks = s // use fake stacks
params := &traceParams{
- events: events,
+ parsed: res,
endTime: int64(1<<63 - 1),
}
--- /dev/null
+// Copyright 2017 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.
+
+// +build darwin dragonfly freebsd linux netbsd openbsd solaris
+
+package main
+
+import (
+ "bytes"
+ "internal/trace"
+ "runtime"
+ rtrace "runtime/trace"
+ "sync"
+ "syscall"
+ "testing"
+ "time"
+)
+
+// TestGoroutineInSyscall tests threads for timer goroutines
+// that preexisted when the tracing started were not counted
+// as threads in syscall. See golang.org/issues/22574.
+func TestGoroutineInSyscall(t *testing.T) {
+ // Start one goroutine blocked in syscall.
+ //
+ // TODO: syscall.Pipe used to cause the goroutine to
+ // remain blocked in syscall is not portable. Replace
+ // it with a more portable way so this test can run
+ // on non-unix architecture e.g. Windows.
+ var p [2]int
+ if err := syscall.Pipe(p[:]); err != nil {
+ t.Fatalf("failed to create pipe: %v", err)
+ }
+
+ var wg sync.WaitGroup
+ defer func() {
+ syscall.Write(p[1], []byte("a"))
+ wg.Wait()
+
+ syscall.Close(p[0])
+ syscall.Close(p[1])
+ }()
+ wg.Add(1)
+ go func() {
+ var tmp [1]byte
+ syscall.Read(p[0], tmp[:])
+ wg.Done()
+ }()
+
+ // Start multiple timer goroutines.
+ allTimers := make([]*time.Timer, 2*runtime.GOMAXPROCS(0))
+ defer func() {
+ for _, timer := range allTimers {
+ timer.Stop()
+ }
+ }()
+
+ var timerSetup sync.WaitGroup
+ for i := range allTimers {
+ timerSetup.Add(1)
+ go func(i int) {
+ defer timerSetup.Done()
+ allTimers[i] = time.AfterFunc(time.Hour, nil)
+ }(i)
+ }
+ timerSetup.Wait()
+
+ // Collect and parse trace.
+ buf := new(bytes.Buffer)
+ if err := rtrace.Start(buf); err != nil {
+ t.Fatalf("failed to start tracing: %v", err)
+ }
+ rtrace.Stop()
+
+ res, err := trace.Parse(buf, "")
+ if err != nil {
+ t.Fatalf("failed to parse trace: %v", err)
+ }
+
+ // Check only one thread for the pipe read goroutine is
+ // considered in-syscall.
+ viewerData, err := generateTrace(&traceParams{
+ parsed: res,
+ endTime: int64(1<<63 - 1),
+ })
+ if err != nil {
+ t.Fatalf("failed to generate ViewerData: %v", err)
+ }
+ for _, ev := range viewerData.Events {
+ if ev.Name == "Threads" {
+ arg := ev.Arg.(*threadCountersArg)
+ if arg.InSyscall > 1 {
+ t.Errorf("%d threads in syscall at time %v; want less than 1 thread in syscall", arg.InSyscall, ev.Time)
+ }
+ }
+ }
+}
GCP // depicts GC state
)
+// ParseResult is the result of Parse.
+type ParseResult struct {
+ // Events is the sorted list of Events in the trace.
+ Events []*Event
+ // Stacks is the stack traces keyed by stack IDs from the trace.
+ Stacks map[uint64][]*Frame
+}
+
// Parse parses, post-processes and verifies the trace.
-func Parse(r io.Reader, bin string) ([]*Event, error) {
- ver, events, err := parse(r, bin)
+func Parse(r io.Reader, bin string) (ParseResult, error) {
+ ver, res, err := parse(r, bin)
if err != nil {
- return nil, err
+ return ParseResult{}, err
}
if ver < 1007 && bin == "" {
- return nil, fmt.Errorf("for traces produced by go 1.6 or below, the binary argument must be provided")
+ return ParseResult{}, fmt.Errorf("for traces produced by go 1.6 or below, the binary argument must be provided")
}
- return events, nil
+ return res, nil
}
// parse parses, post-processes and verifies the trace. It returns the
// trace version and the list of events.
-func parse(r io.Reader, bin string) (int, []*Event, error) {
+func parse(r io.Reader, bin string) (int, ParseResult, error) {
ver, rawEvents, strings, err := readTrace(r)
if err != nil {
- return 0, nil, err
+ return 0, ParseResult{}, err
}
events, stacks, err := parseEvents(ver, rawEvents, strings)
if err != nil {
- return 0, nil, err
+ return 0, ParseResult{}, err
}
events, err = removeFutile(events)
if err != nil {
- return 0, nil, err
+ return 0, ParseResult{}, err
}
err = postProcessTrace(ver, events)
if err != nil {
- return 0, nil, err
+ return 0, ParseResult{}, err
}
// Attach stack traces.
for _, ev := range events {
}
if ver < 1007 && bin != "" {
if err := symbolize(events, bin); err != nil {
- return 0, nil, err
+ return 0, ParseResult{}, err
}
}
- return ver, events, nil
+ return ver, ParseResult{Events: events, Stacks: stacks}, nil
}
// rawEvent is a helper type used during parsing.
"go 1.5 trace\x00\x00\x00\x00\xc3\x0200",
}
for _, data := range tests {
- events, err := Parse(strings.NewReader(data), "")
- if err == nil || events != nil {
+ res, err := Parse(strings.NewReader(data), "")
+ if err == nil || res.Events != nil || res.Stacks != nil {
t.Fatalf("no error on input: %q", data)
}
}
}
func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
- events, err := trace.Parse(r, "")
+ res, err := trace.Parse(r, "")
if err == trace.ErrTimeOrder {
t.Skipf("skipping trace: %v", err)
}
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
- gs := trace.GoroutineStats(events)
+ gs := trace.GoroutineStats(res.Events)
for goid := range gs {
// We don't do any particular checks on the result at the moment.
// But still check that RelatedGoroutines does not crash, hang, etc.
- _ = trace.RelatedGoroutines(events, goid)
+ _ = trace.RelatedGoroutines(res.Events, goid)
}
- return events, gs
+ return res.Events, gs
}
func testBrokenTimestamps(t *testing.T, data []byte) {