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  			if runtime.GOOS == "darwin" {
   452  				want[len(want)-1].frames = append([]frame{{"syscall.syscall", 0}}, want[len(want)-1].frames...)
   453  			}
   454  		}
   455  		stackMatches := func(stk trace.Stack, frames []frame) bool {
   456  			for i, f := range slices.Collect(stk.Frames()) {
   457  				if f.Func != frames[i].fn {
   458  					return false
   459  				}
   460  				if line := uint64(frames[i].line); line != 0 && line != f.Line {
   461  					return false
   462  				}
   463  			}
   464  			return true
   465  		}
   466  		r, err := trace.NewReader(bytes.NewReader(tb))
   467  		if err != nil {
   468  			t.Error(err)
   469  		}
   470  		for {
   471  			ev, err := r.ReadEvent()
   472  			if err == io.EOF {
   473  				break
   474  			}
   475  			if err != nil {
   476  				t.Fatal(err)
   477  			}
   478  			for i, wantEv := range want {
   479  				if wantEv.kind != ev.Kind() {
   480  					continue
   481  				}
   482  				match := false
   483  				switch ev.Kind() {
   484  				case trace.EventStateTransition:
   485  					st := ev.StateTransition()
   486  					str := ""
   487  					switch st.Resource.Kind {
   488  					case trace.ResourceGoroutine:
   489  						old, new := st.Goroutine()
   490  						str = fmt.Sprintf("%s %s->%s", st.Resource.Kind, old, new)
   491  					}
   492  					match = str == wantEv.match
   493  				case trace.EventRangeBegin:
   494  					rng := ev.Range()
   495  					match = rng.Name == wantEv.match
   496  				case trace.EventMetric:
   497  					metric := ev.Metric()
   498  					match = metric.Name == wantEv.match
   499  				}
   500  				match = match && stackMatches(ev.Stack(), wantEv.frames)
   501  				if match {
   502  					want[i] = want[len(want)-1]
   503  					want = want[:len(want)-1]
   504  					break
   505  				}
   506  			}
   507  		}
   508  		if len(want) != 0 {
   509  			for _, ev := range want {
   510  				t.Errorf("no match for %s Match=%s Stack=%#v", ev.kind, ev.match, ev.frames)
   511  			}
   512  		}
   513  	})
   514  }
   515  
   516  func TestTraceStress(t *testing.T) {
   517  	switch runtime.GOOS {
   518  	case "js", "wasip1":
   519  		t.Skip("no os.Pipe on " + runtime.GOOS)
   520  	}
   521  	testTraceProg(t, "stress.go", checkReaderDeterminism)
   522  }
   523  
   524  func TestTraceStressStartStop(t *testing.T) {
   525  	switch runtime.GOOS {
   526  	case "js", "wasip1":
   527  		t.Skip("no os.Pipe on " + runtime.GOOS)
   528  	}
   529  	testTraceProg(t, "stress-start-stop.go", nil)
   530  }
   531  
   532  func TestTraceManyStartStop(t *testing.T) {
   533  	testTraceProg(t, "many-start-stop.go", nil)
   534  }
   535  
   536  func TestTraceWaitOnPipe(t *testing.T) {
   537  	switch runtime.GOOS {
   538  	case "dragonfly", "freebsd", "linux", "netbsd", "openbsd", "solaris":
   539  		testTraceProg(t, "wait-on-pipe.go", nil)
   540  		return
   541  	}
   542  	t.Skip("no applicable syscall.Pipe on " + runtime.GOOS)
   543  }
   544  
   545  func TestTraceIterPull(t *testing.T) {
   546  	testTraceProg(t, "iter-pull.go", nil)
   547  }
   548  
   549  func checkReaderDeterminism(t *testing.T, tb, _ []byte, _ string) {
   550  	events := func() []trace.Event {
   551  		var evs []trace.Event
   552  
   553  		r, err := trace.NewReader(bytes.NewReader(tb))
   554  		if err != nil {
   555  			t.Error(err)
   556  		}
   557  		for {
   558  			ev, err := r.ReadEvent()
   559  			if err == io.EOF {
   560  				break
   561  			}
   562  			if err != nil {
   563  				t.Fatal(err)
   564  			}
   565  			evs = append(evs, ev)
   566  		}
   567  
   568  		return evs
   569  	}
   570  
   571  	evs1 := events()
   572  	evs2 := events()
   573  
   574  	if l1, l2 := len(evs1), len(evs2); l1 != l2 {
   575  		t.Fatalf("re-reading trace gives different event count (%d != %d)", l1, l2)
   576  	}
   577  	for i, ev1 := range evs1 {
   578  		ev2 := evs2[i]
   579  		if s1, s2 := ev1.String(), ev2.String(); s1 != s2 {
   580  			t.Errorf("re-reading trace gives different event %d:\n%s\n%s\n", i, s1, s2)
   581  			break
   582  		}
   583  	}
   584  }
   585  
   586  func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace, stderr []byte, godebug string)) {
   587  	testenv.MustHaveGoRun(t)
   588  
   589  	// Check if we're on a builder.
   590  	onBuilder := testenv.Builder() != ""
   591  	onOldBuilder := !strings.Contains(testenv.Builder(), "gotip") && !strings.Contains(testenv.Builder(), "go1")
   592  
   593  	if progName == "cgo-callback.go" && onBuilder && !onOldBuilder &&
   594  		runtime.GOOS == "freebsd" && runtime.GOARCH == "amd64" && race.Enabled {
   595  		t.Skip("test fails on freebsd-amd64-race in LUCI; see go.dev/issue/71556")
   596  	}
   597  
   598  	testPath := filepath.Join("./testdata/testprog", progName)
   599  	testName := progName
   600  	runTest := func(t *testing.T, stress bool, extraGODEBUG string) {
   601  		// Build the program.
   602  		binFile, err := os.CreateTemp("", progName)
   603  		if err != nil {
   604  			t.Fatalf("failed to create temporary output file: %v", err)
   605  		}
   606  		bin := binFile.Name()
   607  		binFile.Close()
   608  		t.Cleanup(func() {
   609  			os.Remove(bin)
   610  		})
   611  		buildCmd := testenv.CommandContext(t, t.Context(), testenv.GoToolPath(t), "build", "-o", bin)
   612  		if race.Enabled {
   613  			buildCmd.Args = append(buildCmd.Args, "-race")
   614  		}
   615  		buildCmd.Args = append(buildCmd.Args, testPath)
   616  		buildOutput, err := buildCmd.CombinedOutput()
   617  		if err != nil {
   618  			t.Fatalf("failed to build %s: %v: output:\n%s", testPath, err, buildOutput)
   619  		}
   620  
   621  		// Run the program and capture the trace, which is always written to stdout.
   622  		cmd := testenv.CommandContext(t, t.Context(), bin)
   623  
   624  		// Add a stack ownership check. This is cheap enough for testing.
   625  		godebug := "tracecheckstackownership=1"
   626  		if stress {
   627  			// Advance a generation constantly to stress the tracer.
   628  			godebug += ",traceadvanceperiod=0"
   629  		}
   630  		if extraGODEBUG != "" {
   631  			// Add extra GODEBUG flags.
   632  			godebug += "," + extraGODEBUG
   633  		}
   634  		cmd.Env = append(cmd.Env, "GODEBUG="+godebug)
   635  		if _, ok := os.LookupEnv("GOTRACEBACK"); !ok {
   636  			// Unless overriden, set GOTRACEBACK=crash.
   637  			cmd.Env = append(cmd.Env, "GOTRACEBACK=crash")
   638  		}
   639  
   640  		// Capture stdout and stderr.
   641  		//
   642  		// The protocol for these programs is that stdout contains the trace data
   643  		// and stderr is an expectation in string format.
   644  		var traceBuf, errBuf bytes.Buffer
   645  		cmd.Stdout = &traceBuf
   646  		cmd.Stderr = &errBuf
   647  		// Run the program.
   648  		if err := cmd.Run(); err != nil {
   649  			if errBuf.Len() != 0 {
   650  				t.Logf("stderr: %s", string(errBuf.Bytes()))
   651  			}
   652  			t.Fatal(err)
   653  		}
   654  		tb := traceBuf.Bytes()
   655  
   656  		// Test the trace and the parser.
   657  		v := testtrace.NewValidator()
   658  		v.GoVersion = version.Current
   659  		if runtime.GOOS == "windows" && stress {
   660  			// Under stress mode we're constantly advancing trace generations.
   661  			// Windows' clock granularity is too coarse to guarantee monotonic
   662  			// timestamps for monotonic and wall clock time in this case, so
   663  			// skip the checks.
   664  			v.SkipClockSnapshotChecks()
   665  		}
   666  		testReader(t, bytes.NewReader(tb), v, testtrace.ExpectSuccess())
   667  
   668  		// Run some extra validation.
   669  		if !t.Failed() && extra != nil {
   670  			extra(t, tb, errBuf.Bytes(), godebug)
   671  		}
   672  
   673  		// Dump some more information on failure.
   674  		if t.Failed() || *dumpTraces {
   675  			suffix := func(stress bool) string {
   676  				if stress {
   677  					return "stress"
   678  				}
   679  				return "default"
   680  			}
   681  			testtrace.Dump(t, fmt.Sprintf("%s.%s", testName, suffix(stress)), tb, *dumpTraces)
   682  		}
   683  	}
   684  	t.Run("Default", func(t *testing.T) {
   685  		runTest(t, false, "")
   686  	})
   687  	t.Run("AsyncPreemptOff", func(t *testing.T) {
   688  		if testing.Short() && runtime.NumCPU() < 2 {
   689  			t.Skip("skipping trace async preempt off tests in short mode")
   690  		}
   691  		runTest(t, false, "asyncpreemptoff=1")
   692  	})
   693  	t.Run("Stress", func(t *testing.T) {
   694  		if testing.Short() {
   695  			t.Skip("skipping trace stress tests in short mode")
   696  		}
   697  		runTest(t, true, "")
   698  	})
   699  	t.Run("AllocFree", func(t *testing.T) {
   700  		if testing.Short() {
   701  			t.Skip("skipping trace alloc/free tests in short mode")
   702  		}
   703  		runTest(t, false, "traceallocfree=1")
   704  	})
   705  }
   706  

View as plain text