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 <heschi@google.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>

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 {
+	for i, w := range want {
-		if m {
+		if matched[i] {
 			continue
 		}
-		w := want[i]
+		seen, n := dumpEventStacks(w.Type, events)
-		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("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
-		t.Errorf("seen the following events of this type:")
+			trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
-		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("======")
 	}
 }
+
+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()
+}