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, _ string) {
    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, _ string) {
   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, _ string) {
   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, godebug string) {
   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  		}
   407  		asyncPreemptOff := strings.Contains(godebug, "asyncpreemptoff=1")
   408  		if asyncPreemptOff {
   409  			// Only check for syncPreemptPoint if asynchronous preemption is disabled.
   410  			// Otherwise, the syncPreemptPoint goroutine might be exclusively async
   411  			// preempted, causing this test to flake.
   412  			syncPreemptEv := evDesc{trace.EventStateTransition, "Goroutine Running->Runnable", []frame{
   413  				{"main.syncPreemptPoint", 0},
   414  				{"main.main.func12", 0},
   415  			}}
   416  			want = append(want, syncPreemptEv)
   417  		}
   418  		stress := strings.Contains(godebug, "traceadvanceperiod=0")
   419  		if !stress {
   420  			// Only check for this stack if !stress because traceAdvance alone could
   421  			// allocate enough memory to trigger a GC if called frequently enough.
   422  			// This might cause the runtime.GC call we're trying to match against to
   423  			// coalesce with an active GC triggered this by traceAdvance. In that case
   424  			// we won't have an EventRangeBegin event that matches the stace trace we're
   425  			// looking for, since runtime.GC will not have triggered the GC.
   426  			gcEv := evDesc{trace.EventRangeBegin, "GC concurrent mark phase", []frame{
   427  				{"runtime.GC", 0},
   428  				{"main.main", 0},
   429  			}}
   430  			want = append(want, gcEv)
   431  		}
   432  		if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
   433  			want = append(want, []evDesc{
   434  				{trace.EventStateTransition, "Goroutine Running->Waiting", []frame{
   435  					{"internal/poll.(*FD).Accept", 0},
   436  					{"net.(*netFD).accept", 0},
   437  					{"net.(*TCPListener).accept", 0},
   438  					{"net.(*TCPListener).Accept", 0},
   439  					{"main.main.func10", 0},
   440  				}},
   441  				{trace.EventStateTransition, "Goroutine Running->Syscall", []frame{
   442  					{"syscall.read", 0},
   443  					{"syscall.Read", 0},
   444  					{"internal/poll.ignoringEINTRIO", 0},
   445  					{"internal/poll.(*FD).Read", 0},
   446  					{"os.(*File).read", 0},
   447  					{"os.(*File).Read", 0},
   448  					{"main.main.func11", 0},
   449  				}},
   450  			}...)
   451  		}
   452  		stackMatches := func(stk trace.Stack, frames []frame) bool {
   453  			for i, f := range slices.Collect(stk.Frames()) {
   454  				if f.Func != frames[i].fn {
   455  					return false
   456  				}
   457  				if line := uint64(frames[i].line); line != 0 && line != f.Line {
   458  					return false
   459  				}
   460  			}
   461  			return true
   462  		}
   463  		r, err := trace.NewReader(bytes.NewReader(tb))
   464  		if err != nil {
   465  			t.Error(err)
   466  		}
   467  		for {
   468  			ev, err := r.ReadEvent()
   469  			if err == io.EOF {
   470  				break
   471  			}
   472  			if err != nil {
   473  				t.Fatal(err)
   474  			}
   475  			for i, wantEv := range want {
   476  				if wantEv.kind != ev.Kind() {
   477  					continue
   478  				}
   479  				match := false
   480  				switch ev.Kind() {
   481  				case trace.EventStateTransition:
   482  					st := ev.StateTransition()
   483  					str := ""
   484  					switch st.Resource.Kind {
   485  					case trace.ResourceGoroutine:
   486  						old, new := st.Goroutine()
   487  						str = fmt.Sprintf("%s %s->%s", st.Resource.Kind, old, new)
   488  					}
   489  					match = str == wantEv.match
   490  				case trace.EventRangeBegin:
   491  					rng := ev.Range()
   492  					match = rng.Name == wantEv.match
   493  				case trace.EventMetric:
   494  					metric := ev.Metric()
   495  					match = metric.Name == wantEv.match
   496  				}
   497  				match = match && stackMatches(ev.Stack(), wantEv.frames)
   498  				if match {
   499  					want[i] = want[len(want)-1]
   500  					want = want[:len(want)-1]
   501  					break
   502  				}
   503  			}
   504  		}
   505  		if len(want) != 0 {
   506  			for _, ev := range want {
   507  				t.Errorf("no match for %s Match=%s Stack=%#v", ev.kind, ev.match, ev.frames)
   508  			}
   509  		}
   510  	})
   511  }
   512  
   513  func TestTraceStress(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.go", checkReaderDeterminism)
   519  }
   520  
   521  func TestTraceStressStartStop(t *testing.T) {
   522  	switch runtime.GOOS {
   523  	case "js", "wasip1":
   524  		t.Skip("no os.Pipe on " + runtime.GOOS)
   525  	}
   526  	testTraceProg(t, "stress-start-stop.go", nil)
   527  }
   528  
   529  func TestTraceManyStartStop(t *testing.T) {
   530  	testTraceProg(t, "many-start-stop.go", nil)
   531  }
   532  
   533  func TestTraceWaitOnPipe(t *testing.T) {
   534  	switch runtime.GOOS {
   535  	case "dragonfly", "freebsd", "linux", "netbsd", "openbsd", "solaris":
   536  		testTraceProg(t, "wait-on-pipe.go", nil)
   537  		return
   538  	}
   539  	t.Skip("no applicable syscall.Pipe on " + runtime.GOOS)
   540  }
   541  
   542  func TestTraceIterPull(t *testing.T) {
   543  	testTraceProg(t, "iter-pull.go", nil)
   544  }
   545  
   546  func checkReaderDeterminism(t *testing.T, tb, _ []byte, _ string) {
   547  	events := func() []trace.Event {
   548  		var evs []trace.Event
   549  
   550  		r, err := trace.NewReader(bytes.NewReader(tb))
   551  		if err != nil {
   552  			t.Error(err)
   553  		}
   554  		for {
   555  			ev, err := r.ReadEvent()
   556  			if err == io.EOF {
   557  				break
   558  			}
   559  			if err != nil {
   560  				t.Fatal(err)
   561  			}
   562  			evs = append(evs, ev)
   563  		}
   564  
   565  		return evs
   566  	}
   567  
   568  	evs1 := events()
   569  	evs2 := events()
   570  
   571  	if l1, l2 := len(evs1), len(evs2); l1 != l2 {
   572  		t.Fatalf("re-reading trace gives different event count (%d != %d)", l1, l2)
   573  	}
   574  	for i, ev1 := range evs1 {
   575  		ev2 := evs2[i]
   576  		if s1, s2 := ev1.String(), ev2.String(); s1 != s2 {
   577  			t.Errorf("re-reading trace gives different event %d:\n%s\n%s\n", i, s1, s2)
   578  			break
   579  		}
   580  	}
   581  }
   582  
   583  func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace, stderr []byte, godebug string)) {
   584  	testenv.MustHaveGoRun(t)
   585  
   586  	// Check if we're on a builder.
   587  	onBuilder := testenv.Builder() != ""
   588  	onOldBuilder := !strings.Contains(testenv.Builder(), "gotip") && !strings.Contains(testenv.Builder(), "go1")
   589  
   590  	if progName == "cgo-callback.go" && onBuilder && !onOldBuilder &&
   591  		runtime.GOOS == "freebsd" && runtime.GOARCH == "amd64" && race.Enabled {
   592  		t.Skip("test fails on freebsd-amd64-race in LUCI; see go.dev/issue/71556")
   593  	}
   594  
   595  	testPath := filepath.Join("./testdata/testprog", progName)
   596  	testName := progName
   597  	runTest := func(t *testing.T, stress bool, extraGODEBUG string) {
   598  		// Build the program.
   599  		binFile, err := os.CreateTemp("", progName)
   600  		if err != nil {
   601  			t.Fatalf("failed to create temporary output file: %v", err)
   602  		}
   603  		bin := binFile.Name()
   604  		binFile.Close()
   605  		t.Cleanup(func() {
   606  			os.Remove(bin)
   607  		})
   608  		buildCmd := testenv.CommandContext(t, t.Context(), testenv.GoToolPath(t), "build", "-o", bin)
   609  		if race.Enabled {
   610  			buildCmd.Args = append(buildCmd.Args, "-race")
   611  		}
   612  		buildCmd.Args = append(buildCmd.Args, testPath)
   613  		buildCmd.Env = append(os.Environ(), "GOEXPERIMENT=rangefunc")
   614  		buildOutput, err := buildCmd.CombinedOutput()
   615  		if err != nil {
   616  			t.Fatalf("failed to build %s: %v: output:\n%s", testPath, err, buildOutput)
   617  		}
   618  
   619  		// Run the program and capture the trace, which is always written to stdout.
   620  		cmd := testenv.CommandContext(t, t.Context(), bin)
   621  
   622  		// Add a stack ownership check. This is cheap enough for testing.
   623  		godebug := "tracecheckstackownership=1"
   624  		if stress {
   625  			// Advance a generation constantly to stress the tracer.
   626  			godebug += ",traceadvanceperiod=0"
   627  		}
   628  		if extraGODEBUG != "" {
   629  			// Add extra GODEBUG flags.
   630  			godebug += "," + extraGODEBUG
   631  		}
   632  		cmd.Env = append(cmd.Env, "GODEBUG="+godebug)
   633  		if _, ok := os.LookupEnv("GOTRACEBACK"); !ok {
   634  			// Unless overriden, set GOTRACEBACK=crash.
   635  			cmd.Env = append(cmd.Env, "GOTRACEBACK=crash")
   636  		}
   637  
   638  		// Capture stdout and stderr.
   639  		//
   640  		// The protocol for these programs is that stdout contains the trace data
   641  		// and stderr is an expectation in string format.
   642  		var traceBuf, errBuf bytes.Buffer
   643  		cmd.Stdout = &traceBuf
   644  		cmd.Stderr = &errBuf
   645  		// Run the program.
   646  		if err := cmd.Run(); err != nil {
   647  			if errBuf.Len() != 0 {
   648  				t.Logf("stderr: %s", string(errBuf.Bytes()))
   649  			}
   650  			t.Fatal(err)
   651  		}
   652  		tb := traceBuf.Bytes()
   653  
   654  		// Test the trace and the parser.
   655  		v := testtrace.NewValidator()
   656  		v.GoVersion = version.Current
   657  		if runtime.GOOS == "windows" && stress {
   658  			// Under stress mode we're constantly advancing trace generations.
   659  			// Windows' clock granularity is too coarse to guarantee monotonic
   660  			// timestamps for monotonic and wall clock time in this case, so
   661  			// skip the checks.
   662  			v.SkipClockSnapshotChecks()
   663  		}
   664  		testReader(t, bytes.NewReader(tb), v, testtrace.ExpectSuccess())
   665  
   666  		// Run some extra validation.
   667  		if !t.Failed() && extra != nil {
   668  			extra(t, tb, errBuf.Bytes(), godebug)
   669  		}
   670  
   671  		// Dump some more information on failure.
   672  		if t.Failed() && onBuilder {
   673  			// Dump directly to the test log on the builder, since this
   674  			// data is critical for debugging and this is the only way
   675  			// we can currently make sure it's retained.
   676  			t.Log("found bad trace; dumping to test log...")
   677  			s := dumpTraceToText(t, tb)
   678  			if onOldBuilder && len(s) > 1<<20+512<<10 {
   679  				// The old build infrastructure truncates logs at ~2 MiB.
   680  				// Let's assume we're the only failure and give ourselves
   681  				// up to 1.5 MiB to dump the trace.
   682  				//
   683  				// TODO(mknyszek): Remove this when we've migrated off of
   684  				// the old infrastructure.
   685  				t.Logf("text trace too large to dump (%d bytes)", len(s))
   686  			} else {
   687  				t.Log(s)
   688  			}
   689  		} else if t.Failed() || *dumpTraces {
   690  			// We asked to dump the trace or failed. Write the trace to a file.
   691  			t.Logf("wrote trace to file: %s", dumpTraceToFile(t, testName, stress, tb))
   692  		}
   693  	}
   694  	t.Run("Default", func(t *testing.T) {
   695  		runTest(t, false, "")
   696  	})
   697  	t.Run("AsyncPreemptOff", func(t *testing.T) {
   698  		runTest(t, false, "asyncpreemptoff=1")
   699  	})
   700  	t.Run("Stress", func(t *testing.T) {
   701  		if testing.Short() {
   702  			t.Skip("skipping trace stress tests in short mode")
   703  		}
   704  		runTest(t, true, "")
   705  	})
   706  	t.Run("AllocFree", func(t *testing.T) {
   707  		if testing.Short() {
   708  			t.Skip("skipping trace alloc/free tests in short mode")
   709  		}
   710  		runTest(t, false, "traceallocfree=1")
   711  	})
   712  }
   713  

View as plain text