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