trace_stack_test.go

Documentation: runtime/trace

		 1  // Copyright 2014 The Go Authors. All rights reserved.
		 2  // Use of this source code is governed by a BSD-style
		 3  // license that can be found in the LICENSE file.
		 4  
		 5  package trace_test
		 6  
		 7  import (
		 8  	"bytes"
		 9  	"fmt"
		10  	"internal/testenv"
		11  	"internal/trace"
		12  	"net"
		13  	"os"
		14  	"runtime"
		15  	. "runtime/trace"
		16  	"strings"
		17  	"sync"
		18  	"testing"
		19  	"text/tabwriter"
		20  	"time"
		21  )
		22  
		23  // TestTraceSymbolize tests symbolization and that events has proper stacks.
		24  // In particular that we strip bottom uninteresting frames like goexit,
		25  // top uninteresting frames (runtime guts).
		26  func TestTraceSymbolize(t *testing.T) {
		27  	skipTraceSymbolizeTestIfNecessary(t)
		28  
		29  	buf := new(bytes.Buffer)
		30  	if err := Start(buf); err != nil {
		31  		t.Fatalf("failed to start tracing: %v", err)
		32  	}
		33  	defer Stop() // in case of early return
		34  
		35  	// Now we will do a bunch of things for which we verify stacks later.
		36  	// It is impossible to ensure that a goroutine has actually blocked
		37  	// on a channel, in a select or otherwise. So we kick off goroutines
		38  	// that need to block first in the hope that while we are executing
		39  	// the rest of the test, they will block.
		40  	go func() { // func1
		41  		select {}
		42  	}()
		43  	go func() { // func2
		44  		var c chan int
		45  		c <- 0
		46  	}()
		47  	go func() { // func3
		48  		var c chan int
		49  		<-c
		50  	}()
		51  	done1 := make(chan bool)
		52  	go func() { // func4
		53  		<-done1
		54  	}()
		55  	done2 := make(chan bool)
		56  	go func() { // func5
		57  		done2 <- true
		58  	}()
		59  	c1 := make(chan int)
		60  	c2 := make(chan int)
		61  	go func() { // func6
		62  		select {
		63  		case <-c1:
		64  		case <-c2:
		65  		}
		66  	}()
		67  	var mu sync.Mutex
		68  	mu.Lock()
		69  	go func() { // func7
		70  		mu.Lock()
		71  		mu.Unlock()
		72  	}()
		73  	var wg sync.WaitGroup
		74  	wg.Add(1)
		75  	go func() { // func8
		76  		wg.Wait()
		77  	}()
		78  	cv := sync.NewCond(&sync.Mutex{})
		79  	go func() { // func9
		80  		cv.L.Lock()
		81  		cv.Wait()
		82  		cv.L.Unlock()
		83  	}()
		84  	ln, err := net.Listen("tcp", "127.0.0.1:0")
		85  	if err != nil {
		86  		t.Fatalf("failed to listen: %v", err)
		87  	}
		88  	go func() { // func10
		89  		c, err := ln.Accept()
		90  		if err != nil {
		91  			t.Errorf("failed to accept: %v", err)
		92  			return
		93  		}
		94  		c.Close()
		95  	}()
		96  	rp, wp, err := os.Pipe()
		97  	if err != nil {
		98  		t.Fatalf("failed to create a pipe: %v", err)
		99  	}
	 100  	defer rp.Close()
	 101  	defer wp.Close()
	 102  	pipeReadDone := make(chan bool)
	 103  	go func() { // func11
	 104  		var data [1]byte
	 105  		rp.Read(data[:])
	 106  		pipeReadDone <- true
	 107  	}()
	 108  
	 109  	time.Sleep(100 * time.Millisecond)
	 110  	runtime.GC()
	 111  	runtime.Gosched()
	 112  	time.Sleep(100 * time.Millisecond) // the last chance for the goroutines above to block
	 113  	done1 <- true
	 114  	<-done2
	 115  	select {
	 116  	case c1 <- 0:
	 117  	case c2 <- 0:
	 118  	}
	 119  	mu.Unlock()
	 120  	wg.Done()
	 121  	cv.Signal()
	 122  	c, err := net.Dial("tcp", ln.Addr().String())
	 123  	if err != nil {
	 124  		t.Fatalf("failed to dial: %v", err)
	 125  	}
	 126  	c.Close()
	 127  	var data [1]byte
	 128  	wp.Write(data[:])
	 129  	<-pipeReadDone
	 130  
	 131  	oldGoMaxProcs := runtime.GOMAXPROCS(0)
	 132  	runtime.GOMAXPROCS(oldGoMaxProcs + 1)
	 133  
	 134  	Stop()
	 135  
	 136  	runtime.GOMAXPROCS(oldGoMaxProcs)
	 137  
	 138  	events, _ := parseTrace(t, buf)
	 139  
	 140  	// Now check that the stacks are correct.
	 141  	type eventDesc struct {
	 142  		Type byte
	 143  		Stk	[]frame
	 144  	}
	 145  	want := []eventDesc{
	 146  		{trace.EvGCStart, []frame{
	 147  			{"runtime.GC", 0},
	 148  			{"runtime/trace_test.TestTraceSymbolize", 0},
	 149  			{"testing.tRunner", 0},
	 150  		}},
	 151  		{trace.EvGoStart, []frame{
	 152  			{"runtime/trace_test.TestTraceSymbolize.func1", 0},
	 153  		}},
	 154  		{trace.EvGoSched, []frame{
	 155  			{"runtime/trace_test.TestTraceSymbolize", 111},
	 156  			{"testing.tRunner", 0},
	 157  		}},
	 158  		{trace.EvGoCreate, []frame{
	 159  			{"runtime/trace_test.TestTraceSymbolize", 40},
	 160  			{"testing.tRunner", 0},
	 161  		}},
	 162  		{trace.EvGoStop, []frame{
	 163  			{"runtime.block", 0},
	 164  			{"runtime/trace_test.TestTraceSymbolize.func1", 0},
	 165  		}},
	 166  		{trace.EvGoStop, []frame{
	 167  			{"runtime.chansend1", 0},
	 168  			{"runtime/trace_test.TestTraceSymbolize.func2", 0},
	 169  		}},
	 170  		{trace.EvGoStop, []frame{
	 171  			{"runtime.chanrecv1", 0},
	 172  			{"runtime/trace_test.TestTraceSymbolize.func3", 0},
	 173  		}},
	 174  		{trace.EvGoBlockRecv, []frame{
	 175  			{"runtime.chanrecv1", 0},
	 176  			{"runtime/trace_test.TestTraceSymbolize.func4", 0},
	 177  		}},
	 178  		{trace.EvGoUnblock, []frame{
	 179  			{"runtime.chansend1", 0},
	 180  			{"runtime/trace_test.TestTraceSymbolize", 113},
	 181  			{"testing.tRunner", 0},
	 182  		}},
	 183  		{trace.EvGoBlockSend, []frame{
	 184  			{"runtime.chansend1", 0},
	 185  			{"runtime/trace_test.TestTraceSymbolize.func5", 0},
	 186  		}},
	 187  		{trace.EvGoUnblock, []frame{
	 188  			{"runtime.chanrecv1", 0},
	 189  			{"runtime/trace_test.TestTraceSymbolize", 114},
	 190  			{"testing.tRunner", 0},
	 191  		}},
	 192  		{trace.EvGoBlockSelect, []frame{
	 193  			{"runtime.selectgo", 0},
	 194  			{"runtime/trace_test.TestTraceSymbolize.func6", 0},
	 195  		}},
	 196  		{trace.EvGoUnblock, []frame{
	 197  			{"runtime.selectgo", 0},
	 198  			{"runtime/trace_test.TestTraceSymbolize", 115},
	 199  			{"testing.tRunner", 0},
	 200  		}},
	 201  		{trace.EvGoBlockSync, []frame{
	 202  			{"sync.(*Mutex).Lock", 0},
	 203  			{"runtime/trace_test.TestTraceSymbolize.func7", 0},
	 204  		}},
	 205  		{trace.EvGoUnblock, []frame{
	 206  			{"sync.(*Mutex).Unlock", 0},
	 207  			{"runtime/trace_test.TestTraceSymbolize", 0},
	 208  			{"testing.tRunner", 0},
	 209  		}},
	 210  		{trace.EvGoBlockSync, []frame{
	 211  			{"sync.(*WaitGroup).Wait", 0},
	 212  			{"runtime/trace_test.TestTraceSymbolize.func8", 0},
	 213  		}},
	 214  		{trace.EvGoUnblock, []frame{
	 215  			{"sync.(*WaitGroup).Add", 0},
	 216  			{"sync.(*WaitGroup).Done", 0},
	 217  			{"runtime/trace_test.TestTraceSymbolize", 120},
	 218  			{"testing.tRunner", 0},
	 219  		}},
	 220  		{trace.EvGoBlockCond, []frame{
	 221  			{"sync.(*Cond).Wait", 0},
	 222  			{"runtime/trace_test.TestTraceSymbolize.func9", 0},
	 223  		}},
	 224  		{trace.EvGoUnblock, []frame{
	 225  			{"sync.(*Cond).Signal", 0},
	 226  			{"runtime/trace_test.TestTraceSymbolize", 0},
	 227  			{"testing.tRunner", 0},
	 228  		}},
	 229  		{trace.EvGoSleep, []frame{
	 230  			{"time.Sleep", 0},
	 231  			{"runtime/trace_test.TestTraceSymbolize", 0},
	 232  			{"testing.tRunner", 0},
	 233  		}},
	 234  		{trace.EvGomaxprocs, []frame{
	 235  			{"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
	 236  			{"runtime.startTheWorldGC", 0},
	 237  			{"runtime.GOMAXPROCS", 0},
	 238  			{"runtime/trace_test.TestTraceSymbolize", 0},
	 239  			{"testing.tRunner", 0},
	 240  		}},
	 241  	}
	 242  	// Stacks for the following events are OS-dependent due to OS-specific code in net package.
	 243  	if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
	 244  		want = append(want, []eventDesc{
	 245  			{trace.EvGoBlockNet, []frame{
	 246  				{"internal/poll.(*FD).Accept", 0},
	 247  				{"net.(*netFD).accept", 0},
	 248  				{"net.(*TCPListener).accept", 0},
	 249  				{"net.(*TCPListener).Accept", 0},
	 250  				{"runtime/trace_test.TestTraceSymbolize.func10", 0},
	 251  			}},
	 252  			{trace.EvGoSysCall, []frame{
	 253  				{"syscall.read", 0},
	 254  				{"syscall.Read", 0},
	 255  				{"internal/poll.ignoringEINTRIO", 0},
	 256  				{"internal/poll.(*FD).Read", 0},
	 257  				{"os.(*File).read", 0},
	 258  				{"os.(*File).Read", 0},
	 259  				{"runtime/trace_test.TestTraceSymbolize.func11", 0},
	 260  			}},
	 261  		}...)
	 262  	}
	 263  	matched := make([]bool, len(want))
	 264  	for _, ev := range events {
	 265  	wantLoop:
	 266  		for i, w := range want {
	 267  			if matched[i] || w.Type != ev.Type || len(w.Stk) != len(ev.Stk) {
	 268  				continue
	 269  			}
	 270  
	 271  			for fi, f := range ev.Stk {
	 272  				wf := w.Stk[fi]
	 273  				if wf.Fn != f.Fn || wf.Line != 0 && wf.Line != f.Line {
	 274  					continue wantLoop
	 275  				}
	 276  			}
	 277  			matched[i] = true
	 278  		}
	 279  	}
	 280  	for i, w := range want {
	 281  		if matched[i] {
	 282  			continue
	 283  		}
	 284  		seen, n := dumpEventStacks(w.Type, events)
	 285  		t.Errorf("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
	 286  			trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
	 287  	}
	 288  }
	 289  
	 290  func skipTraceSymbolizeTestIfNecessary(t *testing.T) {
	 291  	testenv.MustHaveGoBuild(t)
	 292  	if IsEnabled() {
	 293  		t.Skip("skipping because -test.trace is set")
	 294  	}
	 295  }
	 296  
	 297  func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
	 298  	matched := 0
	 299  	o := new(bytes.Buffer)
	 300  	tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
	 301  	for _, ev := range events {
	 302  		if ev.Type != typ {
	 303  			continue
	 304  		}
	 305  		matched++
	 306  		fmt.Fprintf(tw, "Offset %d\n", ev.Off)
	 307  		for _, f := range ev.Stk {
	 308  			fname := f.File
	 309  			if idx := strings.Index(fname, "/go/src/"); idx > 0 {
	 310  				fname = fname[idx:]
	 311  			}
	 312  			fmt.Fprintf(tw, "	%v\t%s:%d\n", f.Fn, fname, f.Line)
	 313  		}
	 314  	}
	 315  	tw.Flush()
	 316  	return o.Bytes(), matched
	 317  }
	 318  
	 319  type frame struct {
	 320  	Fn	 string
	 321  	Line int
	 322  }
	 323  
	 324  func dumpFrames(frames []frame) []byte {
	 325  	o := new(bytes.Buffer)
	 326  	tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
	 327  
	 328  	for _, f := range frames {
	 329  		fmt.Fprintf(tw, "	%v\t :%d\n", f.Fn, f.Line)
	 330  	}
	 331  	tw.Flush()
	 332  	return o.Bytes()
	 333  }
	 334
View as plain text