Source file src/internal/trace/trace_test.go

     1  // Copyright 2023 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  	"bufio"
     9  	"bytes"
    10  	"fmt"
    11  	"internal/race"
    12  	"internal/testenv"
    13  	"internal/trace"
    14  	"internal/trace/testtrace"
    15  	"internal/trace/version"
    16  	"io"
    17  	"os"
    18  	"path/filepath"
    19  	"runtime"
    20  	"slices"
    21  	"strings"
    22  	"testing"
    23  )
    24  
    25  func TestTraceAnnotations(t *testing.T) {
    26  	testTraceProg(t, "annotations.go", func(t *testing.T, tb, _ []byte, _ bool) {
    27  		type evDesc struct {
    28  			kind trace.EventKind
    29  			task trace.TaskID
    30  			args []string
    31  		}
    32  		want := []evDesc{
    33  			{trace.EventTaskBegin, trace.TaskID(1), []string{"task0"}},
    34  			{trace.EventRegionBegin, trace.TaskID(1), []string{"region0"}},
    35  			{trace.EventRegionBegin, trace.TaskID(1), []string{"region1"}},
    36  			{trace.EventLog, trace.TaskID(1), []string{"key0", "0123456789abcdef"}},
    37  			{trace.EventRegionEnd, trace.TaskID(1), []string{"region1"}},
    38  			{trace.EventRegionEnd, trace.TaskID(1), []string{"region0"}},
    39  			{trace.EventTaskEnd, trace.TaskID(1), []string{"task0"}},
    40  			//  Currently, pre-existing region is not recorded to avoid allocations.
    41  			{trace.EventRegionBegin, trace.BackgroundTask, []string{"post-existing region"}},
    42  		}
    43  		r, err := trace.NewReader(bytes.NewReader(tb))
    44  		if err != nil {
    45  			t.Error(err)
    46  		}
    47  		for {
    48  			ev, err := r.ReadEvent()
    49  			if err == io.EOF {
    50  				break
    51  			}
    52  			if err != nil {
    53  				t.Fatal(err)
    54  			}
    55  			for i, wantEv := range want {
    56  				if wantEv.kind != ev.Kind() {
    57  					continue
    58  				}
    59  				match := false
    60  				switch ev.Kind() {
    61  				case trace.EventTaskBegin, trace.EventTaskEnd:
    62  					task := ev.Task()
    63  					match = task.ID == wantEv.task && task.Type == wantEv.args[0]
    64  				case trace.EventRegionBegin, trace.EventRegionEnd:
    65  					reg := ev.Region()
    66  					match = reg.Task == wantEv.task && reg.Type == wantEv.args[0]
    67  				case trace.EventLog:
    68  					log := ev.Log()
    69  					match = log.Task == wantEv.task && log.Category == wantEv.args[0] && log.Message == wantEv.args[1]
    70  				}
    71  				if match {
    72  					want[i] = want[len(want)-1]
    73  					want = want[:len(want)-1]
    74  					break
    75  				}
    76  			}
    77  		}
    78  		if len(want) != 0 {
    79  			for _, ev := range want {
    80  				t.Errorf("no match for %s TaskID=%d Args=%#v", ev.kind, ev.task, ev.args)
    81  			}
    82  		}
    83  	})
    84  }
    85  
    86  func TestTraceAnnotationsStress(t *testing.T) {
    87  	testTraceProg(t, "annotations-stress.go", nil)
    88  }
    89  
    90  func TestTraceCgoCallback(t *testing.T) {
    91  	testenv.MustHaveCGO(t)
    92  
    93  	switch runtime.GOOS {
    94  	case "plan9", "windows":
    95  		t.Skipf("cgo callback test requires pthreads and is not supported on %s", runtime.GOOS)
    96  	}
    97  	testTraceProg(t, "cgo-callback.go", nil)
    98  }
    99  
   100  func TestTraceCPUProfile(t *testing.T) {
   101  	testTraceProg(t, "cpu-profile.go", func(t *testing.T, tb, stderr []byte, _ bool) {
   102  		// Parse stderr which has a CPU profile summary, if everything went well.
   103  		// (If it didn't, we shouldn't even make it here.)
   104  		scanner := bufio.NewScanner(bytes.NewReader(stderr))
   105  		pprofSamples := 0
   106  		pprofStacks := make(map[string]int)
   107  		for scanner.Scan() {
   108  			var stack string
   109  			var samples int
   110  			_, err := fmt.Sscanf(scanner.Text(), "%s\t%d", &stack, &samples)
   111  			if err != nil {
   112  				t.Fatalf("failed to parse CPU profile summary in stderr: %s\n\tfull:\n%s", scanner.Text(), stderr)
   113  			}
   114  			pprofStacks[stack] = samples
   115  			pprofSamples += samples
   116  		}
   117  		if err := scanner.Err(); err != nil {
   118  			t.Fatalf("failed to parse CPU profile summary in stderr: %v", err)
   119  		}
   120  		if pprofSamples == 0 {
   121  			t.Skip("CPU profile did not include any samples while tracing was active")
   122  		}
   123  
   124  		// Examine the execution tracer's view of the CPU profile samples. Filter it
   125  		// to only include samples from the single test goroutine. Use the goroutine
   126  		// ID that was recorded in the events: that should reflect getg().m.curg,
   127  		// same as the profiler's labels (even when the M is using its g0 stack).
   128  		totalTraceSamples := 0
   129  		traceSamples := 0
   130  		traceStacks := make(map[string]int)
   131  		r, err := trace.NewReader(bytes.NewReader(tb))
   132  		if err != nil {
   133  			t.Error(err)
   134  		}
   135  		var hogRegion *trace.Event
   136  		var hogRegionClosed bool
   137  		for {
   138  			ev, err := r.ReadEvent()
   139  			if err == io.EOF {
   140  				break
   141  			}
   142  			if err != nil {
   143  				t.Fatal(err)
   144  			}
   145  			if ev.Kind() == trace.EventRegionBegin && ev.Region().Type == "cpuHogger" {
   146  				hogRegion = &ev
   147  			}
   148  			if ev.Kind() == trace.EventStackSample {
   149  				totalTraceSamples++
   150  				if hogRegion != nil && ev.Goroutine() == hogRegion.Goroutine() {
   151  					traceSamples++
   152  					var fns []string
   153  					for frame := range ev.Stack().Frames() {
   154  						if frame.Func != "runtime.goexit" {
   155  							fns = append(fns, fmt.Sprintf("%s:%d", frame.Func, frame.Line))
   156  						}
   157  					}
   158  					stack := strings.Join(fns, "|")
   159  					traceStacks[stack]++
   160  				}
   161  			}
   162  			if ev.Kind() == trace.EventRegionEnd && ev.Region().Type == "cpuHogger" {
   163  				hogRegionClosed = true
   164  			}
   165  		}
   166  		if hogRegion == nil {
   167  			t.Fatalf("execution trace did not identify cpuHogger goroutine")
   168  		} else if !hogRegionClosed {
   169  			t.Fatalf("execution trace did not close cpuHogger region")
   170  		}
   171  
   172  		// The execution trace may drop CPU profile samples if the profiling buffer
   173  		// overflows. Based on the size of profBufWordCount, that takes a bit over
   174  		// 1900 CPU samples or 19 thread-seconds at a 100 Hz sample rate. If we've
   175  		// hit that case, then we definitely have at least one full buffer's worth
   176  		// of CPU samples, so we'll call that success.
   177  		overflowed := totalTraceSamples >= 1900
   178  		if traceSamples < pprofSamples {
   179  			t.Logf("execution trace did not include all CPU profile samples; %d in profile, %d in trace", pprofSamples, traceSamples)
   180  			if !overflowed {
   181  				t.Fail()
   182  			}
   183  		}
   184  
   185  		for stack, traceSamples := range traceStacks {
   186  			pprofSamples := pprofStacks[stack]
   187  			delete(pprofStacks, stack)
   188  			if traceSamples < pprofSamples {
   189  				t.Logf("execution trace did not include all CPU profile samples for stack %q; %d in profile, %d in trace",
   190  					stack, pprofSamples, traceSamples)
   191  				if !overflowed {
   192  					t.Fail()
   193  				}
   194  			}
   195  		}
   196  		for stack, pprofSamples := range pprofStacks {
   197  			t.Logf("CPU profile included %d samples at stack %q not present in execution trace", pprofSamples, stack)
   198  			if !overflowed {
   199  				t.Fail()
   200  			}
   201  		}
   202  
   203  		if t.Failed() {
   204  			t.Logf("execution trace CPU samples:")
   205  			for stack, samples := range traceStacks {
   206  				t.Logf("%d: %q", samples, stack)
   207  			}
   208  			t.Logf("CPU profile:\n%s", stderr)
   209  		}
   210  	})
   211  }
   212  
   213  func TestTraceFutileWakeup(t *testing.T) {
   214  	testTraceProg(t, "futile-wakeup.go", func(t *testing.T, tb, _ []byte, _ bool) {
   215  		// Check to make sure that no goroutine in the "special" trace region
   216  		// ends up blocking, unblocking, then immediately blocking again.
   217  		//
   218  		// The goroutines are careful to call runtime.Gosched in between blocking,
   219  		// so there should never be a clean block/unblock on the goroutine unless
   220  		// the runtime was generating extraneous events.
   221  		const (
   222  			entered = iota
   223  			blocked
   224  			runnable
   225  			running
   226  		)
   227  		gs := make(map[trace.GoID]int)
   228  		seenSpecialGoroutines := false
   229  		r, err := trace.NewReader(bytes.NewReader(tb))
   230  		if err != nil {
   231  			t.Error(err)
   232  		}
   233  		for {
   234  			ev, err := r.ReadEvent()
   235  			if err == io.EOF {
   236  				break
   237  			}
   238  			if err != nil {
   239  				t.Fatal(err)
   240  			}
   241  			// Only track goroutines in the special region we control, so runtime
   242  			// goroutines don't interfere (it's totally valid in traces for a
   243  			// goroutine to block, run, and block again; that's not what we care about).
   244  			if ev.Kind() == trace.EventRegionBegin && ev.Region().Type == "special" {
   245  				seenSpecialGoroutines = true
   246  				gs[ev.Goroutine()] = entered
   247  			}
   248  			if ev.Kind() == trace.EventRegionEnd && ev.Region().Type == "special" {
   249  				delete(gs, ev.Goroutine())
   250  			}
   251  			// Track state transitions for goroutines we care about.
   252  			//
   253  			// The goroutines we care about will advance through the state machine
   254  			// of entered -> blocked -> runnable -> running. If in the running state
   255  			// we block, then we have a futile wakeup. Because of the runtime.Gosched
   256  			// on these specially marked goroutines, we should end up back in runnable
   257  			// first. If at any point we go to a different state, switch back to entered
   258  			// and wait for the next time the goroutine blocks.
   259  			if ev.Kind() != trace.EventStateTransition {
   260  				continue
   261  			}
   262  			st := ev.StateTransition()
   263  			if st.Resource.Kind != trace.ResourceGoroutine {
   264  				continue
   265  			}
   266  			id := st.Resource.Goroutine()
   267  			state, ok := gs[id]
   268  			if !ok {
   269  				continue
   270  			}
   271  			_, new := st.Goroutine()
   272  			switch state {
   273  			case entered:
   274  				if new == trace.GoWaiting {
   275  					state = blocked
   276  				} else {
   277  					state = entered
   278  				}
   279  			case blocked:
   280  				if new == trace.GoRunnable {
   281  					state = runnable
   282  				} else {
   283  					state = entered
   284  				}
   285  			case runnable:
   286  				if new == trace.GoRunning {
   287  					state = running
   288  				} else {
   289  					state = entered
   290  				}
   291  			case running:
   292  				if new == trace.GoWaiting {
   293  					t.Fatalf("found futile wakeup on goroutine %d", id)
   294  				} else {
   295  					state = entered
   296  				}
   297  			}
   298  			gs[id] = state
   299  		}
   300  		if !seenSpecialGoroutines {
   301  			t.Fatal("did not see a goroutine in a the region 'special'")
   302  		}
   303  	})
   304  }
   305  
   306  func TestTraceGCStress(t *testing.T) {
   307  	testTraceProg(t, "gc-stress.go", nil)
   308  }
   309  
   310  func TestTraceGOMAXPROCS(t *testing.T) {
   311  	testTraceProg(t, "gomaxprocs.go", nil)
   312  }
   313  
   314  func TestTraceStacks(t *testing.T) {
   315  	testTraceProg(t, "stacks.go", func(t *testing.T, tb, _ []byte, stress bool) {
   316  		type frame struct {
   317  			fn   string
   318  			line int
   319  		}
   320  		type evDesc struct {
   321  			kind   trace.EventKind
   322  			match  string
   323  			frames []frame
   324  		}
   325  		// mainLine is the line number of `func main()` in testprog/stacks.go.
   326  		const mainLine = 21
   327  		want := []evDesc{
   328  			{trace.EventStateTransition, "Goroutine Running->Runnable", []frame{
   329  				{"runtime.Gosched", 0},
   330  				{"main.main", mainLine + 87},
   331  			}},
   332  			{trace.EventStateTransition, "Goroutine NotExist->Runnable", []frame{
   333  				{"main.main", mainLine + 11},
   334  			}},
   335  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   336  				{"runtime.block", 0},
   337  				{"main.main.func1", 0},
   338  			}},
   339  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   340  				{"runtime.chansend1", 0},
   341  				{"main.main.func2", 0},
   342  			}},
   343  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   344  				{"runtime.chanrecv1", 0},
   345  				{"main.main.func3", 0},
   346  			}},
   347  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   348  				{"runtime.chanrecv1", 0},
   349  				{"main.main.func4", 0},
   350  			}},
   351  			{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
   352  				{"runtime.chansend1", 0},
   353  				{"main.main", mainLine + 89},
   354  			}},
   355  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   356  				{"runtime.chansend1", 0},
   357  				{"main.main.func5", 0},
   358  			}},
   359  			{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
   360  				{"runtime.chanrecv1", 0},
   361  				{"main.main", mainLine + 90},
   362  			}},
   363  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   364  				{"runtime.selectgo", 0},
   365  				{"main.main.func6", 0},
   366  			}},
   367  			{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
   368  				{"runtime.selectgo", 0},
   369  				{"main.main", mainLine + 91},
   370  			}},
   371  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   372  				{"sync.(*Mutex).Lock", 0},
   373  				{"main.main.func7", 0},
   374  			}},
   375  			{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
   376  				{"sync.(*Mutex).Unlock", 0},
   377  				{"main.main", 0},
   378  			}},
   379  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   380  				{"sync.(*WaitGroup).Wait", 0},
   381  				{"main.main.func8", 0},
   382  			}},
   383  			{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
   384  				{"sync.(*WaitGroup).Add", 0},
   385  				{"sync.(*WaitGroup).Done", 0},
   386  				{"main.main", mainLine + 96},
   387  			}},
   388  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   389  				{"sync.(*Cond).Wait", 0},
   390  				{"main.main.func9", 0},
   391  			}},
   392  			{trace.EventStateTransition, "Goroutine Waiting->Runnable", []frame{
   393  				{"sync.(*Cond).Signal", 0},
   394  				{"main.main", 0},
   395  			}},
   396  			{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   397  				{"time.Sleep", 0},
   398  				{"main.main", 0},
   399  			}},
   400  			{trace.EventMetric, "/sched/gomaxprocs:threads", []frame{
   401  				{"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
   402  				{"runtime.startTheWorldGC", 0},
   403  				{"runtime.GOMAXPROCS", 0},
   404  				{"main.main", 0},
   405  			}},
   406  			{trace.EventStateTransition, "Goroutine Running->Runnable", []frame{
   407  				{"main.syncPreemptPoint", 0},
   408  				{"main.main.func12", 0},
   409  			}},
   410  		}
   411  		if !stress {
   412  			// Only check for this stack if !stress because traceAdvance alone could
   413  			// allocate enough memory to trigger a GC if called frequently enough.
   414  			// This might cause the runtime.GC call we're trying to match against to
   415  			// coalesce with an active GC triggered this by traceAdvance. In that case
   416  			// we won't have an EventRangeBegin event that matches the stace trace we're
   417  			// looking for, since runtime.GC will not have triggered the GC.
   418  			gcEv := evDesc{trace.EventRangeBegin, "GC concurrent mark phase", []frame{
   419  				{"runtime.GC", 0},
   420  				{"main.main", 0},
   421  			}}
   422  			want = append(want, gcEv)
   423  		}
   424  		if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
   425  			want = append(want, []evDesc{
   426  				{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   427  					{"internal/poll.(*FD).Accept", 0},
   428  					{"net.(*netFD).accept", 0},
   429  					{"net.(*TCPListener).accept", 0},
   430  					{"net.(*TCPListener).Accept", 0},
   431  					{"main.main.func10", 0},
   432  				}},
   433  				{trace.EventStateTransition, "Goroutine Running->Syscall", []frame{
   434  					{"syscall.read", 0},
   435  					{"syscall.Read", 0},
   436  					{"internal/poll.ignoringEINTRIO", 0},
   437  					{"internal/poll.(*FD).Read", 0},
   438  					{"os.(*File).read", 0},
   439  					{"os.(*File).Read", 0},
   440  					{"main.main.func11", 0},
   441  				}},
   442  			}...)
   443  		}
   444  		stackMatches := func(stk trace.Stack, frames []frame) bool {
   445  			for i, f := range slices.Collect(stk.Frames()) {
   446  				if f.Func != frames[i].fn {
   447  					return false
   448  				}
   449  				if line := uint64(frames[i].line); line != 0 && line != f.Line {
   450  					return false
   451  				}
   452  			}
   453  			return true
   454  		}
   455  		r, err := trace.NewReader(bytes.NewReader(tb))
   456  		if err != nil {
   457  			t.Error(err)
   458  		}
   459  		for {
   460  			ev, err := r.ReadEvent()
   461  			if err == io.EOF {
   462  				break
   463  			}
   464  			if err != nil {
   465  				t.Fatal(err)
   466  			}
   467  			for i, wantEv := range want {
   468  				if wantEv.kind != ev.Kind() {
   469  					continue
   470  				}
   471  				match := false
   472  				switch ev.Kind() {
   473  				case trace.EventStateTransition:
   474  					st := ev.StateTransition()
   475  					str := ""
   476  					switch st.Resource.Kind {
   477  					case trace.ResourceGoroutine:
   478  						old, new := st.Goroutine()
   479  						str = fmt.Sprintf("%s %s->%s", st.Resource.Kind, old, new)
   480  					}
   481  					match = str == wantEv.match
   482  				case trace.EventRangeBegin:
   483  					rng := ev.Range()
   484  					match = rng.Name == wantEv.match
   485  				case trace.EventMetric:
   486  					metric := ev.Metric()
   487  					match = metric.Name == wantEv.match
   488  				}
   489  				match = match && stackMatches(ev.Stack(), wantEv.frames)
   490  				if match {
   491  					want[i] = want[len(want)-1]
   492  					want = want[:len(want)-1]
   493  					break
   494  				}
   495  			}
   496  		}
   497  		if len(want) != 0 {
   498  			for _, ev := range want {
   499  				t.Errorf("no match for %s Match=%s Stack=%#v", ev.kind, ev.match, ev.frames)
   500  			}
   501  		}
   502  	})
   503  }
   504  
   505  func TestTraceStress(t *testing.T) {
   506  	switch runtime.GOOS {
   507  	case "js", "wasip1":
   508  		t.Skip("no os.Pipe on " + runtime.GOOS)
   509  	}
   510  	testTraceProg(t, "stress.go", checkReaderDeterminism)
   511  }
   512  
   513  func TestTraceStressStartStop(t *testing.T) {
   514  	switch runtime.GOOS {
   515  	case "js", "wasip1":
   516  		t.Skip("no os.Pipe on " + runtime.GOOS)
   517  	}
   518  	testTraceProg(t, "stress-start-stop.go", nil)
   519  }
   520  
   521  func TestTraceManyStartStop(t *testing.T) {
   522  	testTraceProg(t, "many-start-stop.go", nil)
   523  }
   524  
   525  func TestTraceWaitOnPipe(t *testing.T) {
   526  	switch runtime.GOOS {
   527  	case "dragonfly", "freebsd", "linux", "netbsd", "openbsd", "solaris":
   528  		testTraceProg(t, "wait-on-pipe.go", nil)
   529  		return
   530  	}
   531  	t.Skip("no applicable syscall.Pipe on " + runtime.GOOS)
   532  }
   533  
   534  func TestTraceIterPull(t *testing.T) {
   535  	testTraceProg(t, "iter-pull.go", nil)
   536  }
   537  
   538  func checkReaderDeterminism(t *testing.T, tb, _ []byte, _ bool) {
   539  	events := func() []trace.Event {
   540  		var evs []trace.Event
   541  
   542  		r, err := trace.NewReader(bytes.NewReader(tb))
   543  		if err != nil {
   544  			t.Error(err)
   545  		}
   546  		for {
   547  			ev, err := r.ReadEvent()
   548  			if err == io.EOF {
   549  				break
   550  			}
   551  			if err != nil {
   552  				t.Fatal(err)
   553  			}
   554  			evs = append(evs, ev)
   555  		}
   556  
   557  		return evs
   558  	}
   559  
   560  	evs1 := events()
   561  	evs2 := events()
   562  
   563  	if l1, l2 := len(evs1), len(evs2); l1 != l2 {
   564  		t.Fatalf("re-reading trace gives different event count (%d != %d)", l1, l2)
   565  	}
   566  	for i, ev1 := range evs1 {
   567  		ev2 := evs2[i]
   568  		if s1, s2 := ev1.String(), ev2.String(); s1 != s2 {
   569  			t.Errorf("re-reading trace gives different event %d:\n%s\n%s\n", i, s1, s2)
   570  			break
   571  		}
   572  	}
   573  }
   574  
   575  func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace, stderr []byte, stress bool)) {
   576  	testenv.MustHaveGoRun(t)
   577  
   578  	// Check if we're on a builder.
   579  	onBuilder := testenv.Builder() != ""
   580  	onOldBuilder := !strings.Contains(testenv.Builder(), "gotip") && !strings.Contains(testenv.Builder(), "go1")
   581  
   582  	if progName == "cgo-callback.go" && onBuilder && !onOldBuilder &&
   583  		runtime.GOOS == "freebsd" && runtime.GOARCH == "amd64" && race.Enabled {
   584  		t.Skip("test fails on freebsd-amd64-race in LUCI; see go.dev/issue/71556")
   585  	}
   586  
   587  	testPath := filepath.Join("./testdata/testprog", progName)
   588  	testName := progName
   589  	runTest := func(t *testing.T, stress bool, extraGODEBUG string) {
   590  		// Build the program.
   591  		binFile, err := os.CreateTemp("", progName)
   592  		if err != nil {
   593  			t.Fatalf("failed to create temporary output file: %v", err)
   594  		}
   595  		bin := binFile.Name()
   596  		binFile.Close()
   597  		t.Cleanup(func() {
   598  			os.Remove(bin)
   599  		})
   600  		buildCmd := testenv.CommandContext(t, t.Context(), testenv.GoToolPath(t), "build", "-o", bin)
   601  		if race.Enabled {
   602  			buildCmd.Args = append(buildCmd.Args, "-race")
   603  		}
   604  		buildCmd.Args = append(buildCmd.Args, testPath)
   605  		buildCmd.Env = append(os.Environ(), "GOEXPERIMENT=rangefunc")
   606  		buildOutput, err := buildCmd.CombinedOutput()
   607  		if err != nil {
   608  			t.Fatalf("failed to build %s: %v: output:\n%s", testPath, err, buildOutput)
   609  		}
   610  
   611  		// Run the program and capture the trace, which is always written to stdout.
   612  		cmd := testenv.CommandContext(t, t.Context(), bin)
   613  
   614  		// Add a stack ownership check. This is cheap enough for testing.
   615  		godebug := "tracecheckstackownership=1"
   616  		if stress {
   617  			// Advance a generation constantly to stress the tracer.
   618  			godebug += ",traceadvanceperiod=0"
   619  		}
   620  		if extraGODEBUG != "" {
   621  			// Add extra GODEBUG flags.
   622  			godebug += "," + extraGODEBUG
   623  		}
   624  		cmd.Env = append(cmd.Env, "GODEBUG="+godebug)
   625  		if _, ok := os.LookupEnv("GOTRACEBACK"); !ok {
   626  			// Unless overriden, set GOTRACEBACK=crash.
   627  			cmd.Env = append(cmd.Env, "GOTRACEBACK=crash")
   628  		}
   629  
   630  		// Capture stdout and stderr.
   631  		//
   632  		// The protocol for these programs is that stdout contains the trace data
   633  		// and stderr is an expectation in string format.
   634  		var traceBuf, errBuf bytes.Buffer
   635  		cmd.Stdout = &traceBuf
   636  		cmd.Stderr = &errBuf
   637  		// Run the program.
   638  		if err := cmd.Run(); err != nil {
   639  			if errBuf.Len() != 0 {
   640  				t.Logf("stderr: %s", string(errBuf.Bytes()))
   641  			}
   642  			t.Fatal(err)
   643  		}
   644  		tb := traceBuf.Bytes()
   645  
   646  		// Test the trace and the parser.
   647  		v := testtrace.NewValidator()
   648  		v.GoVersion = version.Current
   649  		if runtime.GOOS == "windows" && stress {
   650  			// Under stress mode we're constantly advancing trace generations.
   651  			// Windows' clock granularity is too coarse to guarantee monotonic
   652  			// timestamps for monotonic and wall clock time in this case, so
   653  			// skip the checks.
   654  			v.SkipClockSnapshotChecks()
   655  		}
   656  		testReader(t, bytes.NewReader(tb), v, testtrace.ExpectSuccess())
   657  
   658  		// Run some extra validation.
   659  		if !t.Failed() && extra != nil {
   660  			extra(t, tb, errBuf.Bytes(), stress)
   661  		}
   662  
   663  		// Dump some more information on failure.
   664  		if t.Failed() && onBuilder {
   665  			// Dump directly to the test log on the builder, since this
   666  			// data is critical for debugging and this is the only way
   667  			// we can currently make sure it's retained.
   668  			t.Log("found bad trace; dumping to test log...")
   669  			s := dumpTraceToText(t, tb)
   670  			if onOldBuilder && len(s) > 1<<20+512<<10 {
   671  				// The old build infrastructure truncates logs at ~2 MiB.
   672  				// Let's assume we're the only failure and give ourselves
   673  				// up to 1.5 MiB to dump the trace.
   674  				//
   675  				// TODO(mknyszek): Remove this when we've migrated off of
   676  				// the old infrastructure.
   677  				t.Logf("text trace too large to dump (%d bytes)", len(s))
   678  			} else {
   679  				t.Log(s)
   680  			}
   681  		} else if t.Failed() || *dumpTraces {
   682  			// We asked to dump the trace or failed. Write the trace to a file.
   683  			t.Logf("wrote trace to file: %s", dumpTraceToFile(t, testName, stress, tb))
   684  		}
   685  	}
   686  	t.Run("Default", func(t *testing.T) {
   687  		runTest(t, false, "")
   688  	})
   689  	t.Run("Stress", func(t *testing.T) {
   690  		if testing.Short() {
   691  			t.Skip("skipping trace stress tests in short mode")
   692  		}
   693  		runTest(t, true, "")
   694  	})
   695  	t.Run("AllocFree", func(t *testing.T) {
   696  		if testing.Short() {
   697  			t.Skip("skipping trace alloc/free tests in short mode")
   698  		}
   699  		runTest(t, false, "traceallocfree=1")
   700  	})
   701  }
   702  

View as plain text