From ebd04885c8684f170cc86ad42d4d7cb05a28c63b Mon Sep 17 00:00:00 2001 From: Hana Kim Date: Thu, 8 Feb 2018 13:23:48 -0500 Subject: [PATCH] runtime/trace: add stack tests for GOMAXPROCS and reorganize test log messages for stack dumps for easier debugging. The error log will be formatted like the following: trace_stack_test.go:282: Did not match event GoCreate with stack runtime/trace_test.TestTraceSymbolize :39 testing.tRunner :0 Seen 30 events of the type Offset 1890 runtime/trace_test.TestTraceSymbolize /go/src/runtime/trace/trace_stack_test.go:30 testing.tRunner /go/src/testing/testing.go:777 Offset 1899 runtime/trace_test.TestTraceSymbolize /go/src/runtime/trace/trace_stack_test.go:30 testing.tRunner /go/src/testing/testing.go:777 ... Change-Id: I0468de04507d6ae38ba84d99d13f7bf592e8d115 Reviewed-on: https://go-review.googlesource.com/92916 Reviewed-by: Heschi Kreinick Run-TryBot: Hyang-Ah Hana Kim --- src/runtime/trace/trace_stack_test.go | 142 ++++++++++++++++---------- 1 file changed, 90 insertions(+), 52 deletions(-) diff --git a/src/runtime/trace/trace_stack_test.go b/src/runtime/trace/trace_stack_test.go index 274cdf7800..0275279a6b 100644 --- a/src/runtime/trace/trace_stack_test.go +++ b/src/runtime/trace/trace_stack_test.go @@ -6,14 +6,17 @@ package trace_test import ( "bytes" + "fmt" "internal/testenv" "internal/trace" "net" "os" "runtime" . "runtime/trace" + "strings" "sync" "testing" + "text/tabwriter" "time" ) @@ -34,28 +37,28 @@ func TestTraceSymbolize(t *testing.T) { // 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: @@ -63,17 +66,17 @@ func TestTraceSymbolize(t *testing.T) { }() 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() @@ -82,7 +85,7 @@ func TestTraceSymbolize(t *testing.T) { if err != nil { t.Fatalf("failed to listen: %v", err) } - go func() { + go func() { // func10 c, err := ln.Accept() if err != nil { t.Errorf("failed to accept: %v", err) @@ -97,7 +100,7 @@ func TestTraceSymbolize(t *testing.T) { defer rp.Close() defer wp.Close() pipeReadDone := make(chan bool) - go func() { + go func() { // func11 var data [1]byte rp.Read(data[:]) pipeReadDone <- true @@ -125,14 +128,15 @@ func TestTraceSymbolize(t *testing.T) { wp.Write(data[:]) <-pipeReadDone + oldGoMaxProcs := runtime.GOMAXPROCS(1) + Stop() + + 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 @@ -140,90 +144,96 @@ func TestTraceSymbolize(t *testing.T) { want := []eventDesc{ {trace.EvGCStart, []frame{ {"runtime.GC", 0}, - {"runtime/trace_test.TestTraceSymbolize", 107}, + {"runtime/trace_test.TestTraceSymbolize", 0}, {"testing.tRunner", 0}, }}, {trace.EvGoStart, []frame{ - {"runtime/trace_test.TestTraceSymbolize.func1", 37}, + {"runtime/trace_test.TestTraceSymbolize.func1", 0}, }}, {trace.EvGoSched, []frame{ - {"runtime/trace_test.TestTraceSymbolize", 108}, + {"runtime/trace_test.TestTraceSymbolize", 111}, {"testing.tRunner", 0}, }}, {trace.EvGoCreate, []frame{ - {"runtime/trace_test.TestTraceSymbolize", 37}, + {"runtime/trace_test.TestTraceSymbolize", 40}, {"testing.tRunner", 0}, }}, {trace.EvGoStop, []frame{ {"runtime.block", 0}, - {"runtime/trace_test.TestTraceSymbolize.func1", 38}, + {"runtime/trace_test.TestTraceSymbolize.func1", 0}, }}, {trace.EvGoStop, []frame{ {"runtime.chansend1", 0}, - {"runtime/trace_test.TestTraceSymbolize.func2", 42}, + {"runtime/trace_test.TestTraceSymbolize.func2", 0}, }}, {trace.EvGoStop, []frame{ {"runtime.chanrecv1", 0}, - {"runtime/trace_test.TestTraceSymbolize.func3", 46}, + {"runtime/trace_test.TestTraceSymbolize.func3", 0}, }}, {trace.EvGoBlockRecv, []frame{ {"runtime.chanrecv1", 0}, - {"runtime/trace_test.TestTraceSymbolize.func4", 50}, + {"runtime/trace_test.TestTraceSymbolize.func4", 0}, }}, {trace.EvGoUnblock, []frame{ {"runtime.chansend1", 0}, - {"runtime/trace_test.TestTraceSymbolize", 110}, + {"runtime/trace_test.TestTraceSymbolize", 113}, {"testing.tRunner", 0}, }}, {trace.EvGoBlockSend, []frame{ {"runtime.chansend1", 0}, - {"runtime/trace_test.TestTraceSymbolize.func5", 54}, + {"runtime/trace_test.TestTraceSymbolize.func5", 0}, }}, {trace.EvGoUnblock, []frame{ {"runtime.chanrecv1", 0}, - {"runtime/trace_test.TestTraceSymbolize", 111}, + {"runtime/trace_test.TestTraceSymbolize", 114}, {"testing.tRunner", 0}, }}, {trace.EvGoBlockSelect, []frame{ {"runtime.selectgo", 0}, - {"runtime/trace_test.TestTraceSymbolize.func6", 59}, + {"runtime/trace_test.TestTraceSymbolize.func6", 0}, }}, {trace.EvGoUnblock, []frame{ {"runtime.selectgo", 0}, - {"runtime/trace_test.TestTraceSymbolize", 112}, + {"runtime/trace_test.TestTraceSymbolize", 115}, {"testing.tRunner", 0}, }}, {trace.EvGoBlockSync, []frame{ {"sync.(*Mutex).Lock", 0}, - {"runtime/trace_test.TestTraceSymbolize.func7", 67}, + {"runtime/trace_test.TestTraceSymbolize.func7", 0}, }}, {trace.EvGoUnblock, []frame{ {"sync.(*Mutex).Unlock", 0}, - {"runtime/trace_test.TestTraceSymbolize", 116}, + {"runtime/trace_test.TestTraceSymbolize", 0}, {"testing.tRunner", 0}, }}, {trace.EvGoBlockSync, []frame{ {"sync.(*WaitGroup).Wait", 0}, - {"runtime/trace_test.TestTraceSymbolize.func8", 73}, + {"runtime/trace_test.TestTraceSymbolize.func8", 0}, }}, {trace.EvGoUnblock, []frame{ {"sync.(*WaitGroup).Add", 0}, {"sync.(*WaitGroup).Done", 0}, - {"runtime/trace_test.TestTraceSymbolize", 117}, + {"runtime/trace_test.TestTraceSymbolize", 120}, {"testing.tRunner", 0}, }}, {trace.EvGoBlockCond, []frame{ {"sync.(*Cond).Wait", 0}, - {"runtime/trace_test.TestTraceSymbolize.func9", 78}, + {"runtime/trace_test.TestTraceSymbolize.func9", 0}, }}, {trace.EvGoUnblock, []frame{ {"sync.(*Cond).Signal", 0}, - {"runtime/trace_test.TestTraceSymbolize", 118}, + {"runtime/trace_test.TestTraceSymbolize", 0}, {"testing.tRunner", 0}, }}, {trace.EvGoSleep, []frame{ {"time.Sleep", 0}, - {"runtime/trace_test.TestTraceSymbolize", 109}, + {"runtime/trace_test.TestTraceSymbolize", 0}, + {"testing.tRunner", 0}, + }}, + {trace.EvGomaxprocs, []frame{ + {"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged. + {"runtime.GOMAXPROCS", 0}, + {"runtime/trace_test.TestTraceSymbolize", 0}, {"testing.tRunner", 0}, }}, } @@ -235,7 +245,7 @@ func TestTraceSymbolize(t *testing.T) { {"net.(*netFD).accept", 0}, {"net.(*TCPListener).accept", 0}, {"net.(*TCPListener).Accept", 0}, - {"runtime/trace_test.TestTraceSymbolize.func10", 86}, + {"runtime/trace_test.TestTraceSymbolize.func10", 0}, }}, {trace.EvGoSysCall, []frame{ {"syscall.read", 0}, @@ -243,7 +253,7 @@ func TestTraceSymbolize(t *testing.T) { {"internal/poll.(*FD).Read", 0}, {"os.(*File).read", 0}, {"os.(*File).Read", 0}, - {"runtime/trace_test.TestTraceSymbolize.func11", 102}, + {"runtime/trace_test.TestTraceSymbolize.func11", 0}, }}, }...) } @@ -264,22 +274,50 @@ func TestTraceSymbolize(t *testing.T) { 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 :: %s:%v", f.Fn, f.File, f.Line) - } - t.Logf("---") - } - t.Logf("======") + 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 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:] + } + 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() +}