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