-// Copyright 2014 The Go Authors. All rights reserved.
+// 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.
import (
"bytes"
+ "fmt"
+ "internal/goexperiment"
"internal/testenv"
"internal/trace"
"net"
"os"
"runtime"
. "runtime/trace"
+ "strings"
"sync"
"testing"
+ "text/tabwriter"
"time"
)
// In particular that we strip bottom uninteresting frames like goexit,
// top uninteresting frames (runtime guts).
func TestTraceSymbolize(t *testing.T) {
- skipTraceTestsIfNeeded(t)
- testenv.MustHaveExec(t)
+ skipTraceSymbolizeTestIfNecessary(t)
+
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
// on a channel, in a select or otherwise. So we kick off goroutines
// that need to block first in the hope that while we are executing
// the rest of the test, they will block.
- go func() {
+ go func() { // func1
select {}
}()
- go func() {
+ go func() { // func2
var c chan int
c <- 0
}()
- go func() {
+ go func() { // func3
var c chan int
<-c
}()
done1 := make(chan bool)
- go func() {
+ go func() { // func4
<-done1
}()
done2 := make(chan bool)
- go func() {
+ go func() { // func5
done2 <- true
}()
c1 := make(chan int)
c2 := make(chan int)
- go func() {
+ go func() { // func6
select {
case <-c1:
case <-c2:
}()
var mu sync.Mutex
mu.Lock()
- go func() {
+ go func() { // func7
mu.Lock()
mu.Unlock()
}()
var wg sync.WaitGroup
wg.Add(1)
- go func() {
+ go func() { // func8
wg.Wait()
}()
cv := sync.NewCond(&sync.Mutex{})
- go func() {
+ go func() { // func9
cv.L.Lock()
cv.Wait()
cv.L.Unlock()
if err != nil {
t.Fatalf("failed to listen: %v", err)
}
- go func() {
+ go func() { // func10
c, err := ln.Accept()
if err != nil {
- t.Fatalf("failed to accept: %v", err)
+ t.Errorf("failed to accept: %v", err)
+ return
}
c.Close()
}()
defer rp.Close()
defer wp.Close()
pipeReadDone := make(chan bool)
- go func() {
+ go func() { // func11
var data [1]byte
rp.Read(data[:])
pipeReadDone <- true
}()
- time.Sleep(time.Millisecond)
+ time.Sleep(100 * time.Millisecond)
runtime.GC()
runtime.Gosched()
- time.Sleep(time.Millisecond) // the last chance for the goroutines above to block
+ time.Sleep(100 * time.Millisecond) // the last chance for the goroutines above to block
done1 <- true
<-done2
select {
wp.Write(data[:])
<-pipeReadDone
+ oldGoMaxProcs := runtime.GOMAXPROCS(0)
+ runtime.GOMAXPROCS(oldGoMaxProcs + 1)
+
Stop()
- events, _, err := parseTrace(buf)
- if err != nil {
- t.Fatalf("failed to parse trace: %v", err)
- }
- err = trace.Symbolize(events, os.Args[0])
- if err != nil {
- t.Fatalf("failed to symbolize trace: %v", err)
- }
+
+ runtime.GOMAXPROCS(oldGoMaxProcs)
+
+ events, _ := parseTrace(t, buf)
// Now check that the stacks are correct.
- type frame struct {
- Fn string
- Line int
- }
type eventDesc struct {
Type byte
Stk []frame
}
want := []eventDesc{
- eventDesc{trace.EvGCStart, []frame{
- frame{"runtime.GC", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 106},
- frame{"testing.tRunner", 0},
+ {trace.EvGCStart, []frame{
+ {"runtime.GC", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 0},
+ {"testing.tRunner", 0},
+ }},
+ {trace.EvGoStart, []frame{
+ {"runtime/trace_test.TestTraceSymbolize.func1", 0},
}},
- eventDesc{trace.EvGoSched, []frame{
- frame{"runtime/trace_test.TestTraceSymbolize", 107},
- frame{"testing.tRunner", 0},
+ {trace.EvGoSched, []frame{
+ {"runtime/trace_test.TestTraceSymbolize", 112},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoCreate, []frame{
- frame{"runtime/trace_test.TestTraceSymbolize", 39},
- frame{"testing.tRunner", 0},
+ {trace.EvGoCreate, []frame{
+ {"runtime/trace_test.TestTraceSymbolize", 41},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoStop, []frame{
- frame{"runtime.block", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func1", 38},
+ {trace.EvGoStop, []frame{
+ {"runtime.block", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func1", 0},
}},
- eventDesc{trace.EvGoStop, []frame{
- frame{"runtime.chansend1", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func2", 42},
+ {trace.EvGoStop, []frame{
+ {"runtime.chansend1", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func2", 0},
}},
- eventDesc{trace.EvGoStop, []frame{
- frame{"runtime.chanrecv1", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func3", 46},
+ {trace.EvGoStop, []frame{
+ {"runtime.chanrecv1", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func3", 0},
}},
- eventDesc{trace.EvGoBlockRecv, []frame{
- frame{"runtime.chanrecv1", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func4", 50},
+ {trace.EvGoBlockRecv, []frame{
+ {"runtime.chanrecv1", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func4", 0},
}},
- eventDesc{trace.EvGoUnblock, []frame{
- frame{"runtime.chansend1", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 109},
- frame{"testing.tRunner", 0},
+ {trace.EvGoUnblock, []frame{
+ {"runtime.chansend1", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 114},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoBlockSend, []frame{
- frame{"runtime.chansend1", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func5", 54},
+ {trace.EvGoBlockSend, []frame{
+ {"runtime.chansend1", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func5", 0},
}},
- eventDesc{trace.EvGoUnblock, []frame{
- frame{"runtime.chanrecv1", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 110},
- frame{"testing.tRunner", 0},
+ {trace.EvGoUnblock, []frame{
+ {"runtime.chanrecv1", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 115},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoBlockSelect, []frame{
- frame{"runtime.selectgo", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func6", 59},
+ {trace.EvGoBlockSelect, []frame{
+ {"runtime.selectgo", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func6", 0},
}},
- eventDesc{trace.EvGoUnblock, []frame{
- frame{"runtime.selectgo", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 111},
- frame{"testing.tRunner", 0},
+ {trace.EvGoUnblock, []frame{
+ {"runtime.selectgo", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 116},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoBlockSync, []frame{
- frame{"sync.(*Mutex).Lock", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func7", 67},
+ {trace.EvGoBlockSync, []frame{
+ {"sync.(*Mutex).Lock", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func7", 0},
}},
- eventDesc{trace.EvGoUnblock, []frame{
- frame{"sync.(*Mutex).Unlock", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 115},
- frame{"testing.tRunner", 0},
+ {trace.EvGoUnblock, []frame{
+ {"sync.(*Mutex).Unlock", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 0},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoBlockSync, []frame{
- frame{"sync.(*WaitGroup).Wait", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func8", 73},
+ {trace.EvGoBlockSync, []frame{
+ {"sync.(*WaitGroup).Wait", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func8", 0},
}},
- eventDesc{trace.EvGoUnblock, []frame{
- frame{"sync.(*WaitGroup).Add", 0},
- frame{"sync.(*WaitGroup).Done", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 116},
- frame{"testing.tRunner", 0},
+ {trace.EvGoUnblock, []frame{
+ {"sync.(*WaitGroup).Add", 0},
+ {"sync.(*WaitGroup).Done", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 121},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoBlockCond, []frame{
- frame{"sync.(*Cond).Wait", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func9", 78},
+ {trace.EvGoBlockCond, []frame{
+ {"sync.(*Cond).Wait", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func9", 0},
}},
- eventDesc{trace.EvGoUnblock, []frame{
- frame{"sync.(*Cond).Signal", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 117},
- frame{"testing.tRunner", 0},
+ {trace.EvGoUnblock, []frame{
+ {"sync.(*Cond).Signal", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 0},
+ {"testing.tRunner", 0},
}},
- eventDesc{trace.EvGoSleep, []frame{
- frame{"time.Sleep", 0},
- frame{"runtime/trace_test.TestTraceSymbolize", 108},
- frame{"testing.tRunner", 0},
+ {trace.EvGoSleep, []frame{
+ {"time.Sleep", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 0},
+ {"testing.tRunner", 0},
+ }},
+ {trace.EvGomaxprocs, []frame{
+ {"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
+ {"runtime.startTheWorldGC", 0},
+ {"runtime.GOMAXPROCS", 0},
+ {"runtime/trace_test.TestTraceSymbolize", 0},
+ {"testing.tRunner", 0},
}},
}
// Stacks for the following events are OS-dependent due to OS-specific code in net package.
if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
want = append(want, []eventDesc{
- eventDesc{trace.EvGoBlockNet, []frame{
- frame{"net.(*netFD).accept", 0},
- frame{"net.(*TCPListener).AcceptTCP", 0},
- frame{"net.(*TCPListener).Accept", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func10", 86},
+ {trace.EvGoBlockNet, []frame{
+ {"internal/poll.(*FD).Accept", 0},
+ {"net.(*netFD).accept", 0},
+ {"net.(*TCPListener).accept", 0},
+ {"net.(*TCPListener).Accept", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func10", 0},
}},
- eventDesc{trace.EvGoSysCall, []frame{
- frame{"syscall.read", 0},
- frame{"syscall.Read", 0},
- frame{"os.(*File).read", 0},
- frame{"os.(*File).Read", 0},
- frame{"runtime/trace_test.TestTraceSymbolize.func11", 101},
+ {trace.EvGoSysCall, []frame{
+ {"syscall.read", 0},
+ {"syscall.Read", 0},
+ {"internal/poll.ignoringEINTRIO", 0},
+ {"internal/poll.(*FD).Read", 0},
+ {"os.(*File).read", 0},
+ {"os.(*File).Read", 0},
+ {"runtime/trace_test.TestTraceSymbolize.func11", 0},
}},
}...)
}
matched[i] = true
}
}
- for i, m := range matched {
- if m {
+ for i, w := range want {
+ if matched[i] {
continue
}
- w := want[i]
- t.Errorf("did not match event %v at %v:%v", trace.EventDescriptions[w.Type].Name, w.Stk[0].Fn, w.Stk[0].Line)
- t.Errorf("seen the following events of this type:")
- for _, ev := range events {
- if ev.Type != w.Type {
- continue
- }
- for _, f := range ev.Stk {
- t.Logf(" %v:%v", f.Fn, f.Line)
+ seen, n := dumpEventStacks(w.Type, events)
+ t.Errorf("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
+ trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
+ }
+}
+
+func skipTraceSymbolizeTestIfNecessary(t *testing.T) {
+ testenv.MustHaveGoBuild(t)
+ if goexperiment.ExecTracer2 {
+ // An equivalent test exists in internal/trace/v2.
+ t.Skip("skipping because this test is incompatible with the new tracer")
+ }
+ if IsEnabled() {
+ t.Skip("skipping because -test.trace is set")
+ }
+}
+
+func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
+ matched := 0
+ o := new(bytes.Buffer)
+ tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
+ for _, ev := range events {
+ if ev.Type != typ {
+ continue
+ }
+ matched++
+ fmt.Fprintf(tw, "Offset %d\n", ev.Off)
+ for _, f := range ev.Stk {
+ fname := f.File
+ if idx := strings.Index(fname, "/go/src/"); idx > 0 {
+ fname = fname[idx:]
}
- t.Logf("---")
+ fmt.Fprintf(tw, " %v\t%s:%d\n", f.Fn, fname, f.Line)
}
}
+ tw.Flush()
+ return o.Bytes(), matched
+}
+
+type frame struct {
+ Fn string
+ Line int
+}
+
+func dumpFrames(frames []frame) []byte {
+ o := new(bytes.Buffer)
+ tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
+
+ for _, f := range frames {
+ fmt.Fprintf(tw, " %v\t :%d\n", f.Fn, f.Line)
+ }
+ tw.Flush()
+ return o.Bytes()
}