...
Run Format

Source file src/runtime/trace/trace_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  	"flag"
    10  	"internal/race"
    11  	"internal/trace"
    12  	"io"
    13  	"io/ioutil"
    14  	"net"
    15  	"os"
    16  	"runtime"
    17  	. "runtime/trace"
    18  	"strconv"
    19  	"sync"
    20  	"testing"
    21  	"time"
    22  )
    23  
    24  var (
    25  	saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
    26  )
    27  
    28  // TestEventBatch tests Flush calls that happen during Start
    29  // don't produce corrupted traces.
    30  func TestEventBatch(t *testing.T) {
    31  	if race.Enabled {
    32  		t.Skip("skipping in race mode")
    33  	}
    34  	if IsEnabled() {
    35  		t.Skip("skipping because -test.trace is set")
    36  	}
    37  	if testing.Short() {
    38  		t.Skip("skipping in short mode")
    39  	}
    40  	// During Start, bunch of records are written to reflect the current
    41  	// snapshot of the program, including state of each goroutines.
    42  	// And some string constants are written to the trace to aid trace
    43  	// parsing. This test checks Flush of the buffer occurred during
    44  	// this process doesn't cause corrupted traces.
    45  	// When a Flush is called during Start is complicated
    46  	// so we test with a range of number of goroutines hoping that one
    47  	// of them triggers Flush.
    48  	// This range was chosen to fill up a ~64KB buffer with traceEvGoCreate
    49  	// and traceEvGoWaiting events (12~13bytes per goroutine).
    50  	for g := 4950; g < 5050; g++ {
    51  		n := g
    52  		t.Run("G="+strconv.Itoa(n), func(t *testing.T) {
    53  			var wg sync.WaitGroup
    54  			wg.Add(n)
    55  
    56  			in := make(chan bool, 1000)
    57  			for i := 0; i < n; i++ {
    58  				go func() {
    59  					<-in
    60  					wg.Done()
    61  				}()
    62  			}
    63  			buf := new(bytes.Buffer)
    64  			if err := Start(buf); err != nil {
    65  				t.Fatalf("failed to start tracing: %v", err)
    66  			}
    67  
    68  			for i := 0; i < n; i++ {
    69  				in <- true
    70  			}
    71  			wg.Wait()
    72  			Stop()
    73  
    74  			_, err := trace.Parse(buf, "")
    75  			if err == trace.ErrTimeOrder {
    76  				t.Skipf("skipping trace: %v", err)
    77  			}
    78  
    79  			if err != nil {
    80  				t.Fatalf("failed to parse trace: %v", err)
    81  			}
    82  		})
    83  	}
    84  }
    85  
    86  func TestTraceStartStop(t *testing.T) {
    87  	if IsEnabled() {
    88  		t.Skip("skipping because -test.trace is set")
    89  	}
    90  	buf := new(bytes.Buffer)
    91  	if err := Start(buf); err != nil {
    92  		t.Fatalf("failed to start tracing: %v", err)
    93  	}
    94  	Stop()
    95  	size := buf.Len()
    96  	if size == 0 {
    97  		t.Fatalf("trace is empty")
    98  	}
    99  	time.Sleep(100 * time.Millisecond)
   100  	if size != buf.Len() {
   101  		t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
   102  	}
   103  	saveTrace(t, buf, "TestTraceStartStop")
   104  }
   105  
   106  func TestTraceDoubleStart(t *testing.T) {
   107  	if IsEnabled() {
   108  		t.Skip("skipping because -test.trace is set")
   109  	}
   110  	Stop()
   111  	buf := new(bytes.Buffer)
   112  	if err := Start(buf); err != nil {
   113  		t.Fatalf("failed to start tracing: %v", err)
   114  	}
   115  	if err := Start(buf); err == nil {
   116  		t.Fatalf("succeed to start tracing second time")
   117  	}
   118  	Stop()
   119  	Stop()
   120  }
   121  
   122  func TestTrace(t *testing.T) {
   123  	if IsEnabled() {
   124  		t.Skip("skipping because -test.trace is set")
   125  	}
   126  	buf := new(bytes.Buffer)
   127  	if err := Start(buf); err != nil {
   128  		t.Fatalf("failed to start tracing: %v", err)
   129  	}
   130  	Stop()
   131  	saveTrace(t, buf, "TestTrace")
   132  	_, err := trace.Parse(buf, "")
   133  	if err == trace.ErrTimeOrder {
   134  		t.Skipf("skipping trace: %v", err)
   135  	}
   136  	if err != nil {
   137  		t.Fatalf("failed to parse trace: %v", err)
   138  	}
   139  }
   140  
   141  func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
   142  	res, err := trace.Parse(r, "")
   143  	if err == trace.ErrTimeOrder {
   144  		t.Skipf("skipping trace: %v", err)
   145  	}
   146  	if err != nil {
   147  		t.Fatalf("failed to parse trace: %v", err)
   148  	}
   149  	gs := trace.GoroutineStats(res.Events)
   150  	for goid := range gs {
   151  		// We don't do any particular checks on the result at the moment.
   152  		// But still check that RelatedGoroutines does not crash, hang, etc.
   153  		_ = trace.RelatedGoroutines(res.Events, goid)
   154  	}
   155  	return res.Events, gs
   156  }
   157  
   158  func testBrokenTimestamps(t *testing.T, data []byte) {
   159  	// On some processors cputicks (used to generate trace timestamps)
   160  	// produce non-monotonic timestamps. It is important that the parser
   161  	// distinguishes logically inconsistent traces (e.g. missing, excessive
   162  	// or misordered events) from broken timestamps. The former is a bug
   163  	// in tracer, the latter is a machine issue.
   164  	// So now that we have a consistent trace, test that (1) parser does
   165  	// not return a logical error in case of broken timestamps
   166  	// and (2) broken timestamps are eventually detected and reported.
   167  	trace.BreakTimestampsForTesting = true
   168  	defer func() {
   169  		trace.BreakTimestampsForTesting = false
   170  	}()
   171  	for i := 0; i < 1e4; i++ {
   172  		_, err := trace.Parse(bytes.NewReader(data), "")
   173  		if err == trace.ErrTimeOrder {
   174  			return
   175  		}
   176  		if err != nil {
   177  			t.Fatalf("failed to parse trace: %v", err)
   178  		}
   179  	}
   180  }
   181  
   182  func TestTraceStress(t *testing.T) {
   183  	if runtime.GOOS == "js" {
   184  		t.Skip("no os.Pipe on js")
   185  	}
   186  	if IsEnabled() {
   187  		t.Skip("skipping because -test.trace is set")
   188  	}
   189  	var wg sync.WaitGroup
   190  	done := make(chan bool)
   191  
   192  	// Create a goroutine blocked before tracing.
   193  	wg.Add(1)
   194  	go func() {
   195  		<-done
   196  		wg.Done()
   197  	}()
   198  
   199  	// Create a goroutine blocked in syscall before tracing.
   200  	rp, wp, err := os.Pipe()
   201  	if err != nil {
   202  		t.Fatalf("failed to create pipe: %v", err)
   203  	}
   204  	defer func() {
   205  		rp.Close()
   206  		wp.Close()
   207  	}()
   208  	wg.Add(1)
   209  	go func() {
   210  		var tmp [1]byte
   211  		rp.Read(tmp[:])
   212  		<-done
   213  		wg.Done()
   214  	}()
   215  	time.Sleep(time.Millisecond) // give the goroutine above time to block
   216  
   217  	buf := new(bytes.Buffer)
   218  	if err := Start(buf); err != nil {
   219  		t.Fatalf("failed to start tracing: %v", err)
   220  	}
   221  
   222  	procs := runtime.GOMAXPROCS(10)
   223  	time.Sleep(50 * time.Millisecond) // test proc stop/start events
   224  
   225  	go func() {
   226  		runtime.LockOSThread()
   227  		for {
   228  			select {
   229  			case <-done:
   230  				return
   231  			default:
   232  				runtime.Gosched()
   233  			}
   234  		}
   235  	}()
   236  
   237  	runtime.GC()
   238  	// Trigger GC from malloc.
   239  	n := int(1e3)
   240  	if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" {
   241  		// Reduce allocation to avoid running out of
   242  		// memory on the builder - see issue/12032.
   243  		n = 512
   244  	}
   245  	for i := 0; i < n; i++ {
   246  		_ = make([]byte, 1<<20)
   247  	}
   248  
   249  	// Create a bunch of busy goroutines to load all Ps.
   250  	for p := 0; p < 10; p++ {
   251  		wg.Add(1)
   252  		go func() {
   253  			// Do something useful.
   254  			tmp := make([]byte, 1<<16)
   255  			for i := range tmp {
   256  				tmp[i]++
   257  			}
   258  			_ = tmp
   259  			<-done
   260  			wg.Done()
   261  		}()
   262  	}
   263  
   264  	// Block in syscall.
   265  	wg.Add(1)
   266  	go func() {
   267  		var tmp [1]byte
   268  		rp.Read(tmp[:])
   269  		<-done
   270  		wg.Done()
   271  	}()
   272  
   273  	// Test timers.
   274  	timerDone := make(chan bool)
   275  	go func() {
   276  		time.Sleep(time.Millisecond)
   277  		timerDone <- true
   278  	}()
   279  	<-timerDone
   280  
   281  	// A bit of network.
   282  	ln, err := net.Listen("tcp", "127.0.0.1:0")
   283  	if err != nil {
   284  		t.Fatalf("listen failed: %v", err)
   285  	}
   286  	defer ln.Close()
   287  	go func() {
   288  		c, err := ln.Accept()
   289  		if err != nil {
   290  			return
   291  		}
   292  		time.Sleep(time.Millisecond)
   293  		var buf [1]byte
   294  		c.Write(buf[:])
   295  		c.Close()
   296  	}()
   297  	c, err := net.Dial("tcp", ln.Addr().String())
   298  	if err != nil {
   299  		t.Fatalf("dial failed: %v", err)
   300  	}
   301  	var tmp [1]byte
   302  	c.Read(tmp[:])
   303  	c.Close()
   304  
   305  	go func() {
   306  		runtime.Gosched()
   307  		select {}
   308  	}()
   309  
   310  	// Unblock helper goroutines and wait them to finish.
   311  	wp.Write(tmp[:])
   312  	wp.Write(tmp[:])
   313  	close(done)
   314  	wg.Wait()
   315  
   316  	runtime.GOMAXPROCS(procs)
   317  
   318  	Stop()
   319  	saveTrace(t, buf, "TestTraceStress")
   320  	trace := buf.Bytes()
   321  	parseTrace(t, buf)
   322  	testBrokenTimestamps(t, trace)
   323  }
   324  
   325  // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
   326  // And concurrently with all that start/stop trace 3 times.
   327  func TestTraceStressStartStop(t *testing.T) {
   328  	if runtime.GOOS == "js" {
   329  		t.Skip("no os.Pipe on js")
   330  	}
   331  	if IsEnabled() {
   332  		t.Skip("skipping because -test.trace is set")
   333  	}
   334  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
   335  	outerDone := make(chan bool)
   336  
   337  	go func() {
   338  		defer func() {
   339  			outerDone <- true
   340  		}()
   341  
   342  		var wg sync.WaitGroup
   343  		done := make(chan bool)
   344  
   345  		wg.Add(1)
   346  		go func() {
   347  			<-done
   348  			wg.Done()
   349  		}()
   350  
   351  		rp, wp, err := os.Pipe()
   352  		if err != nil {
   353  			t.Errorf("failed to create pipe: %v", err)
   354  			return
   355  		}
   356  		defer func() {
   357  			rp.Close()
   358  			wp.Close()
   359  		}()
   360  		wg.Add(1)
   361  		go func() {
   362  			var tmp [1]byte
   363  			rp.Read(tmp[:])
   364  			<-done
   365  			wg.Done()
   366  		}()
   367  		time.Sleep(time.Millisecond)
   368  
   369  		go func() {
   370  			runtime.LockOSThread()
   371  			for {
   372  				select {
   373  				case <-done:
   374  					return
   375  				default:
   376  					runtime.Gosched()
   377  				}
   378  			}
   379  		}()
   380  
   381  		runtime.GC()
   382  		// Trigger GC from malloc.
   383  		n := int(1e3)
   384  		if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" {
   385  			// Reduce allocation to avoid running out of
   386  			// memory on the builder - see issue/12032.
   387  			n = 512
   388  		}
   389  		for i := 0; i < n; i++ {
   390  			_ = make([]byte, 1<<20)
   391  		}
   392  
   393  		// Create a bunch of busy goroutines to load all Ps.
   394  		for p := 0; p < 10; p++ {
   395  			wg.Add(1)
   396  			go func() {
   397  				// Do something useful.
   398  				tmp := make([]byte, 1<<16)
   399  				for i := range tmp {
   400  					tmp[i]++
   401  				}
   402  				_ = tmp
   403  				<-done
   404  				wg.Done()
   405  			}()
   406  		}
   407  
   408  		// Block in syscall.
   409  		wg.Add(1)
   410  		go func() {
   411  			var tmp [1]byte
   412  			rp.Read(tmp[:])
   413  			<-done
   414  			wg.Done()
   415  		}()
   416  
   417  		runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
   418  
   419  		// Test timers.
   420  		timerDone := make(chan bool)
   421  		go func() {
   422  			time.Sleep(time.Millisecond)
   423  			timerDone <- true
   424  		}()
   425  		<-timerDone
   426  
   427  		// A bit of network.
   428  		ln, err := net.Listen("tcp", "127.0.0.1:0")
   429  		if err != nil {
   430  			t.Errorf("listen failed: %v", err)
   431  			return
   432  		}
   433  		defer ln.Close()
   434  		go func() {
   435  			c, err := ln.Accept()
   436  			if err != nil {
   437  				return
   438  			}
   439  			time.Sleep(time.Millisecond)
   440  			var buf [1]byte
   441  			c.Write(buf[:])
   442  			c.Close()
   443  		}()
   444  		c, err := net.Dial("tcp", ln.Addr().String())
   445  		if err != nil {
   446  			t.Errorf("dial failed: %v", err)
   447  			return
   448  		}
   449  		var tmp [1]byte
   450  		c.Read(tmp[:])
   451  		c.Close()
   452  
   453  		go func() {
   454  			runtime.Gosched()
   455  			select {}
   456  		}()
   457  
   458  		// Unblock helper goroutines and wait them to finish.
   459  		wp.Write(tmp[:])
   460  		wp.Write(tmp[:])
   461  		close(done)
   462  		wg.Wait()
   463  	}()
   464  
   465  	for i := 0; i < 3; i++ {
   466  		buf := new(bytes.Buffer)
   467  		if err := Start(buf); err != nil {
   468  			t.Fatalf("failed to start tracing: %v", err)
   469  		}
   470  		time.Sleep(time.Millisecond)
   471  		Stop()
   472  		saveTrace(t, buf, "TestTraceStressStartStop")
   473  		trace := buf.Bytes()
   474  		parseTrace(t, buf)
   475  		testBrokenTimestamps(t, trace)
   476  	}
   477  	<-outerDone
   478  }
   479  
   480  func TestTraceFutileWakeup(t *testing.T) {
   481  	if IsEnabled() {
   482  		t.Skip("skipping because -test.trace is set")
   483  	}
   484  	buf := new(bytes.Buffer)
   485  	if err := Start(buf); err != nil {
   486  		t.Fatalf("failed to start tracing: %v", err)
   487  	}
   488  
   489  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
   490  	c0 := make(chan int, 1)
   491  	c1 := make(chan int, 1)
   492  	c2 := make(chan int, 1)
   493  	const procs = 2
   494  	var done sync.WaitGroup
   495  	done.Add(4 * procs)
   496  	for p := 0; p < procs; p++ {
   497  		const iters = 1e3
   498  		go func() {
   499  			for i := 0; i < iters; i++ {
   500  				runtime.Gosched()
   501  				c0 <- 0
   502  			}
   503  			done.Done()
   504  		}()
   505  		go func() {
   506  			for i := 0; i < iters; i++ {
   507  				runtime.Gosched()
   508  				<-c0
   509  			}
   510  			done.Done()
   511  		}()
   512  		go func() {
   513  			for i := 0; i < iters; i++ {
   514  				runtime.Gosched()
   515  				select {
   516  				case c1 <- 0:
   517  				case c2 <- 0:
   518  				}
   519  			}
   520  			done.Done()
   521  		}()
   522  		go func() {
   523  			for i := 0; i < iters; i++ {
   524  				runtime.Gosched()
   525  				select {
   526  				case <-c1:
   527  				case <-c2:
   528  				}
   529  			}
   530  			done.Done()
   531  		}()
   532  	}
   533  	done.Wait()
   534  
   535  	Stop()
   536  	saveTrace(t, buf, "TestTraceFutileWakeup")
   537  	events, _ := parseTrace(t, buf)
   538  	// Check that (1) trace does not contain EvFutileWakeup events and
   539  	// (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
   540  	// (we call runtime.Gosched between all operations, so these would be futile wakeups).
   541  	gs := make(map[uint64]int)
   542  	for _, ev := range events {
   543  		switch ev.Type {
   544  		case trace.EvFutileWakeup:
   545  			t.Fatalf("found EvFutileWakeup event")
   546  		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
   547  			if gs[ev.G] == 2 {
   548  				t.Fatalf("goroutine %v blocked on %v at %v right after start",
   549  					ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
   550  			}
   551  			if gs[ev.G] == 1 {
   552  				t.Fatalf("goroutine %v blocked on %v at %v while blocked",
   553  					ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
   554  			}
   555  			gs[ev.G] = 1
   556  		case trace.EvGoStart:
   557  			if gs[ev.G] == 1 {
   558  				gs[ev.G] = 2
   559  			}
   560  		default:
   561  			delete(gs, ev.G)
   562  		}
   563  	}
   564  }
   565  
   566  func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
   567  	if !*saveTraces {
   568  		return
   569  	}
   570  	if err := ioutil.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
   571  		t.Errorf("failed to write trace file: %s", err)
   572  	}
   573  }
   574  

View as plain text