trace_stack_test.go

     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