Source file src/runtime/pprof/pprof_test.go

     1  // Copyright 2011 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  //go:build !js
     6  
     7  package pprof
     8  
     9  import (
    10  	"bytes"
    11  	"context"
    12  	"fmt"
    13  	"internal/abi"
    14  	"internal/profile"
    15  	"internal/runtime/pprof/label"
    16  	"internal/syscall/unix"
    17  	"internal/testenv"
    18  	"io"
    19  	"iter"
    20  	"math"
    21  	"math/big"
    22  	"os"
    23  	"regexp"
    24  	"runtime"
    25  	"runtime/debug"
    26  	"slices"
    27  	"strconv"
    28  	"strings"
    29  	"sync"
    30  	"sync/atomic"
    31  	"testing"
    32  	"time"
    33  	_ "unsafe"
    34  )
    35  
    36  func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
    37  	// We only need to get one 100 Hz clock tick, so we've got
    38  	// a large safety buffer.
    39  	// But do at least 500 iterations (which should take about 100ms),
    40  	// otherwise TestCPUProfileMultithreaded can fail if only one
    41  	// thread is scheduled during the testing period.
    42  	t0 := time.Now()
    43  	accum := *y
    44  	for i := 0; i < 500 || time.Since(t0) < dur; i++ {
    45  		accum = f(accum)
    46  	}
    47  	*y = accum
    48  }
    49  
    50  var (
    51  	salt1 = 0
    52  	salt2 = 0
    53  )
    54  
    55  // The actual CPU hogging function.
    56  // Must not call other functions nor access heap/globals in the loop,
    57  // otherwise under race detector the samples will be in the race runtime.
    58  func cpuHog1(x int) int {
    59  	return cpuHog0(x, 1e5)
    60  }
    61  
    62  func cpuHog0(x, n int) int {
    63  	foo := x
    64  	for i := 0; i < n; i++ {
    65  		if foo > 0 {
    66  			foo *= foo
    67  		} else {
    68  			foo *= foo + 1
    69  		}
    70  	}
    71  	return foo
    72  }
    73  
    74  func cpuHog2(x int) int {
    75  	foo := x
    76  	for i := 0; i < 1e5; i++ {
    77  		if foo > 0 {
    78  			foo *= foo
    79  		} else {
    80  			foo *= foo + 2
    81  		}
    82  	}
    83  	return foo
    84  }
    85  
    86  // Return a list of functions that we don't want to ever appear in CPU
    87  // profiles. For gccgo, that list includes the sigprof handler itself.
    88  func avoidFunctions() []string {
    89  	if runtime.Compiler == "gccgo" {
    90  		return []string{"runtime.sigprof"}
    91  	}
    92  	return nil
    93  }
    94  
    95  func TestCPUProfile(t *testing.T) {
    96  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
    97  	testCPUProfile(t, matches, func(dur time.Duration) {
    98  		cpuHogger(cpuHog1, &salt1, dur)
    99  	})
   100  }
   101  
   102  func TestCPUProfileMultithreaded(t *testing.T) {
   103  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
   104  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions())
   105  	testCPUProfile(t, matches, func(dur time.Duration) {
   106  		c := make(chan int)
   107  		go func() {
   108  			cpuHogger(cpuHog1, &salt1, dur)
   109  			c <- 1
   110  		}()
   111  		cpuHogger(cpuHog2, &salt2, dur)
   112  		<-c
   113  	})
   114  }
   115  
   116  func TestCPUProfileMultithreadMagnitude(t *testing.T) {
   117  	if runtime.GOOS != "linux" {
   118  		t.Skip("issue 35057 is only confirmed on Linux")
   119  	}
   120  
   121  	defer func() {
   122  		if t.Failed() {
   123  			t.Logf("Failure of this test may indicate that your system suffers from a known Linux kernel bug fixed on newer kernels. See https://golang.org/issue/49065.")
   124  		}
   125  	}()
   126  
   127  	// Disable on affected builders to avoid flakiness, but otherwise keep
   128  	// it enabled to potentially warn users that they are on a broken
   129  	// kernel.
   130  	if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") {
   131  		// Linux [5.9,5.16) has a kernel bug that can break CPU timers on newly
   132  		// created threads, breaking our CPU accounting.
   133  		if unix.KernelVersionGE(5, 9) && !unix.KernelVersionGE(5, 16) {
   134  			testenv.SkipFlaky(t, 49065)
   135  		}
   136  	}
   137  
   138  	// Run a workload in a single goroutine, then run copies of the same
   139  	// workload in several goroutines. For both the serial and parallel cases,
   140  	// the CPU time the process measures with its own profiler should match the
   141  	// total CPU usage that the OS reports.
   142  	//
   143  	// We could also check that increases in parallelism (GOMAXPROCS) lead to a
   144  	// linear increase in the CPU usage reported by both the OS and the
   145  	// profiler, but without a guarantee of exclusive access to CPU resources
   146  	// that is likely to be a flaky test.
   147  
   148  	// Require the smaller value to be within 10%, or 40% in short mode.
   149  	maxDiff := 0.10
   150  	if testing.Short() {
   151  		maxDiff = 0.40
   152  	}
   153  
   154  	compare := func(a, b time.Duration, maxDiff float64) error {
   155  		if a <= 0 || b <= 0 {
   156  			return fmt.Errorf("Expected both time reports to be positive")
   157  		}
   158  
   159  		if a < b {
   160  			a, b = b, a
   161  		}
   162  
   163  		diff := float64(a-b) / float64(a)
   164  		if diff > maxDiff {
   165  			return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100)
   166  		}
   167  
   168  		return nil
   169  	}
   170  
   171  	for _, tc := range []struct {
   172  		name    string
   173  		workers int
   174  	}{
   175  		{
   176  			name:    "serial",
   177  			workers: 1,
   178  		},
   179  		{
   180  			name:    "parallel",
   181  			workers: runtime.GOMAXPROCS(0),
   182  		},
   183  	} {
   184  		// check that the OS's perspective matches what the Go runtime measures.
   185  		t.Run(tc.name, func(t *testing.T) {
   186  			t.Logf("Running with %d workers", tc.workers)
   187  
   188  			var userTime, systemTime time.Duration
   189  			matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
   190  			acceptProfile := func(t *testing.T, p *profile.Profile) bool {
   191  				if !matches(t, p) {
   192  					return false
   193  				}
   194  
   195  				ok := true
   196  				for i, unit := range []string{"count", "nanoseconds"} {
   197  					if have, want := p.SampleType[i].Unit, unit; have != want {
   198  						t.Logf("pN SampleType[%d]; %q != %q", i, have, want)
   199  						ok = false
   200  					}
   201  				}
   202  
   203  				// cpuHog1 called below is the primary source of CPU
   204  				// load, but there may be some background work by the
   205  				// runtime. Since the OS rusage measurement will
   206  				// include all work done by the process, also compare
   207  				// against all samples in our profile.
   208  				var value time.Duration
   209  				for _, sample := range p.Sample {
   210  					value += time.Duration(sample.Value[1]) * time.Nanosecond
   211  				}
   212  
   213  				totalTime := userTime + systemTime
   214  				t.Logf("compare %s user + %s system = %s vs %s", userTime, systemTime, totalTime, value)
   215  				if err := compare(totalTime, value, maxDiff); err != nil {
   216  					t.Logf("compare got %v want nil", err)
   217  					ok = false
   218  				}
   219  
   220  				return ok
   221  			}
   222  
   223  			testCPUProfile(t, acceptProfile, func(dur time.Duration) {
   224  				userTime, systemTime = diffCPUTime(t, func() {
   225  					var wg sync.WaitGroup
   226  					var once sync.Once
   227  					for i := 0; i < tc.workers; i++ {
   228  						wg.Add(1)
   229  						go func() {
   230  							defer wg.Done()
   231  							var salt = 0
   232  							cpuHogger(cpuHog1, &salt, dur)
   233  							once.Do(func() { salt1 = salt })
   234  						}()
   235  					}
   236  					wg.Wait()
   237  				})
   238  			})
   239  		})
   240  	}
   241  }
   242  
   243  // containsInlinedCall reports whether the function body for the function f is
   244  // known to contain an inlined function call within the first maxBytes bytes.
   245  func containsInlinedCall(f any, maxBytes int) bool {
   246  	_, found := findInlinedCall(f, maxBytes)
   247  	return found
   248  }
   249  
   250  // findInlinedCall returns the PC of an inlined function call within
   251  // the function body for the function f if any.
   252  func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) {
   253  	fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f)))
   254  	if fFunc == nil || fFunc.Entry() == 0 {
   255  		panic("failed to locate function entry")
   256  	}
   257  
   258  	for offset := 0; offset < maxBytes; offset++ {
   259  		innerPC := fFunc.Entry() + uintptr(offset)
   260  		inner := runtime.FuncForPC(innerPC)
   261  		if inner == nil {
   262  			// No function known for this PC value.
   263  			// It might simply be misaligned, so keep searching.
   264  			continue
   265  		}
   266  		if inner.Entry() != fFunc.Entry() {
   267  			// Scanned past f and didn't find any inlined functions.
   268  			break
   269  		}
   270  		if inner.Name() != fFunc.Name() {
   271  			// This PC has f as its entry-point, but is not f. Therefore, it must be a
   272  			// function inlined into f.
   273  			return uint64(innerPC), true
   274  		}
   275  	}
   276  
   277  	return 0, false
   278  }
   279  
   280  func TestCPUProfileInlining(t *testing.T) {
   281  	if !containsInlinedCall(inlinedCaller, 4<<10) {
   282  		t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.")
   283  	}
   284  
   285  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions())
   286  	p := testCPUProfile(t, matches, func(dur time.Duration) {
   287  		cpuHogger(inlinedCaller, &salt1, dur)
   288  	})
   289  
   290  	// Check if inlined function locations are encoded correctly. The inlinedCalee and inlinedCaller should be in one location.
   291  	for _, loc := range p.Location {
   292  		hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false
   293  		for _, line := range loc.Line {
   294  			if line.Function.Name == "runtime/pprof.inlinedCallee" {
   295  				hasInlinedCallee = true
   296  			}
   297  			if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" {
   298  				hasInlinedCallerAfterInlinedCallee = true
   299  			}
   300  		}
   301  		if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee {
   302  			t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p)
   303  		}
   304  	}
   305  }
   306  
   307  func inlinedCaller(x int) int {
   308  	x = inlinedCallee(x, 1e5)
   309  	return x
   310  }
   311  
   312  func inlinedCallee(x, n int) int {
   313  	return cpuHog0(x, n)
   314  }
   315  
   316  //go:noinline
   317  func dumpCallers(pcs []uintptr) {
   318  	if pcs == nil {
   319  		return
   320  	}
   321  
   322  	skip := 2 // Callers and dumpCallers
   323  	runtime.Callers(skip, pcs)
   324  }
   325  
   326  //go:noinline
   327  func inlinedCallerDump(pcs []uintptr) {
   328  	inlinedCalleeDump(pcs)
   329  }
   330  
   331  func inlinedCalleeDump(pcs []uintptr) {
   332  	dumpCallers(pcs)
   333  }
   334  
   335  type inlineWrapperInterface interface {
   336  	dump(stack []uintptr)
   337  }
   338  
   339  type inlineWrapper struct {
   340  }
   341  
   342  func (h inlineWrapper) dump(pcs []uintptr) {
   343  	dumpCallers(pcs)
   344  }
   345  
   346  func inlinedWrapperCallerDump(pcs []uintptr) {
   347  	var h inlineWrapperInterface
   348  
   349  	// Take the address of h, such that h.dump() call (below)
   350  	// does not get devirtualized by the compiler.
   351  	_ = &h
   352  
   353  	h = &inlineWrapper{}
   354  	h.dump(pcs)
   355  }
   356  
   357  func TestCPUProfileRecursion(t *testing.T) {
   358  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions())
   359  	p := testCPUProfile(t, matches, func(dur time.Duration) {
   360  		cpuHogger(recursionCaller, &salt1, dur)
   361  	})
   362  
   363  	// check the Location encoding was not confused by recursive calls.
   364  	for i, loc := range p.Location {
   365  		recursionFunc := 0
   366  		for _, line := range loc.Line {
   367  			if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" {
   368  				recursionFunc++
   369  			}
   370  		}
   371  		if recursionFunc > 1 {
   372  			t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p)
   373  		}
   374  	}
   375  }
   376  
   377  func recursionCaller(x int) int {
   378  	y := recursionCallee(3, x)
   379  	return y
   380  }
   381  
   382  func recursionCallee(n, x int) int {
   383  	if n == 0 {
   384  		return 1
   385  	}
   386  	y := inlinedCallee(x, 1e4)
   387  	return y * recursionCallee(n-1, x)
   388  }
   389  
   390  func recursionChainTop(x int, pcs []uintptr) {
   391  	if x < 0 {
   392  		return
   393  	}
   394  	recursionChainMiddle(x, pcs)
   395  }
   396  
   397  func recursionChainMiddle(x int, pcs []uintptr) {
   398  	recursionChainBottom(x, pcs)
   399  }
   400  
   401  func recursionChainBottom(x int, pcs []uintptr) {
   402  	// This will be called each time, we only care about the last. We
   403  	// can't make this conditional or this function won't be inlined.
   404  	dumpCallers(pcs)
   405  
   406  	recursionChainTop(x-1, pcs)
   407  }
   408  
   409  func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile {
   410  	p, err := profile.Parse(bytes.NewReader(valBytes))
   411  	if err != nil {
   412  		t.Fatal(err)
   413  	}
   414  	for _, sample := range p.Sample {
   415  		count := uintptr(sample.Value[0])
   416  		f(count, sample.Location, sample.Label)
   417  	}
   418  	return p
   419  }
   420  
   421  // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need,
   422  // as interpreted by matches, and returns the parsed profile.
   423  func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile {
   424  	switch runtime.GOOS {
   425  	case "darwin":
   426  		out, err := testenv.Command(t, "uname", "-a").CombinedOutput()
   427  		if err != nil {
   428  			t.Fatal(err)
   429  		}
   430  		vers := string(out)
   431  		t.Logf("uname -a: %v", vers)
   432  	case "plan9":
   433  		t.Skip("skipping on plan9")
   434  	case "wasip1":
   435  		t.Skip("skipping on wasip1")
   436  	}
   437  
   438  	broken := testenv.CPUProfilingBroken()
   439  
   440  	deadline, ok := t.Deadline()
   441  	if broken || !ok {
   442  		if broken && testing.Short() {
   443  			// If it's expected to be broken, no point waiting around.
   444  			deadline = time.Now().Add(1 * time.Second)
   445  		} else {
   446  			deadline = time.Now().Add(10 * time.Second)
   447  		}
   448  	}
   449  
   450  	// If we're running a long test, start with a long duration
   451  	// for tests that try to make sure something *doesn't* happen.
   452  	duration := 5 * time.Second
   453  	if testing.Short() {
   454  		duration = 100 * time.Millisecond
   455  	}
   456  
   457  	// Profiling tests are inherently flaky, especially on a
   458  	// loaded system, such as when this test is running with
   459  	// several others under go test std. If a test fails in a way
   460  	// that could mean it just didn't run long enough, try with a
   461  	// longer duration.
   462  	for {
   463  		var prof bytes.Buffer
   464  		if err := StartCPUProfile(&prof); err != nil {
   465  			t.Fatal(err)
   466  		}
   467  		f(duration)
   468  		StopCPUProfile()
   469  
   470  		if p, ok := profileOk(t, matches, &prof, duration); ok {
   471  			return p
   472  		}
   473  
   474  		duration *= 2
   475  		if time.Until(deadline) < duration {
   476  			break
   477  		}
   478  		t.Logf("retrying with %s duration", duration)
   479  	}
   480  
   481  	if broken {
   482  		t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH)
   483  	}
   484  
   485  	// Ignore the failure if the tests are running in a QEMU-based emulator,
   486  	// QEMU is not perfect at emulating everything.
   487  	// IN_QEMU environmental variable is set by some of the Go builders.
   488  	// IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
   489  	if os.Getenv("IN_QEMU") == "1" {
   490  		t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
   491  	}
   492  	t.FailNow()
   493  	return nil
   494  }
   495  
   496  var diffCPUTimeImpl func(f func()) (user, system time.Duration)
   497  
   498  func diffCPUTime(t *testing.T, f func()) (user, system time.Duration) {
   499  	if fn := diffCPUTimeImpl; fn != nil {
   500  		return fn(f)
   501  	}
   502  	t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH)
   503  	return 0, 0
   504  }
   505  
   506  // stackContains matches if a function named spec appears anywhere in the stack trace.
   507  func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   508  	for _, loc := range stk {
   509  		for _, line := range loc.Line {
   510  			if strings.Contains(line.Function.Name, spec) {
   511  				return true
   512  			}
   513  		}
   514  	}
   515  	return false
   516  }
   517  
   518  type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool
   519  
   520  func profileOk(t *testing.T, matches profileMatchFunc, prof *bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) {
   521  	ok = true
   522  
   523  	var samples uintptr
   524  	var buf strings.Builder
   525  	p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) {
   526  		fmt.Fprintf(&buf, "%d:", count)
   527  		fprintStack(&buf, stk)
   528  		fmt.Fprintf(&buf, " labels: %v\n", labels)
   529  		samples += count
   530  		fmt.Fprintf(&buf, "\n")
   531  	})
   532  	t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String())
   533  
   534  	if samples < 10 && runtime.GOOS == "windows" {
   535  		// On some windows machines we end up with
   536  		// not enough samples due to coarse timer
   537  		// resolution. Let it go.
   538  		t.Log("too few samples on Windows (golang.org/issue/10842)")
   539  		return p, false
   540  	}
   541  
   542  	// Check that we got a reasonable number of samples.
   543  	// We used to always require at least ideal/4 samples,
   544  	// but that is too hard to guarantee on a loaded system.
   545  	// Now we accept 10 or more samples, which we take to be
   546  	// enough to show that at least some profiling is occurring.
   547  	if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) {
   548  		t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
   549  		ok = false
   550  	}
   551  
   552  	if matches != nil && !matches(t, p) {
   553  		ok = false
   554  	}
   555  
   556  	return p, ok
   557  }
   558  
   559  type profileMatchFunc func(*testing.T, *profile.Profile) bool
   560  
   561  func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc {
   562  	return func(t *testing.T, p *profile.Profile) (ok bool) {
   563  		ok = true
   564  
   565  		// Check that profile is well formed, contains 'need', and does not contain
   566  		// anything from 'avoid'.
   567  		have := make([]uintptr, len(need))
   568  		avoidSamples := make([]uintptr, len(avoid))
   569  
   570  		for _, sample := range p.Sample {
   571  			count := uintptr(sample.Value[0])
   572  			for i, spec := range need {
   573  				if matches(spec, count, sample.Location, sample.Label) {
   574  					have[i] += count
   575  				}
   576  			}
   577  			for i, name := range avoid {
   578  				for _, loc := range sample.Location {
   579  					for _, line := range loc.Line {
   580  						if strings.Contains(line.Function.Name, name) {
   581  							avoidSamples[i] += count
   582  						}
   583  					}
   584  				}
   585  			}
   586  		}
   587  
   588  		for i, name := range avoid {
   589  			bad := avoidSamples[i]
   590  			if bad != 0 {
   591  				t.Logf("found %d samples in avoid-function %s\n", bad, name)
   592  				ok = false
   593  			}
   594  		}
   595  
   596  		if len(need) == 0 {
   597  			return
   598  		}
   599  
   600  		var total uintptr
   601  		for i, name := range need {
   602  			total += have[i]
   603  			t.Logf("found %d samples in expected function %s\n", have[i], name)
   604  		}
   605  		if total == 0 {
   606  			t.Logf("no samples in expected functions")
   607  			ok = false
   608  		}
   609  
   610  		// We'd like to check a reasonable minimum, like
   611  		// total / len(have) / smallconstant, but this test is
   612  		// pretty flaky (see bug 7095).  So we'll just test to
   613  		// make sure we got at least one sample.
   614  		min := uintptr(1)
   615  		for i, name := range need {
   616  			if have[i] < min {
   617  				t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
   618  				ok = false
   619  			}
   620  		}
   621  		return
   622  	}
   623  }
   624  
   625  // Fork can hang if preempted with signals frequently enough (see issue 5517).
   626  // Ensure that we do not do this.
   627  func TestCPUProfileWithFork(t *testing.T) {
   628  	testenv.MustHaveExec(t)
   629  
   630  	exe, err := os.Executable()
   631  	if err != nil {
   632  		t.Fatal(err)
   633  	}
   634  
   635  	heap := 1 << 30
   636  	if runtime.GOOS == "android" {
   637  		// Use smaller size for Android to avoid crash.
   638  		heap = 100 << 20
   639  	}
   640  	if testing.Short() {
   641  		heap = 100 << 20
   642  	}
   643  	// This makes fork slower.
   644  	garbage := make([]byte, heap)
   645  	// Need to touch the slice, otherwise it won't be paged in.
   646  	done := make(chan bool)
   647  	go func() {
   648  		for i := range garbage {
   649  			garbage[i] = 42
   650  		}
   651  		done <- true
   652  	}()
   653  	<-done
   654  
   655  	var prof bytes.Buffer
   656  	if err := StartCPUProfile(&prof); err != nil {
   657  		t.Fatal(err)
   658  	}
   659  	defer StopCPUProfile()
   660  
   661  	for i := 0; i < 10; i++ {
   662  		testenv.Command(t, exe, "-h").CombinedOutput()
   663  	}
   664  }
   665  
   666  func TestCPUProfileRateErrorLog(t *testing.T) {
   667  	testenv.MustHaveExec(t)
   668  
   669  	switch os.Getenv("GO_TEST_CPU_PROFILE_RATE_SCENARIO") {
   670  	case "DoubleSet":
   671  		runtime.SetCPUProfileRate(100)
   672  		runtime.SetCPUProfileRate(500) // should log error: profile already active
   673  		runtime.SetCPUProfileRate(0)
   674  		return
   675  	case "SetThenStart":
   676  		runtime.SetCPUProfileRate(500)
   677  		if err := StartCPUProfile(io.Discard); err != nil {
   678  			fmt.Fprintf(os.Stderr, "StartCPUProfile: unexpected error: %v\n", err)
   679  		}
   680  		StopCPUProfile()
   681  		return
   682  	}
   683  
   684  	for _, tc := range []struct {
   685  		scenario string
   686  		want     string
   687  	}{
   688  		{"DoubleSet", "runtime: cannot set cpu profile rate until previous profile has finished."},
   689  		{"SetThenStart", ""},
   690  	} {
   691  		t.Run(tc.scenario, func(t *testing.T) {
   692  			cmd := testenv.CleanCmdEnv(testenv.Command(t, testenv.Executable(t),
   693  				"-test.run="+"^"+t.Name()+"$"))
   694  			cmd.Env = append(cmd.Env, "GO_TEST_CPU_PROFILE_RATE_SCENARIO="+tc.scenario)
   695  			var stderr bytes.Buffer
   696  			cmd.Stderr = &stderr
   697  			cmd.Run()
   698  			if got := strings.TrimSpace(stderr.String()); got != tc.want {
   699  				t.Errorf("got error output %q, wanted %q", got, tc.want)
   700  			}
   701  		})
   702  	}
   703  }
   704  
   705  // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
   706  // If it did, it would see inconsistent state and would either record an incorrect stack
   707  // or crash because the stack was malformed.
   708  func TestGoroutineSwitch(t *testing.T) {
   709  	if runtime.Compiler == "gccgo" {
   710  		t.Skip("not applicable for gccgo")
   711  	}
   712  	// How much to try. These defaults take about 1 seconds
   713  	// on a 2012 MacBook Pro. The ones in short mode take
   714  	// about 0.1 seconds.
   715  	tries := 10
   716  	count := 1000000
   717  	if testing.Short() {
   718  		tries = 1
   719  	}
   720  	for try := 0; try < tries; try++ {
   721  		var prof bytes.Buffer
   722  		if err := StartCPUProfile(&prof); err != nil {
   723  			t.Fatal(err)
   724  		}
   725  		for i := 0; i < count; i++ {
   726  			runtime.Gosched()
   727  		}
   728  		StopCPUProfile()
   729  
   730  		// Read profile to look for entries for gogo with an attempt at a traceback.
   731  		// "runtime.gogo" is OK, because that's the part of the context switch
   732  		// before the actual switch begins. But we should not see "gogo",
   733  		// aka "gogo<>(SB)", which does the actual switch and is marked SPWRITE.
   734  		parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) {
   735  			// An entry with two frames with 'System' in its top frame
   736  			// exists to record a PC without a traceback. Those are okay.
   737  			if len(stk) == 2 {
   738  				name := stk[1].Line[0].Function.Name
   739  				if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" {
   740  					return
   741  				}
   742  			}
   743  
   744  			// An entry with just one frame is OK too:
   745  			// it knew to stop at gogo.
   746  			if len(stk) == 1 {
   747  				return
   748  			}
   749  
   750  			// Otherwise, should not see gogo.
   751  			// The place we'd see it would be the inner most frame.
   752  			name := stk[0].Line[0].Function.Name
   753  			if name == "gogo" {
   754  				var buf strings.Builder
   755  				fprintStack(&buf, stk)
   756  				t.Fatalf("found profile entry for gogo:\n%s", buf.String())
   757  			}
   758  		})
   759  	}
   760  }
   761  
   762  func fprintStack(w io.Writer, stk []*profile.Location) {
   763  	if len(stk) == 0 {
   764  		fmt.Fprintf(w, " (stack empty)")
   765  	}
   766  	for _, loc := range stk {
   767  		fmt.Fprintf(w, " %#x", loc.Address)
   768  		fmt.Fprintf(w, " (")
   769  		for i, line := range loc.Line {
   770  			if i > 0 {
   771  				fmt.Fprintf(w, " ")
   772  			}
   773  			fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line)
   774  		}
   775  		fmt.Fprintf(w, ")")
   776  	}
   777  }
   778  
   779  // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
   780  func TestMathBigDivide(t *testing.T) {
   781  	testCPUProfile(t, nil, func(duration time.Duration) {
   782  		t := time.After(duration)
   783  		pi := new(big.Int)
   784  		for {
   785  			for i := 0; i < 100; i++ {
   786  				n := big.NewInt(2646693125139304345)
   787  				d := big.NewInt(842468587426513207)
   788  				pi.Div(n, d)
   789  			}
   790  			select {
   791  			case <-t:
   792  				return
   793  			default:
   794  			}
   795  		}
   796  	})
   797  }
   798  
   799  // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace.
   800  func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   801  	for _, f := range strings.Split(spec, ",") {
   802  		if !stackContains(f, count, stk, labels) {
   803  			return false
   804  		}
   805  	}
   806  	return true
   807  }
   808  
   809  func TestMorestack(t *testing.T) {
   810  	matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions())
   811  	testCPUProfile(t, matches, func(duration time.Duration) {
   812  		t := time.After(duration)
   813  		c := make(chan bool)
   814  		for {
   815  			go func() {
   816  				growstack1()
   817  				// NOTE(vsaioc): This goroutine may leak without this select.
   818  				select {
   819  				case c <- true:
   820  				case <-time.After(duration):
   821  				}
   822  			}()
   823  			select {
   824  			case <-t:
   825  				return
   826  			case <-c:
   827  			}
   828  		}
   829  	})
   830  }
   831  
   832  //go:noinline
   833  func growstack1() {
   834  	growstack(10)
   835  }
   836  
   837  //go:noinline
   838  func growstack(n int) {
   839  	var buf [8 << 18]byte
   840  	use(buf)
   841  	if n > 0 {
   842  		growstack(n - 1)
   843  	}
   844  }
   845  
   846  //go:noinline
   847  func use(x [8 << 18]byte) {}
   848  
   849  func TestBlockProfile(t *testing.T) {
   850  	type TestCase struct {
   851  		name string
   852  		f    func(*testing.T)
   853  		stk  []string
   854  		re   string
   855  	}
   856  	tests := [...]TestCase{
   857  		{
   858  			name: "chan recv",
   859  			f:    blockChanRecv,
   860  			stk: []string{
   861  				"runtime.chanrecv1",
   862  				"runtime/pprof.blockChanRecv",
   863  				"runtime/pprof.TestBlockProfile",
   864  			},
   865  			re: `
   866  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   867  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*runtime/chan.go:[0-9]+
   868  #	0x[0-9a-f]+	runtime/pprof\.blockChanRecv\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   869  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   870  `},
   871  		{
   872  			name: "chan send",
   873  			f:    blockChanSend,
   874  			stk: []string{
   875  				"runtime.chansend1",
   876  				"runtime/pprof.blockChanSend",
   877  				"runtime/pprof.TestBlockProfile",
   878  			},
   879  			re: `
   880  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   881  #	0x[0-9a-f]+	runtime\.chansend1\+0x[0-9a-f]+	.*runtime/chan.go:[0-9]+
   882  #	0x[0-9a-f]+	runtime/pprof\.blockChanSend\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   883  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   884  `},
   885  		{
   886  			name: "chan close",
   887  			f:    blockChanClose,
   888  			stk: []string{
   889  				"runtime.chanrecv1",
   890  				"runtime/pprof.blockChanClose",
   891  				"runtime/pprof.TestBlockProfile",
   892  			},
   893  			re: `
   894  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   895  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*runtime/chan.go:[0-9]+
   896  #	0x[0-9a-f]+	runtime/pprof\.blockChanClose\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   897  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   898  `},
   899  		{
   900  			name: "select recv async",
   901  			f:    blockSelectRecvAsync,
   902  			stk: []string{
   903  				"runtime.selectgo",
   904  				"runtime/pprof.blockSelectRecvAsync",
   905  				"runtime/pprof.TestBlockProfile",
   906  			},
   907  			re: `
   908  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   909  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*runtime/select.go:[0-9]+
   910  #	0x[0-9a-f]+	runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   911  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   912  `},
   913  		{
   914  			name: "select send sync",
   915  			f:    blockSelectSendSync,
   916  			stk: []string{
   917  				"runtime.selectgo",
   918  				"runtime/pprof.blockSelectSendSync",
   919  				"runtime/pprof.TestBlockProfile",
   920  			},
   921  			re: `
   922  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   923  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*runtime/select.go:[0-9]+
   924  #	0x[0-9a-f]+	runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   925  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   926  `},
   927  		{
   928  			name: "mutex",
   929  			f:    blockMutex,
   930  			stk: []string{
   931  				"sync.(*Mutex).Lock",
   932  				"runtime/pprof.blockMutex",
   933  				"runtime/pprof.TestBlockProfile",
   934  			},
   935  			re: `
   936  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   937  #	0x[0-9a-f]+	sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+	.*sync/mutex\.go:[0-9]+
   938  #	0x[0-9a-f]+	runtime/pprof\.blockMutex\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   939  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   940  `},
   941  		{
   942  			name: "cond",
   943  			f:    blockCond,
   944  			stk: []string{
   945  				"sync.(*Cond).Wait",
   946  				"runtime/pprof.blockCond",
   947  				"runtime/pprof.TestBlockProfile",
   948  			},
   949  			re: `
   950  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   951  #	0x[0-9a-f]+	sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+	.*sync/cond\.go:[0-9]+
   952  #	0x[0-9a-f]+	runtime/pprof\.blockCond\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   953  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   954  `},
   955  	}
   956  
   957  	// Generate block profile
   958  	runtime.SetBlockProfileRate(1)
   959  	defer runtime.SetBlockProfileRate(0)
   960  	for _, test := range tests {
   961  		test.f(t)
   962  	}
   963  
   964  	t.Run("debug=1", func(t *testing.T) {
   965  		var w strings.Builder
   966  		Lookup("block").WriteTo(&w, 1)
   967  		prof := w.String()
   968  
   969  		if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
   970  			t.Fatalf("Bad profile header:\n%v", prof)
   971  		}
   972  
   973  		if strings.HasSuffix(prof, "#\t0x0\n\n") {
   974  			t.Errorf("Useless 0 suffix:\n%v", prof)
   975  		}
   976  
   977  		for _, test := range tests {
   978  			if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) {
   979  				t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
   980  			}
   981  		}
   982  	})
   983  
   984  	t.Run("proto", func(t *testing.T) {
   985  		// proto format
   986  		var w bytes.Buffer
   987  		Lookup("block").WriteTo(&w, 0)
   988  		p, err := profile.Parse(&w)
   989  		if err != nil {
   990  			t.Fatalf("failed to parse profile: %v", err)
   991  		}
   992  		t.Logf("parsed proto: %s", p)
   993  		if err := p.CheckValid(); err != nil {
   994  			t.Fatalf("invalid profile: %v", err)
   995  		}
   996  
   997  		stks := profileStacks(p)
   998  		for _, test := range tests {
   999  			if !containsStack(stks, test.stk) {
  1000  				t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk)
  1001  			}
  1002  		}
  1003  	})
  1004  
  1005  }
  1006  
  1007  func profileStacks(p *profile.Profile) (res [][]string) {
  1008  	for _, s := range p.Sample {
  1009  		var stk []string
  1010  		for _, l := range s.Location {
  1011  			for _, line := range l.Line {
  1012  				stk = append(stk, line.Function.Name)
  1013  			}
  1014  		}
  1015  		res = append(res, stk)
  1016  	}
  1017  	return res
  1018  }
  1019  
  1020  func blockRecordStacks(records []runtime.BlockProfileRecord) (res [][]string) {
  1021  	for _, record := range records {
  1022  		frames := runtime.CallersFrames(record.Stack())
  1023  		var stk []string
  1024  		for {
  1025  			frame, more := frames.Next()
  1026  			stk = append(stk, frame.Function)
  1027  			if !more {
  1028  				break
  1029  			}
  1030  		}
  1031  		res = append(res, stk)
  1032  	}
  1033  	return res
  1034  }
  1035  
  1036  func containsStack(got [][]string, want []string) bool {
  1037  	for _, stk := range got {
  1038  		if len(stk) < len(want) {
  1039  			continue
  1040  		}
  1041  		for i, f := range want {
  1042  			if f != stk[i] {
  1043  				break
  1044  			}
  1045  			if i == len(want)-1 {
  1046  				return true
  1047  			}
  1048  		}
  1049  	}
  1050  	return false
  1051  }
  1052  
  1053  // awaitBlockedGoroutine spins on runtime.Gosched until a runtime stack dump
  1054  // shows a goroutine in the given state with a stack frame in
  1055  // runtime/pprof.<fName>.
  1056  func awaitBlockedGoroutine(t *testing.T, state, fName string, count int) {
  1057  	re := fmt.Sprintf(`(?m)^goroutine \d+ \[%s\]:\n(?:.+\n\t.+\n)*runtime/pprof\.%s`, regexp.QuoteMeta(state), fName)
  1058  	r := regexp.MustCompile(re)
  1059  
  1060  	if deadline, ok := t.Deadline(); ok {
  1061  		if d := time.Until(deadline); d > 1*time.Second {
  1062  			timer := time.AfterFunc(d-1*time.Second, func() {
  1063  				debug.SetTraceback("all")
  1064  				panic(fmt.Sprintf("timed out waiting for %#q", re))
  1065  			})
  1066  			defer timer.Stop()
  1067  		}
  1068  	}
  1069  
  1070  	buf := make([]byte, 64<<10)
  1071  	for {
  1072  		runtime.Gosched()
  1073  		n := runtime.Stack(buf, true)
  1074  		if n == len(buf) {
  1075  			// Buffer wasn't large enough for a full goroutine dump.
  1076  			// Resize it and try again.
  1077  			buf = make([]byte, 2*len(buf))
  1078  			continue
  1079  		}
  1080  		if len(r.FindAll(buf[:n], -1)) >= count {
  1081  			return
  1082  		}
  1083  	}
  1084  }
  1085  
  1086  func blockChanRecv(t *testing.T) {
  1087  	c := make(chan bool)
  1088  	go func() {
  1089  		awaitBlockedGoroutine(t, "chan receive", "blockChanRecv", 1)
  1090  		c <- true
  1091  	}()
  1092  	<-c
  1093  }
  1094  
  1095  func blockChanSend(t *testing.T) {
  1096  	c := make(chan bool)
  1097  	go func() {
  1098  		awaitBlockedGoroutine(t, "chan send", "blockChanSend", 1)
  1099  		<-c
  1100  	}()
  1101  	c <- true
  1102  }
  1103  
  1104  func blockChanClose(t *testing.T) {
  1105  	c := make(chan bool)
  1106  	go func() {
  1107  		awaitBlockedGoroutine(t, "chan receive", "blockChanClose", 1)
  1108  		close(c)
  1109  	}()
  1110  	<-c
  1111  }
  1112  
  1113  func blockSelectRecvAsync(t *testing.T) {
  1114  	const numTries = 3
  1115  	c := make(chan bool, 1)
  1116  	c2 := make(chan bool, 1)
  1117  	go func() {
  1118  		for i := 0; i < numTries; i++ {
  1119  			awaitBlockedGoroutine(t, "select", "blockSelectRecvAsync", 1)
  1120  			c <- true
  1121  		}
  1122  	}()
  1123  	for i := 0; i < numTries; i++ {
  1124  		select {
  1125  		case <-c:
  1126  		case <-c2:
  1127  		}
  1128  	}
  1129  }
  1130  
  1131  func blockSelectSendSync(t *testing.T) {
  1132  	c := make(chan bool)
  1133  	c2 := make(chan bool)
  1134  	go func() {
  1135  		awaitBlockedGoroutine(t, "select", "blockSelectSendSync", 1)
  1136  		<-c
  1137  	}()
  1138  	select {
  1139  	case c <- true:
  1140  	case c2 <- true:
  1141  	}
  1142  }
  1143  
  1144  func blockMutex(t *testing.T) {
  1145  	var mu sync.Mutex
  1146  	mu.Lock()
  1147  	go func() {
  1148  		awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex", 1)
  1149  		mu.Unlock()
  1150  	}()
  1151  	// Note: Unlock releases mu before recording the mutex event,
  1152  	// so it's theoretically possible for this to proceed and
  1153  	// capture the profile before the event is recorded. As long
  1154  	// as this is blocked before the unlock happens, it's okay.
  1155  	mu.Lock()
  1156  }
  1157  
  1158  func blockMutexN(t *testing.T, n int, d time.Duration) {
  1159  	var wg sync.WaitGroup
  1160  	var mu sync.Mutex
  1161  	mu.Lock()
  1162  	go func() {
  1163  		awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex", n)
  1164  		time.Sleep(d)
  1165  		mu.Unlock()
  1166  	}()
  1167  	// Note: Unlock releases mu before recording the mutex event,
  1168  	// so it's theoretically possible for this to proceed and
  1169  	// capture the profile before the event is recorded. As long
  1170  	// as this is blocked before the unlock happens, it's okay.
  1171  	for i := 0; i < n; i++ {
  1172  		wg.Add(1)
  1173  		go func() {
  1174  			defer wg.Done()
  1175  			mu.Lock()
  1176  			mu.Unlock()
  1177  		}()
  1178  	}
  1179  	wg.Wait()
  1180  }
  1181  
  1182  func blockCond(t *testing.T) {
  1183  	var mu sync.Mutex
  1184  	c := sync.NewCond(&mu)
  1185  	mu.Lock()
  1186  	go func() {
  1187  		awaitBlockedGoroutine(t, "sync.Cond.Wait", "blockCond", 1)
  1188  		mu.Lock()
  1189  		c.Signal()
  1190  		mu.Unlock()
  1191  	}()
  1192  	c.Wait()
  1193  	mu.Unlock()
  1194  }
  1195  
  1196  // See http://golang.org/cl/299991.
  1197  func TestBlockProfileBias(t *testing.T) {
  1198  	rate := int(1000) // arbitrary value
  1199  	runtime.SetBlockProfileRate(rate)
  1200  	defer runtime.SetBlockProfileRate(0)
  1201  
  1202  	// simulate blocking events
  1203  	blockFrequentShort(rate)
  1204  	blockInfrequentLong(rate)
  1205  
  1206  	var w bytes.Buffer
  1207  	Lookup("block").WriteTo(&w, 0)
  1208  	p, err := profile.Parse(&w)
  1209  	if err != nil {
  1210  		t.Fatalf("failed to parse profile: %v", err)
  1211  	}
  1212  	t.Logf("parsed proto: %s", p)
  1213  
  1214  	il := float64(-1) // blockInfrequentLong duration
  1215  	fs := float64(-1) // blockFrequentShort duration
  1216  	for _, s := range p.Sample {
  1217  		for _, l := range s.Location {
  1218  			for _, line := range l.Line {
  1219  				if len(s.Value) < 2 {
  1220  					t.Fatal("block profile has less than 2 sample types")
  1221  				}
  1222  
  1223  				if line.Function.Name == "runtime/pprof.blockInfrequentLong" {
  1224  					il = float64(s.Value[1])
  1225  				} else if line.Function.Name == "runtime/pprof.blockFrequentShort" {
  1226  					fs = float64(s.Value[1])
  1227  				}
  1228  			}
  1229  		}
  1230  	}
  1231  	if il == -1 || fs == -1 {
  1232  		t.Fatal("block profile is missing expected functions")
  1233  	}
  1234  
  1235  	// stddev of bias from 100 runs on local machine multiplied by 10x
  1236  	const threshold = 0.2
  1237  	if bias := (il - fs) / il; math.Abs(bias) > threshold {
  1238  		t.Fatalf("bias: abs(%f) > %f", bias, threshold)
  1239  	} else {
  1240  		t.Logf("bias: abs(%f) < %f", bias, threshold)
  1241  	}
  1242  }
  1243  
  1244  // blockFrequentShort produces 100000 block events with an average duration of
  1245  // rate / 10.
  1246  func blockFrequentShort(rate int) {
  1247  	for i := 0; i < 100000; i++ {
  1248  		blockevent(int64(rate/10), 1)
  1249  	}
  1250  }
  1251  
  1252  // blockInfrequentLong produces 10000 block events with an average duration of
  1253  // rate.
  1254  func blockInfrequentLong(rate int) {
  1255  	for i := 0; i < 10000; i++ {
  1256  		blockevent(int64(rate), 1)
  1257  	}
  1258  }
  1259  
  1260  // Used by TestBlockProfileBias.
  1261  //
  1262  //go:linkname blockevent runtime.blockevent
  1263  func blockevent(cycles int64, skip int)
  1264  
  1265  func TestMutexProfile(t *testing.T) {
  1266  	// Generate mutex profile
  1267  
  1268  	old := runtime.SetMutexProfileFraction(1)
  1269  	defer runtime.SetMutexProfileFraction(old)
  1270  	if old != 0 {
  1271  		t.Fatalf("need MutexProfileRate 0, got %d", old)
  1272  	}
  1273  
  1274  	const (
  1275  		N = 100
  1276  		D = 100 * time.Millisecond
  1277  	)
  1278  	start := time.Now()
  1279  	blockMutexN(t, N, D)
  1280  	blockMutexNTime := time.Since(start)
  1281  
  1282  	t.Run("debug=1", func(t *testing.T) {
  1283  		var w strings.Builder
  1284  		Lookup("mutex").WriteTo(&w, 1)
  1285  		prof := w.String()
  1286  		t.Logf("received profile: %v", prof)
  1287  
  1288  		if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") {
  1289  			t.Errorf("Bad profile header:\n%v", prof)
  1290  		}
  1291  		prof = strings.Trim(prof, "\n")
  1292  		lines := strings.Split(prof, "\n")
  1293  		if len(lines) < 6 {
  1294  			t.Fatalf("expected >=6 lines, got %d %q\n%s", len(lines), prof, prof)
  1295  		}
  1296  		// checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931"
  1297  		r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+`
  1298  		if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok {
  1299  			t.Errorf("%q didn't match %q", lines[3], r2)
  1300  		}
  1301  		r3 := "^#.*runtime/pprof.blockMutex.*$"
  1302  		if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok {
  1303  			t.Errorf("%q didn't match %q", lines[5], r3)
  1304  		}
  1305  		t.Log(prof)
  1306  	})
  1307  	t.Run("proto", func(t *testing.T) {
  1308  		// proto format
  1309  		var w bytes.Buffer
  1310  		Lookup("mutex").WriteTo(&w, 0)
  1311  		p, err := profile.Parse(&w)
  1312  		if err != nil {
  1313  			t.Fatalf("failed to parse profile: %v", err)
  1314  		}
  1315  		t.Logf("parsed proto: %s", p)
  1316  		if err := p.CheckValid(); err != nil {
  1317  			t.Fatalf("invalid profile: %v", err)
  1318  		}
  1319  
  1320  		stks := profileStacks(p)
  1321  		for _, want := range [][]string{
  1322  			{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexN.func1"},
  1323  		} {
  1324  			if !containsStack(stks, want) {
  1325  				t.Errorf("No matching stack entry for %+v", want)
  1326  			}
  1327  		}
  1328  
  1329  		i := 0
  1330  		for ; i < len(p.SampleType); i++ {
  1331  			if p.SampleType[i].Unit == "nanoseconds" {
  1332  				break
  1333  			}
  1334  		}
  1335  		if i >= len(p.SampleType) {
  1336  			t.Fatalf("profile did not contain nanoseconds sample")
  1337  		}
  1338  		total := int64(0)
  1339  		for _, s := range p.Sample {
  1340  			total += s.Value[i]
  1341  		}
  1342  		// Want d to be at least N*D, but give some wiggle-room to avoid
  1343  		// a test flaking. Set an upper-bound proportional to the total
  1344  		// wall time spent in blockMutexN. Generally speaking, the total
  1345  		// contention time could be arbitrarily high when considering
  1346  		// OS scheduler delays, or any other delays from the environment:
  1347  		// time keeps ticking during these delays. By making the upper
  1348  		// bound proportional to the wall time in blockMutexN, in theory
  1349  		// we're accounting for all these possible delays.
  1350  		d := time.Duration(total)
  1351  		lo := time.Duration(N * D * 9 / 10)
  1352  		hi := time.Duration(N) * blockMutexNTime * 11 / 10
  1353  		if d < lo || d > hi {
  1354  			for _, s := range p.Sample {
  1355  				t.Logf("sample: %s", time.Duration(s.Value[i]))
  1356  			}
  1357  			t.Fatalf("profile samples total %v, want within range [%v, %v] (target: %v)", d, lo, hi, N*D)
  1358  		}
  1359  	})
  1360  
  1361  	t.Run("records", func(t *testing.T) {
  1362  		// Record a mutex profile using the structured record API.
  1363  		var records []runtime.BlockProfileRecord
  1364  		for {
  1365  			n, ok := runtime.MutexProfile(records)
  1366  			if ok {
  1367  				records = records[:n]
  1368  				break
  1369  			}
  1370  			records = make([]runtime.BlockProfileRecord, n*2)
  1371  		}
  1372  
  1373  		// Check that we see the same stack trace as the proto profile. For
  1374  		// historical reason we expect a runtime.goexit root frame here that is
  1375  		// omitted in the proto profile.
  1376  		stks := blockRecordStacks(records)
  1377  		want := []string{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexN.func1", "runtime.goexit"}
  1378  		if !containsStack(stks, want) {
  1379  			t.Errorf("No matching stack entry for %+v", want)
  1380  		}
  1381  	})
  1382  }
  1383  
  1384  func TestMutexProfileRateAdjust(t *testing.T) {
  1385  	old := runtime.SetMutexProfileFraction(1)
  1386  	defer runtime.SetMutexProfileFraction(old)
  1387  	if old != 0 {
  1388  		t.Fatalf("need MutexProfileRate 0, got %d", old)
  1389  	}
  1390  
  1391  	readProfile := func() (contentions int64, delay int64) {
  1392  		var w bytes.Buffer
  1393  		Lookup("mutex").WriteTo(&w, 0)
  1394  		p, err := profile.Parse(&w)
  1395  		if err != nil {
  1396  			t.Fatalf("failed to parse profile: %v", err)
  1397  		}
  1398  		t.Logf("parsed proto: %s", p)
  1399  		if err := p.CheckValid(); err != nil {
  1400  			t.Fatalf("invalid profile: %v", err)
  1401  		}
  1402  
  1403  		for _, s := range p.Sample {
  1404  			var match, runtimeInternal bool
  1405  			for _, l := range s.Location {
  1406  				for _, line := range l.Line {
  1407  					if line.Function.Name == "runtime/pprof.blockMutex.func1" {
  1408  						match = true
  1409  					}
  1410  					if line.Function.Name == "runtime.unlock" {
  1411  						runtimeInternal = true
  1412  					}
  1413  				}
  1414  			}
  1415  			if match && !runtimeInternal {
  1416  				contentions += s.Value[0]
  1417  				delay += s.Value[1]
  1418  			}
  1419  		}
  1420  		return
  1421  	}
  1422  
  1423  	blockMutex(t)
  1424  	contentions, delay := readProfile()
  1425  	if contentions == 0 { // low-resolution timers can have delay of 0 in mutex profile
  1426  		t.Fatal("did not see expected function in profile")
  1427  	}
  1428  	runtime.SetMutexProfileFraction(0)
  1429  	newContentions, newDelay := readProfile()
  1430  	if newContentions != contentions || newDelay != delay {
  1431  		t.Fatalf("sample value changed: got [%d, %d], want [%d, %d]", newContentions, newDelay, contentions, delay)
  1432  	}
  1433  }
  1434  
  1435  func func1(c chan int) { <-c }
  1436  func func2(c chan int) { <-c }
  1437  func func3(c chan int) { <-c }
  1438  func func4(c chan int) { <-c }
  1439  
  1440  func TestGoroutineCounts(t *testing.T) {
  1441  	// Setting GOMAXPROCS to 1 ensures we can force all goroutines to the
  1442  	// desired blocking point.
  1443  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
  1444  
  1445  	c := make(chan int)
  1446  	for i := 0; i < 100; i++ {
  1447  		switch {
  1448  		case i%10 == 0:
  1449  			go func1(c)
  1450  		case i%2 == 0:
  1451  			go func2(c)
  1452  		default:
  1453  			go func3(c)
  1454  		}
  1455  		// Let goroutines block on channel
  1456  		for j := 0; j < 5; j++ {
  1457  			runtime.Gosched()
  1458  		}
  1459  	}
  1460  	ctx := context.Background()
  1461  
  1462  	// ... and again, with labels this time (just with fewer iterations to keep
  1463  	// sorting deterministic).
  1464  	Do(ctx, Labels("label", "value"), func(context.Context) {
  1465  		for i := 0; i < 89; i++ {
  1466  			switch {
  1467  			case i%10 == 0:
  1468  				go func1(c)
  1469  			case i%2 == 0:
  1470  				go func2(c)
  1471  			default:
  1472  				go func3(c)
  1473  			}
  1474  			// Let goroutines block on channel
  1475  			for j := 0; j < 5; j++ {
  1476  				runtime.Gosched()
  1477  			}
  1478  		}
  1479  	})
  1480  
  1481  	SetGoroutineLabels(WithLabels(context.Background(), Labels("self-label", "self-value")))
  1482  	defer SetGoroutineLabels(context.Background())
  1483  
  1484  	garbage := new(*int)
  1485  	fingReady := make(chan struct{})
  1486  	runtime.SetFinalizer(garbage, func(v **int) {
  1487  		Do(context.Background(), Labels("fing-label", "fing-value"), func(ctx context.Context) {
  1488  			close(fingReady)
  1489  			<-c
  1490  		})
  1491  	})
  1492  	garbage = nil
  1493  	for i := 0; i < 2; i++ {
  1494  		runtime.GC()
  1495  	}
  1496  	<-fingReady
  1497  
  1498  	var w bytes.Buffer
  1499  	goroutineProf := Lookup("goroutine")
  1500  
  1501  	// Check debug profile
  1502  	goroutineProf.WriteTo(&w, 1)
  1503  	prof := w.String()
  1504  
  1505  	labels := labelMap{label.NewSet(Labels("label", "value").list)}
  1506  	labelStr := "\n# labels: " + labels.String()
  1507  	selfLabel := labelMap{label.NewSet(Labels("self-label", "self-value").list)}
  1508  	selfLabelStr := "\n# labels: " + selfLabel.String()
  1509  	fingLabel := labelMap{label.NewSet(Labels("fing-label", "fing-value").list)}
  1510  	fingLabelStr := "\n# labels: " + fingLabel.String()
  1511  	orderedPrefix := []string{
  1512  		"\n50 @ ",
  1513  		"\n44 @", labelStr,
  1514  		"\n40 @",
  1515  		"\n36 @", labelStr,
  1516  		"\n10 @",
  1517  		"\n9 @", labelStr,
  1518  		"\n1 @"}
  1519  	if !containsInOrder(prof, append(orderedPrefix, selfLabelStr)...) {
  1520  		t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
  1521  	}
  1522  	if !containsInOrder(prof, append(orderedPrefix, fingLabelStr)...) {
  1523  		t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
  1524  	}
  1525  
  1526  	// Check proto profile
  1527  	w.Reset()
  1528  	goroutineProf.WriteTo(&w, 0)
  1529  	p, err := profile.Parse(&w)
  1530  	if err != nil {
  1531  		t.Errorf("error parsing protobuf profile: %v", err)
  1532  	}
  1533  	if err := p.CheckValid(); err != nil {
  1534  		t.Errorf("protobuf profile is invalid: %v", err)
  1535  	}
  1536  	expectedLabels := map[int64]map[string]string{
  1537  		50: {},
  1538  		44: {"label": "value"},
  1539  		40: {},
  1540  		36: {"label": "value"},
  1541  		10: {},
  1542  		9:  {"label": "value"},
  1543  		1:  {"self-label": "self-value", "fing-label": "fing-value"},
  1544  	}
  1545  	if !containsCountsLabels(p, expectedLabels) {
  1546  		t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v",
  1547  			expectedLabels, p)
  1548  	}
  1549  
  1550  	close(c)
  1551  
  1552  	time.Sleep(10 * time.Millisecond) // let goroutines exit
  1553  }
  1554  
  1555  func containsInOrder(s string, all ...string) bool {
  1556  	for _, t := range all {
  1557  		var ok bool
  1558  		if _, s, ok = strings.Cut(s, t); !ok {
  1559  			return false
  1560  		}
  1561  	}
  1562  	return true
  1563  }
  1564  
  1565  func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool {
  1566  	m := make(map[int64]int)
  1567  	type nkey struct {
  1568  		count    int64
  1569  		key, val string
  1570  	}
  1571  	n := make(map[nkey]int)
  1572  	for c, kv := range countLabels {
  1573  		m[c]++
  1574  		for k, v := range kv {
  1575  			n[nkey{
  1576  				count: c,
  1577  				key:   k,
  1578  				val:   v,
  1579  			}]++
  1580  
  1581  		}
  1582  	}
  1583  	for _, s := range prof.Sample {
  1584  		// The count is the single value in the sample
  1585  		if len(s.Value) != 1 {
  1586  			return false
  1587  		}
  1588  		m[s.Value[0]]--
  1589  		for k, vs := range s.Label {
  1590  			for _, v := range vs {
  1591  				n[nkey{
  1592  					count: s.Value[0],
  1593  					key:   k,
  1594  					val:   v,
  1595  				}]--
  1596  			}
  1597  		}
  1598  	}
  1599  	for _, n := range m {
  1600  		if n > 0 {
  1601  			return false
  1602  		}
  1603  	}
  1604  	for _, ncnt := range n {
  1605  		if ncnt != 0 {
  1606  			return false
  1607  		}
  1608  	}
  1609  	return true
  1610  }
  1611  
  1612  // Inlining disabled to make identification simpler.
  1613  //
  1614  //go:noinline
  1615  func goroutineLeakExample() {
  1616  	<-make(chan struct{})
  1617  	panic("unreachable")
  1618  }
  1619  
  1620  func TestGoroutineLeakProfileConcurrency(t *testing.T) {
  1621  	const leakCount = 3
  1622  
  1623  	testenv.MustHaveParallelism(t)
  1624  	regexLeakCount := regexp.MustCompile("goroutineleak profile: total ")
  1625  	whiteSpace := regexp.MustCompile("\\s+")
  1626  
  1627  	// Regular goroutine profile. Used to check that there is no interference between
  1628  	// the two profile types.
  1629  	goroutineProf := Lookup("goroutine")
  1630  	goroutineLeakProf := goroutineLeakProfile
  1631  
  1632  	// We use this helper to count the total number of leaked goroutines in a text profile.
  1633  	countLeaks := func(t *testing.T, profText string) int64 {
  1634  		t.Helper()
  1635  
  1636  		// Strip the profile header
  1637  		parts := regexLeakCount.Split(profText, -1)
  1638  		if len(parts) < 2 {
  1639  			t.Fatalf("goroutineleak profile does not contain 'goroutineleak profile: total ': %s\nparts: %v", profText, parts)
  1640  		}
  1641  
  1642  		parts = whiteSpace.Split(parts[1], -1)
  1643  
  1644  		count, err := strconv.ParseInt(parts[0], 10, 64)
  1645  		if err != nil {
  1646  			t.Fatalf("goroutineleak profile count is not a number: %s\nerror: %v", profText, err)
  1647  		}
  1648  		return count
  1649  	}
  1650  
  1651  	// checkFrame looks for a specific frame in the stack.
  1652  	//
  1653  	// i is the location index in the profile and j is the location line index for the location.
  1654  	// (Inlining may cause aliasing to the same location.)
  1655  	checkFrame := func(t *testing.T, i int, j int, locations []*profile.Location, funcName string) {
  1656  		if len(locations) <= i {
  1657  			t.Errorf("leaked goroutine stack locations: out of range index %d, length %d", i, len(locations))
  1658  			return
  1659  		}
  1660  		location := locations[i]
  1661  		if len(location.Line) <= j {
  1662  			t.Errorf("leaked goroutine stack location lines: out of range index %d, length %d", j, len(location.Line))
  1663  			return
  1664  		}
  1665  		if location.Line[j].Function.Name != funcName {
  1666  			t.Errorf("leaked goroutine stack expected %s as location[%d].Line[%d] but found %s (%s:%d)", funcName, i, j, location.Line[j].Function.Name, location.Line[j].Function.Filename, location.Line[j].Line)
  1667  		}
  1668  	}
  1669  
  1670  	// checkLeakStack hooks into profile parsing and performs validation, looking for specific stacks for
  1671  	// the goroutines we'll leak in this test.
  1672  	checkLeakStack := func(t *testing.T) func(pc uintptr, locations []*profile.Location, _ map[string][]string) {
  1673  		return func(pc uintptr, locations []*profile.Location, _ map[string][]string) {
  1674  			if pc != leakCount {
  1675  				t.Errorf("expected %d leaked goroutines with specific stack configurations, but found %d", leakCount, pc)
  1676  				return
  1677  			}
  1678  			if len(locations) < 4 || len(locations) > 5 {
  1679  				message := fmt.Sprintf("leaked goroutine stack expected 4 or 5 locations but found %d", len(locations))
  1680  				for _, location := range locations {
  1681  					for _, line := range location.Line {
  1682  						message += fmt.Sprintf("\n%s:%d", line.Function.Name, line.Line)
  1683  					}
  1684  				}
  1685  				t.Errorf("%s", message)
  1686  				return
  1687  			}
  1688  			// We expect a receive operation. This is the typical stack.
  1689  			checkFrame(t, 0, 0, locations, "runtime.gopark")
  1690  			checkFrame(t, 1, 0, locations, "runtime.chanrecv")
  1691  			checkFrame(t, 2, 0, locations, "runtime.chanrecv1")
  1692  			checkFrame(t, 3, 0, locations, "runtime/pprof.goroutineLeakExample")
  1693  			if len(locations) == 5 {
  1694  				checkFrame(t, 4, 0, locations, "runtime/pprof.TestGoroutineLeakProfileConcurrency.func4")
  1695  			}
  1696  		}
  1697  	}
  1698  
  1699  	// Leak some goroutines that will feature in the goroutine leak profile
  1700  	const totalLeaked = leakCount * 2
  1701  	for i := 0; i < leakCount; i++ {
  1702  		go goroutineLeakExample()
  1703  		go func() {
  1704  			// Leak another goroutine that will feature a slightly different stack.
  1705  			// This includes the frame runtime/pprof.TestGoroutineLeakProfileConcurrency.func1.
  1706  			goroutineLeakExample()
  1707  			panic("unreachable")
  1708  		}()
  1709  	}
  1710  
  1711  	// Wait for the goroutines to leak. We might wait here until the timeout,
  1712  	// but this is better than intermittent flakes because we didn't wait long
  1713  	// enough. If we actually time out, then there's likely a bug.
  1714  	attempts := 0
  1715  	startTime := time.Now()
  1716  	waitFor := 10 * time.Millisecond
  1717  	for {
  1718  		//
  1719  		// If they never get detected, we'll get a timeout.
  1720  		time.Sleep(waitFor)
  1721  
  1722  		var w strings.Builder
  1723  		goroutineLeakProf.WriteTo(&w, 1)
  1724  		n := countLeaks(t, w.String())
  1725  		if n >= totalLeaked {
  1726  			break
  1727  		}
  1728  
  1729  		// Log some messages so if a timeout is seen
  1730  		attempts++
  1731  		t.Logf("waiting for leak: attempt %d (t=%s): found %d leaked goroutines", attempts, time.Since(startTime), n)
  1732  
  1733  		// Wait a little longer to avoid spamming the log.
  1734  		waitFor *= 2
  1735  		if waitFor > time.Second {
  1736  			waitFor = time.Second
  1737  		}
  1738  	}
  1739  
  1740  	t.Run("profile contains leak", func(t *testing.T) {
  1741  		var w strings.Builder
  1742  		goroutineLeakProf.WriteTo(&w, 0)
  1743  		parseProfile(t, []byte(w.String()), checkLeakStack(t))
  1744  	})
  1745  
  1746  	t.Run("leak persists between sequential profiling runs", func(t *testing.T) {
  1747  		for i := 0; i < 2; i++ {
  1748  			var w strings.Builder
  1749  			goroutineLeakProf.WriteTo(&w, 0)
  1750  			parseProfile(t, []byte(w.String()), checkLeakStack(t))
  1751  		}
  1752  	})
  1753  
  1754  	// Concurrent calls to the goroutine leak profiler should not trigger data races
  1755  	// or corruption.
  1756  	quickCheckForGoroutine := func(t *testing.T, profType, leak, profText string) {
  1757  		if !strings.Contains(profText, leak) {
  1758  			t.Errorf("%s profile does not contain expected leaked goroutine %s: %s", profType, leak, profText)
  1759  		}
  1760  	}
  1761  
  1762  	// TODO(thepudds,vsaioc): the next two subtests would ideally find totalLeaked goroutines,
  1763  	// but in rare cases they seem to be 1 short, leading to intermittent flakes. Perhaps this
  1764  	// is "expected" due to a convervative scan keeping something alive or some other rare event.
  1765  	// Deflake for now by allowing a small margin of error. #79452 is for finding a true root
  1766  	// cause, improving this test, or adjusting the leak profiler if warranted.
  1767  	const minWantLeaks = totalLeaked - 1
  1768  
  1769  	t.Run("overlapping profile requests", func(t *testing.T) {
  1770  		ctx := context.Background()
  1771  		ctx, cancel := context.WithTimeout(ctx, time.Second)
  1772  		defer cancel()
  1773  
  1774  		var wg sync.WaitGroup
  1775  		for i := 0; i < 2; i++ {
  1776  			wg.Add(1)
  1777  			Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
  1778  				go func() {
  1779  					defer wg.Done()
  1780  					for ctx.Err() == nil {
  1781  						var w strings.Builder
  1782  						goroutineLeakProf.WriteTo(&w, 1)
  1783  						got := countLeaks(t, w.String())
  1784  						// TODO(thepudds,vsaioc): see related comment on minWantLeaks above.
  1785  						if got < minWantLeaks || got > totalLeaked {
  1786  							t.Errorf("expected at least %d and at most %d goroutines leaked, got %d: %s",
  1787  								minWantLeaks, totalLeaked, got, w.String())
  1788  						}
  1789  						quickCheckForGoroutine(t, "goroutineleak", "runtime/pprof.goroutineLeakExample", w.String())
  1790  					}
  1791  				}()
  1792  			})
  1793  		}
  1794  		wg.Wait()
  1795  	})
  1796  
  1797  	// Concurrent calls to the goroutine leak profiler should not trigger data races
  1798  	// or corruption, or interfere with regular goroutine profiles.
  1799  	t.Run("overlapping goroutine and goroutine leak profile requests", func(t *testing.T) {
  1800  		ctx := context.Background()
  1801  		ctx, cancel := context.WithTimeout(ctx, time.Second)
  1802  		defer cancel()
  1803  
  1804  		var wg sync.WaitGroup
  1805  		for i := 0; i < 2; i++ {
  1806  			wg.Add(2)
  1807  			Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
  1808  				go func() {
  1809  					defer wg.Done()
  1810  					for ctx.Err() == nil {
  1811  						var w strings.Builder
  1812  						goroutineLeakProf.WriteTo(&w, 1)
  1813  						got := countLeaks(t, w.String())
  1814  						// TODO(thepudds,vsaioc): see related comment on minWantLeaks above.
  1815  						if got < minWantLeaks || got > totalLeaked {
  1816  							t.Errorf("expected at least %d and at most %d goroutines leaked, got %d: %s",
  1817  								minWantLeaks, totalLeaked, got, w.String())
  1818  						}
  1819  						quickCheckForGoroutine(t, "goroutineleak", "runtime/pprof.goroutineLeakExample", w.String())
  1820  					}
  1821  				}()
  1822  				go func() {
  1823  					defer wg.Done()
  1824  					for ctx.Err() == nil {
  1825  						var w strings.Builder
  1826  						goroutineProf.WriteTo(&w, 1)
  1827  						// The regular goroutine profile should see the leaked
  1828  						// goroutines. We simply check that the goroutine leak
  1829  						// profile does not corrupt the goroutine profile state.
  1830  						quickCheckForGoroutine(t, "goroutine", "runtime/pprof.goroutineLeakExample", w.String())
  1831  					}
  1832  				}()
  1833  			})
  1834  		}
  1835  		wg.Wait()
  1836  	})
  1837  }
  1838  
  1839  func TestGoroutineProfileConcurrency(t *testing.T) {
  1840  	testenv.MustHaveParallelism(t)
  1841  
  1842  	goroutineProf := Lookup("goroutine")
  1843  
  1844  	profilerCalls := func(s string) int {
  1845  		return strings.Count(s, "\truntime/pprof.runtime_goroutineProfileWithLabels+")
  1846  	}
  1847  
  1848  	includesFinalizerOrCleanup := func(s string) bool {
  1849  		return strings.Contains(s, "runtime.runFinalizers") || strings.Contains(s, "runtime.runCleanups")
  1850  	}
  1851  
  1852  	// Concurrent calls to the goroutine profiler should not trigger data races
  1853  	// or corruption.
  1854  	t.Run("overlapping profile requests", func(t *testing.T) {
  1855  		ctx := context.Background()
  1856  		ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
  1857  		defer cancel()
  1858  
  1859  		var wg sync.WaitGroup
  1860  		for i := 0; i < 2; i++ {
  1861  			wg.Add(1)
  1862  			Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
  1863  				go func() {
  1864  					defer wg.Done()
  1865  					for ctx.Err() == nil {
  1866  						var w strings.Builder
  1867  						goroutineProf.WriteTo(&w, 1)
  1868  						prof := w.String()
  1869  						count := profilerCalls(prof)
  1870  						if count >= 2 {
  1871  							t.Logf("prof %d\n%s", count, prof)
  1872  							cancel()
  1873  						}
  1874  					}
  1875  				}()
  1876  			})
  1877  		}
  1878  		wg.Wait()
  1879  	})
  1880  
  1881  	// The finalizer goroutine should not show up in most profiles, since it's
  1882  	// marked as a system goroutine when idle.
  1883  	t.Run("finalizer not present", func(t *testing.T) {
  1884  		var w strings.Builder
  1885  		goroutineProf.WriteTo(&w, 1)
  1886  		prof := w.String()
  1887  		if includesFinalizerOrCleanup(prof) {
  1888  			t.Errorf("profile includes finalizer or cleanup (but should be marked as system):\n%s", prof)
  1889  		}
  1890  	})
  1891  
  1892  	// The finalizer goroutine should show up when it's running user code.
  1893  	t.Run("finalizer present", func(t *testing.T) {
  1894  		// T is a pointer type so it won't be allocated by the tiny
  1895  		// allocator, which can lead to its finalizer not being called
  1896  		// during this test
  1897  		type T *byte
  1898  		obj := new(T)
  1899  		ch1, ch2 := make(chan int), make(chan int)
  1900  		defer close(ch2)
  1901  		runtime.SetFinalizer(obj, func(_ any) {
  1902  			close(ch1)
  1903  			<-ch2
  1904  		})
  1905  		obj = nil
  1906  		for i := 10; i >= 0; i-- {
  1907  			select {
  1908  			case <-ch1:
  1909  			default:
  1910  				if i == 0 {
  1911  					t.Fatalf("finalizer did not run")
  1912  				}
  1913  				runtime.GC()
  1914  			}
  1915  		}
  1916  		var w strings.Builder
  1917  		goroutineProf.WriteTo(&w, 1)
  1918  		prof := w.String()
  1919  		if !includesFinalizerOrCleanup(prof) {
  1920  			t.Errorf("profile does not include finalizer (and it should be marked as user):\n%s", prof)
  1921  		}
  1922  	})
  1923  
  1924  	// Check that new goroutines only show up in order.
  1925  	testLaunches := func(t *testing.T) {
  1926  		var done sync.WaitGroup
  1927  		defer done.Wait()
  1928  
  1929  		ctx := context.Background()
  1930  		ctx, cancel := context.WithCancel(ctx)
  1931  		defer cancel()
  1932  
  1933  		ch := make(chan int)
  1934  		defer close(ch)
  1935  
  1936  		var ready sync.WaitGroup
  1937  
  1938  		// These goroutines all survive until the end of the subtest, so we can
  1939  		// check that a (numbered) goroutine appearing in the profile implies
  1940  		// that all older goroutines also appear in the profile.
  1941  		ready.Add(1)
  1942  		done.Add(1)
  1943  		go func() {
  1944  			defer done.Done()
  1945  			for i := 0; ctx.Err() == nil; i++ {
  1946  				// Use SetGoroutineLabels rather than Do we can always expect an
  1947  				// extra goroutine (this one) with most recent label.
  1948  				SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-loop-i", fmt.Sprint(i))))
  1949  				done.Add(1)
  1950  				go func() {
  1951  					<-ch
  1952  					done.Done()
  1953  				}()
  1954  				for j := 0; j < i; j++ {
  1955  					// Spin for longer and longer as the test goes on. This
  1956  					// goroutine will do O(N^2) work with the number of
  1957  					// goroutines it launches. This should be slow relative to
  1958  					// the work involved in collecting a goroutine profile,
  1959  					// which is O(N) with the high-water mark of the number of
  1960  					// goroutines in this process (in the allgs slice).
  1961  					runtime.Gosched()
  1962  				}
  1963  				if i == 0 {
  1964  					ready.Done()
  1965  				}
  1966  			}
  1967  		}()
  1968  
  1969  		// Short-lived goroutines exercise different code paths (goroutines with
  1970  		// status _Gdead, for instance). This churn doesn't have behavior that
  1971  		// we can test directly, but does help to shake out data races.
  1972  		ready.Add(1)
  1973  		var churn func(i int)
  1974  		churn = func(i int) {
  1975  			SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-churn-i", fmt.Sprint(i))))
  1976  			if i == 0 {
  1977  				ready.Done()
  1978  			} else if i%16 == 0 {
  1979  				// Yield on occasion so this sequence of goroutine launches
  1980  				// doesn't monopolize a P. See issue #52934.
  1981  				runtime.Gosched()
  1982  			}
  1983  			if ctx.Err() == nil {
  1984  				go churn(i + 1)
  1985  			}
  1986  		}
  1987  		go func() {
  1988  			churn(0)
  1989  		}()
  1990  
  1991  		ready.Wait()
  1992  
  1993  		var w [3]bytes.Buffer
  1994  		for i := range w {
  1995  			goroutineProf.WriteTo(&w[i], 0)
  1996  		}
  1997  		for i := range w {
  1998  			p, err := profile.Parse(bytes.NewReader(w[i].Bytes()))
  1999  			if err != nil {
  2000  				t.Errorf("error parsing protobuf profile: %v", err)
  2001  			}
  2002  
  2003  			// High-numbered loop-i goroutines imply that every lower-numbered
  2004  			// loop-i goroutine should be present in the profile too.
  2005  			counts := make(map[string]int)
  2006  			for _, s := range p.Sample {
  2007  				label := s.Label[t.Name()+"-loop-i"]
  2008  				if len(label) > 0 {
  2009  					counts[label[0]]++
  2010  				}
  2011  			}
  2012  			for j, max := 0, len(counts)-1; j <= max; j++ {
  2013  				n := counts[fmt.Sprint(j)]
  2014  				if n == 1 || (n == 2 && j == max) {
  2015  					continue
  2016  				}
  2017  				t.Errorf("profile #%d's goroutines with label loop-i:%d; %d != 1 (or 2 for the last entry, %d)",
  2018  					i+1, j, n, max)
  2019  				t.Logf("counts %v", counts)
  2020  				break
  2021  			}
  2022  		}
  2023  	}
  2024  
  2025  	runs := 100
  2026  	if testing.Short() {
  2027  		runs = 5
  2028  	}
  2029  	for i := 0; i < runs; i++ {
  2030  		// Run multiple times to shake out data races
  2031  		t.Run("goroutine launches", testLaunches)
  2032  	}
  2033  }
  2034  
  2035  // Regression test for #69998.
  2036  func TestGoroutineProfileCoro(t *testing.T) {
  2037  	testenv.MustHaveParallelism(t)
  2038  
  2039  	goroutineProf := Lookup("goroutine")
  2040  
  2041  	// Set up a goroutine to just create and run coroutine goroutines all day.
  2042  	iterFunc := func() {
  2043  		p, stop := iter.Pull2(
  2044  			func(yield func(int, int) bool) {
  2045  				for i := 0; i < 10000; i++ {
  2046  					if !yield(i, i) {
  2047  						return
  2048  					}
  2049  				}
  2050  			},
  2051  		)
  2052  		defer stop()
  2053  		for {
  2054  			_, _, ok := p()
  2055  			if !ok {
  2056  				break
  2057  			}
  2058  		}
  2059  	}
  2060  	var wg sync.WaitGroup
  2061  	done := make(chan struct{})
  2062  	wg.Add(1)
  2063  	go func() {
  2064  		defer wg.Done()
  2065  		for {
  2066  			iterFunc()
  2067  			select {
  2068  			case <-done:
  2069  			default:
  2070  			}
  2071  		}
  2072  	}()
  2073  
  2074  	// Take a goroutine profile. If the bug in #69998 is present, this will crash
  2075  	// with high probability. We don't care about the output for this bug.
  2076  	goroutineProf.WriteTo(io.Discard, 1)
  2077  }
  2078  
  2079  // This test tries to provoke a situation wherein the finalizer goroutine is
  2080  // erroneously inspected by the goroutine profiler in such a way that could
  2081  // cause a crash. See go.dev/issue/74090.
  2082  func TestGoroutineProfileIssue74090(t *testing.T) {
  2083  	testenv.MustHaveParallelism(t)
  2084  
  2085  	goroutineProf := Lookup("goroutine")
  2086  
  2087  	// T is a pointer type so it won't be allocated by the tiny
  2088  	// allocator, which can lead to its finalizer not being called
  2089  	// during this test.
  2090  	type T *byte
  2091  	for range 10 {
  2092  		// We use finalizers for this test because finalizers transition between
  2093  		// system and user goroutine on each call, since there's substantially
  2094  		// more work to do to set up a finalizer call. Cleanups, on the other hand,
  2095  		// transition once for a whole batch, and so are less likely to trigger
  2096  		// the failure. Under stress testing conditions this test fails approximately
  2097  		// 5 times every 1000 executions on a 64 core machine without the appropriate
  2098  		// fix, which is not ideal but if this test crashes at all, it's a clear
  2099  		// signal that something is broken.
  2100  		var objs []*T
  2101  		for range 10000 {
  2102  			obj := new(T)
  2103  			runtime.SetFinalizer(obj, func(_ any) {})
  2104  			objs = append(objs, obj)
  2105  		}
  2106  		objs = nil
  2107  
  2108  		// Queue up all the finalizers.
  2109  		runtime.GC()
  2110  
  2111  		// Try to run a goroutine profile concurrently with finalizer execution
  2112  		// to trigger the bug.
  2113  		var w strings.Builder
  2114  		goroutineProf.WriteTo(&w, 1)
  2115  	}
  2116  }
  2117  
  2118  func BenchmarkGoroutine(b *testing.B) {
  2119  	withIdle := func(n int, fn func(b *testing.B)) func(b *testing.B) {
  2120  		return func(b *testing.B) {
  2121  			c := make(chan int)
  2122  			var ready, done sync.WaitGroup
  2123  			defer func() {
  2124  				close(c)
  2125  				done.Wait()
  2126  			}()
  2127  
  2128  			for i := 0; i < n; i++ {
  2129  				ready.Add(1)
  2130  				done.Add(1)
  2131  				go func() {
  2132  					ready.Done()
  2133  					<-c
  2134  					done.Done()
  2135  				}()
  2136  			}
  2137  			// Let goroutines block on channel
  2138  			ready.Wait()
  2139  			for i := 0; i < 5; i++ {
  2140  				runtime.Gosched()
  2141  			}
  2142  
  2143  			fn(b)
  2144  		}
  2145  	}
  2146  
  2147  	withChurn := func(fn func(b *testing.B)) func(b *testing.B) {
  2148  		return func(b *testing.B) {
  2149  			ctx := context.Background()
  2150  			ctx, cancel := context.WithCancel(ctx)
  2151  			defer cancel()
  2152  
  2153  			var ready sync.WaitGroup
  2154  			ready.Add(1)
  2155  			var count int64
  2156  			var churn func(i int)
  2157  			churn = func(i int) {
  2158  				SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
  2159  				atomic.AddInt64(&count, 1)
  2160  				if i == 0 {
  2161  					ready.Done()
  2162  				}
  2163  				if ctx.Err() == nil {
  2164  					go churn(i + 1)
  2165  				}
  2166  			}
  2167  			go func() {
  2168  				churn(0)
  2169  			}()
  2170  			ready.Wait()
  2171  
  2172  			fn(b)
  2173  			b.ReportMetric(float64(atomic.LoadInt64(&count))/float64(b.N), "concurrent_launches/op")
  2174  		}
  2175  	}
  2176  
  2177  	benchWriteTo := func(b *testing.B) {
  2178  		goroutineProf := Lookup("goroutine")
  2179  		b.ResetTimer()
  2180  		for i := 0; i < b.N; i++ {
  2181  			goroutineProf.WriteTo(io.Discard, 0)
  2182  		}
  2183  		b.StopTimer()
  2184  	}
  2185  
  2186  	benchGoroutineProfile := func(b *testing.B) {
  2187  		p := make([]runtime.StackRecord, 10000)
  2188  		b.ResetTimer()
  2189  		for i := 0; i < b.N; i++ {
  2190  			runtime.GoroutineProfile(p)
  2191  		}
  2192  		b.StopTimer()
  2193  	}
  2194  
  2195  	// Note that some costs of collecting a goroutine profile depend on the
  2196  	// length of the runtime.allgs slice, which never shrinks. Stay within race
  2197  	// detector's 8k-goroutine limit
  2198  	for _, n := range []int{50, 500, 5000} {
  2199  		b.Run(fmt.Sprintf("Profile.WriteTo idle %d", n), withIdle(n, benchWriteTo))
  2200  		b.Run(fmt.Sprintf("Profile.WriteTo churn %d", n), withIdle(n, withChurn(benchWriteTo)))
  2201  		b.Run(fmt.Sprintf("runtime.GoroutineProfile churn %d", n), withIdle(n, withChurn(benchGoroutineProfile)))
  2202  	}
  2203  }
  2204  
  2205  var emptyCallStackTestRun int64
  2206  
  2207  // Issue 18836.
  2208  func TestEmptyCallStack(t *testing.T) {
  2209  	name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun)
  2210  	emptyCallStackTestRun++
  2211  
  2212  	t.Parallel()
  2213  	var buf strings.Builder
  2214  	p := NewProfile(name)
  2215  
  2216  	p.Add("foo", 47674)
  2217  	p.WriteTo(&buf, 1)
  2218  	p.Remove("foo")
  2219  	got := buf.String()
  2220  	prefix := name + " profile: total 1\n"
  2221  	if !strings.HasPrefix(got, prefix) {
  2222  		t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix)
  2223  	}
  2224  	lostevent := "lostProfileEvent"
  2225  	if !strings.Contains(got, lostevent) {
  2226  		t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent)
  2227  	}
  2228  }
  2229  
  2230  // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key
  2231  // and value and has funcname somewhere in the stack.
  2232  func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
  2233  	base, kv, ok := strings.Cut(spec, ";")
  2234  	if !ok {
  2235  		panic("no semicolon in key/value spec")
  2236  	}
  2237  	k, v, ok := strings.Cut(kv, "=")
  2238  	if !ok {
  2239  		panic("missing = in key/value spec")
  2240  	}
  2241  	if !slices.Contains(labels[k], v) {
  2242  		return false
  2243  	}
  2244  	return stackContains(base, count, stk, labels)
  2245  }
  2246  
  2247  func TestCPUProfileLabel(t *testing.T) {
  2248  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions())
  2249  	testCPUProfile(t, matches, func(dur time.Duration) {
  2250  		Do(context.Background(), Labels("key", "value"), func(context.Context) {
  2251  			cpuHogger(cpuHog1, &salt1, dur)
  2252  		})
  2253  	})
  2254  }
  2255  
  2256  func TestLabelRace(t *testing.T) {
  2257  	testenv.MustHaveParallelism(t)
  2258  	// Test the race detector annotations for synchronization
  2259  	// between setting labels and consuming them from the
  2260  	// profile.
  2261  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil)
  2262  	testCPUProfile(t, matches, func(dur time.Duration) {
  2263  		start := time.Now()
  2264  		var wg sync.WaitGroup
  2265  		for time.Since(start) < dur {
  2266  			var salts [10]int
  2267  			for i := 0; i < 10; i++ {
  2268  				wg.Add(1)
  2269  				go func(j int) {
  2270  					Do(context.Background(), Labels("key", "value"), func(context.Context) {
  2271  						cpuHogger(cpuHog1, &salts[j], time.Millisecond)
  2272  					})
  2273  					wg.Done()
  2274  				}(i)
  2275  			}
  2276  			wg.Wait()
  2277  		}
  2278  	})
  2279  }
  2280  
  2281  func TestGoroutineProfileLabelRace(t *testing.T) {
  2282  	testenv.MustHaveParallelism(t)
  2283  	// Test the race detector annotations for synchronization
  2284  	// between setting labels and consuming them from the
  2285  	// goroutine profile. See issue #50292.
  2286  
  2287  	t.Run("reset", func(t *testing.T) {
  2288  		ctx := context.Background()
  2289  		ctx, cancel := context.WithCancel(ctx)
  2290  		defer cancel()
  2291  
  2292  		go func() {
  2293  			goroutineProf := Lookup("goroutine")
  2294  			for ctx.Err() == nil {
  2295  				var w strings.Builder
  2296  				goroutineProf.WriteTo(&w, 1)
  2297  				prof := w.String()
  2298  				if strings.Contains(prof, "loop-i") {
  2299  					cancel()
  2300  				}
  2301  			}
  2302  		}()
  2303  
  2304  		for i := 0; ctx.Err() == nil; i++ {
  2305  			Do(ctx, Labels("loop-i", fmt.Sprint(i)), func(ctx context.Context) {
  2306  			})
  2307  		}
  2308  	})
  2309  
  2310  	t.Run("churn", func(t *testing.T) {
  2311  		ctx := context.Background()
  2312  		ctx, cancel := context.WithCancel(ctx)
  2313  		defer cancel()
  2314  
  2315  		var ready sync.WaitGroup
  2316  		ready.Add(1)
  2317  		var churn func(i int)
  2318  		churn = func(i int) {
  2319  			SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
  2320  			if i == 0 {
  2321  				ready.Done()
  2322  			}
  2323  			if ctx.Err() == nil {
  2324  				go churn(i + 1)
  2325  			}
  2326  		}
  2327  		go func() {
  2328  			churn(0)
  2329  		}()
  2330  		ready.Wait()
  2331  
  2332  		goroutineProf := Lookup("goroutine")
  2333  		for i := 0; i < 10; i++ {
  2334  			goroutineProf.WriteTo(io.Discard, 1)
  2335  		}
  2336  	})
  2337  }
  2338  
  2339  // TestLabelSystemstack makes sure CPU profiler samples of goroutines running
  2340  // on systemstack include the correct pprof labels. See issue #48577
  2341  func TestLabelSystemstack(t *testing.T) {
  2342  	// Grab and re-set the initial value before continuing to ensure
  2343  	// GOGC doesn't actually change following the test.
  2344  	gogc := debug.SetGCPercent(100)
  2345  	debug.SetGCPercent(gogc)
  2346  
  2347  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions())
  2348  	p := testCPUProfile(t, matches, func(dur time.Duration) {
  2349  		Do(context.Background(), Labels("key", "value"), func(ctx context.Context) {
  2350  			parallelLabelHog(ctx, dur, gogc)
  2351  		})
  2352  	})
  2353  
  2354  	// Two conditions to check:
  2355  	// * labelHog should always be labeled.
  2356  	// * The label should _only_ appear on labelHog and the Do call above.
  2357  	for _, s := range p.Sample {
  2358  		isLabeled := s.Label != nil && slices.Contains(s.Label["key"], "value")
  2359  		var (
  2360  			mayBeLabeled     bool
  2361  			mustBeLabeled    string
  2362  			mustNotBeLabeled string
  2363  		)
  2364  		for _, loc := range s.Location {
  2365  			for _, l := range loc.Line {
  2366  				switch l.Function.Name {
  2367  				case "runtime/pprof.labelHog", "runtime/pprof.parallelLabelHog", "runtime/pprof.parallelLabelHog.func1":
  2368  					mustBeLabeled = l.Function.Name
  2369  				case "runtime/pprof.Do":
  2370  					// Do sets the labels, so samples may
  2371  					// or may not be labeled depending on
  2372  					// which part of the function they are
  2373  					// at.
  2374  					mayBeLabeled = true
  2375  				case "runtime.bgsweep", "runtime.bgscavenge", "runtime.forcegchelper", "runtime.gcBgMarkWorker", "runtime.runFinalizers", "runtime.runCleanups", "runtime.sysmon":
  2376  					// Runtime system goroutines or threads
  2377  					// (such as those identified by
  2378  					// runtime.isSystemGoroutine). These
  2379  					// should never be labeled.
  2380  					mustNotBeLabeled = l.Function.Name
  2381  				case "gogo", "gosave_systemstack_switch", "racecall":
  2382  					// These are context switch/race
  2383  					// critical that we can't do a full
  2384  					// traceback from. Typically this would
  2385  					// be covered by the runtime check
  2386  					// below, but these symbols don't have
  2387  					// the package name.
  2388  					mayBeLabeled = true
  2389  				}
  2390  
  2391  				if strings.HasPrefix(l.Function.Name, "runtime.") {
  2392  					// There are many places in the runtime
  2393  					// where we can't do a full traceback.
  2394  					// Ideally we'd list them all, but
  2395  					// barring that allow anything in the
  2396  					// runtime, unless explicitly excluded
  2397  					// above.
  2398  					mayBeLabeled = true
  2399  				}
  2400  			}
  2401  		}
  2402  		errorStack := func(f string, args ...any) {
  2403  			var buf strings.Builder
  2404  			fprintStack(&buf, s.Location)
  2405  			t.Errorf("%s: %s", fmt.Sprintf(f, args...), buf.String())
  2406  		}
  2407  		if mustBeLabeled != "" && mustNotBeLabeled != "" {
  2408  			errorStack("sample contains both %s, which must be labeled, and %s, which must not be labeled", mustBeLabeled, mustNotBeLabeled)
  2409  			continue
  2410  		}
  2411  		if mustBeLabeled != "" || mustNotBeLabeled != "" {
  2412  			// We found a definitive frame, so mayBeLabeled hints are not relevant.
  2413  			mayBeLabeled = false
  2414  		}
  2415  		if mayBeLabeled {
  2416  			// This sample may or may not be labeled, so there's nothing we can check.
  2417  			continue
  2418  		}
  2419  		if mustBeLabeled != "" && !isLabeled {
  2420  			errorStack("sample must be labeled because of %s, but is not", mustBeLabeled)
  2421  		}
  2422  		if mustNotBeLabeled != "" && isLabeled {
  2423  			errorStack("sample must not be labeled because of %s, but is", mustNotBeLabeled)
  2424  		}
  2425  	}
  2426  }
  2427  
  2428  // labelHog is designed to burn CPU time in a way that a high number of CPU
  2429  // samples end up running on systemstack.
  2430  func labelHog(stop chan struct{}, gogc int) {
  2431  	// Regression test for issue 50032. We must give GC an opportunity to
  2432  	// be initially triggered by a labelled goroutine.
  2433  	runtime.GC()
  2434  
  2435  	for i := 0; ; i++ {
  2436  		select {
  2437  		case <-stop:
  2438  			return
  2439  		default:
  2440  			debug.SetGCPercent(gogc)
  2441  		}
  2442  	}
  2443  }
  2444  
  2445  // parallelLabelHog runs GOMAXPROCS goroutines running labelHog.
  2446  func parallelLabelHog(ctx context.Context, dur time.Duration, gogc int) {
  2447  	var wg sync.WaitGroup
  2448  	stop := make(chan struct{})
  2449  	for i := 0; i < runtime.GOMAXPROCS(0); i++ {
  2450  		wg.Add(1)
  2451  		go func() {
  2452  			defer wg.Done()
  2453  			labelHog(stop, gogc)
  2454  		}()
  2455  	}
  2456  
  2457  	time.Sleep(dur)
  2458  	close(stop)
  2459  	wg.Wait()
  2460  }
  2461  
  2462  // Check that there is no deadlock when the program receives SIGPROF while in
  2463  // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146.
  2464  func TestAtomicLoadStore64(t *testing.T) {
  2465  	f, err := os.CreateTemp("", "profatomic")
  2466  	if err != nil {
  2467  		t.Fatalf("TempFile: %v", err)
  2468  	}
  2469  	defer os.Remove(f.Name())
  2470  	defer f.Close()
  2471  
  2472  	if err := StartCPUProfile(f); err != nil {
  2473  		t.Fatal(err)
  2474  	}
  2475  	defer StopCPUProfile()
  2476  
  2477  	var flag uint64
  2478  	done := make(chan bool, 1)
  2479  
  2480  	go func() {
  2481  		for atomic.LoadUint64(&flag) == 0 {
  2482  			runtime.Gosched()
  2483  		}
  2484  		done <- true
  2485  	}()
  2486  	time.Sleep(50 * time.Millisecond)
  2487  	atomic.StoreUint64(&flag, 1)
  2488  	<-done
  2489  }
  2490  
  2491  func TestTracebackAll(t *testing.T) {
  2492  	// With gccgo, if a profiling signal arrives at the wrong time
  2493  	// during traceback, it may crash or hang. See issue #29448.
  2494  	f, err := os.CreateTemp("", "proftraceback")
  2495  	if err != nil {
  2496  		t.Fatalf("TempFile: %v", err)
  2497  	}
  2498  	defer os.Remove(f.Name())
  2499  	defer f.Close()
  2500  
  2501  	if err := StartCPUProfile(f); err != nil {
  2502  		t.Fatal(err)
  2503  	}
  2504  	defer StopCPUProfile()
  2505  
  2506  	ch := make(chan int)
  2507  	defer close(ch)
  2508  
  2509  	count := 10
  2510  	for i := 0; i < count; i++ {
  2511  		go func() {
  2512  			<-ch // block
  2513  		}()
  2514  	}
  2515  
  2516  	N := 10000
  2517  	if testing.Short() {
  2518  		N = 500
  2519  	}
  2520  	buf := make([]byte, 10*1024)
  2521  	for i := 0; i < N; i++ {
  2522  		runtime.Stack(buf, true)
  2523  	}
  2524  }
  2525  
  2526  // TestTryAdd tests the cases that are hard to test with real program execution.
  2527  //
  2528  // For example, the current go compilers may not always inline functions
  2529  // involved in recursion but that may not be true in the future compilers. This
  2530  // tests such cases by using fake call sequences and forcing the profile build
  2531  // utilizing translateCPUProfile defined in proto_test.go
  2532  func TestTryAdd(t *testing.T) {
  2533  	if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found {
  2534  		t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.")
  2535  	}
  2536  
  2537  	// inlinedCallerDump
  2538  	//   inlinedCalleeDump
  2539  	pcs := make([]uintptr, 2)
  2540  	inlinedCallerDump(pcs)
  2541  	inlinedCallerStack := make([]uint64, 2)
  2542  	for i := range pcs {
  2543  		inlinedCallerStack[i] = uint64(pcs[i])
  2544  	}
  2545  	wrapperPCs := make([]uintptr, 1)
  2546  	inlinedWrapperCallerDump(wrapperPCs)
  2547  
  2548  	if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found {
  2549  		t.Skip("Can't determine whether anything was inlined into recursionChainBottom.")
  2550  	}
  2551  
  2552  	// recursionChainTop
  2553  	//   recursionChainMiddle
  2554  	//     recursionChainBottom
  2555  	//       recursionChainTop
  2556  	//         recursionChainMiddle
  2557  	//           recursionChainBottom
  2558  	pcs = make([]uintptr, 6)
  2559  	recursionChainTop(1, pcs)
  2560  	recursionStack := make([]uint64, len(pcs))
  2561  	for i := range pcs {
  2562  		recursionStack[i] = uint64(pcs[i])
  2563  	}
  2564  
  2565  	period := int64(2000 * 1000) // 1/500*1e9 nanosec.
  2566  
  2567  	testCases := []struct {
  2568  		name        string
  2569  		input       []uint64          // following the input format assumed by profileBuilder.addCPUData.
  2570  		count       int               // number of records in input.
  2571  		wantLocs    [][]string        // ordered location entries with function names.
  2572  		wantSamples []*profile.Sample // ordered samples, we care only about Value and the profile location IDs.
  2573  	}{{
  2574  		// Sanity test for a normal, complete stack trace.
  2575  		name: "full_stack_trace",
  2576  		input: []uint64{
  2577  			3, 0, 500, // hz = 500. Must match the period.
  2578  			5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
  2579  		},
  2580  		count: 2,
  2581  		wantLocs: [][]string{
  2582  			{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
  2583  		},
  2584  		wantSamples: []*profile.Sample{
  2585  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  2586  		},
  2587  	}, {
  2588  		name: "bug35538",
  2589  		input: []uint64{
  2590  			3, 0, 500, // hz = 500. Must match the period.
  2591  			// Fake frame: tryAdd will have inlinedCallerDump
  2592  			// (stack[1]) on the deck when it encounters the next
  2593  			// inline function. It should accept this.
  2594  			7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1],
  2595  			5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1],
  2596  		},
  2597  		count:    3,
  2598  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2599  		wantSamples: []*profile.Sample{
  2600  			{Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}},
  2601  			{Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}},
  2602  		},
  2603  	}, {
  2604  		name: "bug38096",
  2605  		input: []uint64{
  2606  			3, 0, 500, // hz = 500. Must match the period.
  2607  			// count (data[2]) == 0 && len(stk) == 1 is an overflow
  2608  			// entry. The "stk" entry is actually the count.
  2609  			4, 0, 0, 4242,
  2610  		},
  2611  		count:    2,
  2612  		wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}},
  2613  		wantSamples: []*profile.Sample{
  2614  			{Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}},
  2615  		},
  2616  	}, {
  2617  		// If a function is directly called recursively then it must
  2618  		// not be inlined in the caller.
  2619  		//
  2620  		// N.B. We're generating an impossible profile here, with a
  2621  		// recursive inlineCalleeDump call. This is simulating a non-Go
  2622  		// function that looks like an inlined Go function other than
  2623  		// its recursive property. See pcDeck.tryAdd.
  2624  		name: "directly_recursive_func_is_not_inlined",
  2625  		input: []uint64{
  2626  			3, 0, 500, // hz = 500. Must match the period.
  2627  			5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0],
  2628  			4, 0, 40, inlinedCallerStack[0],
  2629  		},
  2630  		count: 3,
  2631  		// inlinedCallerDump shows up here because
  2632  		// runtime_expandFinalInlineFrame adds it to the stack frame.
  2633  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}},
  2634  		wantSamples: []*profile.Sample{
  2635  			{Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}},
  2636  			{Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}},
  2637  		},
  2638  	}, {
  2639  		name: "recursion_chain_inline",
  2640  		input: []uint64{
  2641  			3, 0, 500, // hz = 500. Must match the period.
  2642  			9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5],
  2643  		},
  2644  		count: 2,
  2645  		wantLocs: [][]string{
  2646  			{"runtime/pprof.recursionChainBottom"},
  2647  			{
  2648  				"runtime/pprof.recursionChainMiddle",
  2649  				"runtime/pprof.recursionChainTop",
  2650  				"runtime/pprof.recursionChainBottom",
  2651  			},
  2652  			{
  2653  				"runtime/pprof.recursionChainMiddle",
  2654  				"runtime/pprof.recursionChainTop",
  2655  				"runtime/pprof.TestTryAdd", // inlined into the test.
  2656  			},
  2657  		},
  2658  		wantSamples: []*profile.Sample{
  2659  			{Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}},
  2660  		},
  2661  	}, {
  2662  		name: "truncated_stack_trace_later",
  2663  		input: []uint64{
  2664  			3, 0, 500, // hz = 500. Must match the period.
  2665  			5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
  2666  			4, 0, 60, inlinedCallerStack[0],
  2667  		},
  2668  		count:    3,
  2669  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2670  		wantSamples: []*profile.Sample{
  2671  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  2672  			{Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}},
  2673  		},
  2674  	}, {
  2675  		name: "truncated_stack_trace_first",
  2676  		input: []uint64{
  2677  			3, 0, 500, // hz = 500. Must match the period.
  2678  			4, 0, 70, inlinedCallerStack[0],
  2679  			5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1],
  2680  		},
  2681  		count:    3,
  2682  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2683  		wantSamples: []*profile.Sample{
  2684  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  2685  			{Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}},
  2686  		},
  2687  	}, {
  2688  		// We can recover the inlined caller from a truncated stack.
  2689  		name: "truncated_stack_trace_only",
  2690  		input: []uint64{
  2691  			3, 0, 500, // hz = 500. Must match the period.
  2692  			4, 0, 70, inlinedCallerStack[0],
  2693  		},
  2694  		count:    2,
  2695  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2696  		wantSamples: []*profile.Sample{
  2697  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  2698  		},
  2699  	}, {
  2700  		// The same location is used for duplicated stacks.
  2701  		name: "truncated_stack_trace_twice",
  2702  		input: []uint64{
  2703  			3, 0, 500, // hz = 500. Must match the period.
  2704  			4, 0, 70, inlinedCallerStack[0],
  2705  			// Fake frame: add a fake call to
  2706  			// inlinedCallerDump to prevent this sample
  2707  			// from getting merged into above.
  2708  			5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0],
  2709  		},
  2710  		count: 3,
  2711  		wantLocs: [][]string{
  2712  			{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
  2713  			{"runtime/pprof.inlinedCallerDump"},
  2714  		},
  2715  		wantSamples: []*profile.Sample{
  2716  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  2717  			{Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}},
  2718  		},
  2719  	}, {
  2720  		name: "expand_wrapper_function",
  2721  		input: []uint64{
  2722  			3, 0, 500, // hz = 500. Must match the period.
  2723  			4, 0, 50, uint64(wrapperPCs[0]),
  2724  		},
  2725  		count:    2,
  2726  		wantLocs: [][]string{{"runtime/pprof.inlineWrapper.dump"}},
  2727  		wantSamples: []*profile.Sample{
  2728  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  2729  		},
  2730  	}}
  2731  
  2732  	for _, tc := range testCases {
  2733  		t.Run(tc.name, func(t *testing.T) {
  2734  			p, err := translateCPUProfile(tc.input, tc.count)
  2735  			if err != nil {
  2736  				t.Fatalf("translating profile: %v", err)
  2737  			}
  2738  			t.Logf("Profile: %v\n", p)
  2739  
  2740  			// One location entry with all inlined functions.
  2741  			var gotLoc [][]string
  2742  			for _, loc := range p.Location {
  2743  				var names []string
  2744  				for _, line := range loc.Line {
  2745  					names = append(names, line.Function.Name)
  2746  				}
  2747  				gotLoc = append(gotLoc, names)
  2748  			}
  2749  			if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want {
  2750  				t.Errorf("Got Location = %+v\n\twant %+v", got, want)
  2751  			}
  2752  			// All samples should point to one location.
  2753  			var gotSamples []*profile.Sample
  2754  			for _, sample := range p.Sample {
  2755  				var locs []*profile.Location
  2756  				for _, loc := range sample.Location {
  2757  					locs = append(locs, &profile.Location{ID: loc.ID})
  2758  				}
  2759  				gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs})
  2760  			}
  2761  			if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want {
  2762  				t.Errorf("Got Samples = %+v\n\twant %+v", got, want)
  2763  			}
  2764  		})
  2765  	}
  2766  }
  2767  
  2768  func TestTimeVDSO(t *testing.T) {
  2769  	// Test that time functions have the right stack trace. In particular,
  2770  	// it shouldn't be recursive.
  2771  
  2772  	if runtime.GOOS == "android" {
  2773  		// Flaky on Android, issue 48655. VDSO may not be enabled.
  2774  		testenv.SkipFlaky(t, 48655)
  2775  	}
  2776  
  2777  	matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions())
  2778  	p := testCPUProfile(t, matches, func(dur time.Duration) {
  2779  		t0 := time.Now()
  2780  		for {
  2781  			t := time.Now()
  2782  			if t.Sub(t0) >= dur {
  2783  				return
  2784  			}
  2785  		}
  2786  	})
  2787  
  2788  	// Check for recursive time.now sample.
  2789  	for _, sample := range p.Sample {
  2790  		var seenNow bool
  2791  		for _, loc := range sample.Location {
  2792  			for _, line := range loc.Line {
  2793  				if line.Function.Name == "time.now" {
  2794  					if seenNow {
  2795  						t.Fatalf("unexpected recursive time.now")
  2796  					}
  2797  					seenNow = true
  2798  				}
  2799  			}
  2800  		}
  2801  	}
  2802  }
  2803  
  2804  func TestProfilerStackDepth(t *testing.T) {
  2805  	t.Cleanup(disableSampling())
  2806  
  2807  	const depth = 128
  2808  	go produceProfileEvents(t, depth)
  2809  	awaitBlockedGoroutine(t, "chan receive", "goroutineDeep", 1)
  2810  
  2811  	tests := []struct {
  2812  		profiler string
  2813  		prefix   []string
  2814  	}{
  2815  		{"heap", []string{"runtime/pprof.allocDeep"}},
  2816  		{"block", []string{"runtime.chanrecv1", "runtime/pprof.blockChanDeep"}},
  2817  		{"mutex", []string{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexDeep"}},
  2818  		{"goroutine", []string{"runtime.gopark", "runtime.chanrecv", "runtime.chanrecv1", "runtime/pprof.goroutineDeep"}},
  2819  	}
  2820  
  2821  	for _, test := range tests {
  2822  		t.Run(test.profiler, func(t *testing.T) {
  2823  			var buf bytes.Buffer
  2824  			if err := Lookup(test.profiler).WriteTo(&buf, 0); err != nil {
  2825  				t.Fatalf("failed to write heap profile: %v", err)
  2826  			}
  2827  			p, err := profile.Parse(&buf)
  2828  			if err != nil {
  2829  				t.Fatalf("failed to parse heap profile: %v", err)
  2830  			}
  2831  			t.Logf("Profile = %v", p)
  2832  
  2833  			stks := profileStacks(p)
  2834  			var matchedStacks [][]string
  2835  			for _, stk := range stks {
  2836  				if !hasPrefix(stk, test.prefix) {
  2837  					continue
  2838  				}
  2839  				// We may get multiple stacks which contain the prefix we want, but
  2840  				// which might not have enough frames, e.g. if the profiler hides
  2841  				// some leaf frames that would count against the stack depth limit.
  2842  				// Check for at least one match
  2843  				matchedStacks = append(matchedStacks, stk)
  2844  				if len(stk) != depth {
  2845  					continue
  2846  				}
  2847  				if rootFn, wantFn := stk[depth-1], "runtime/pprof.produceProfileEvents"; rootFn != wantFn {
  2848  					continue
  2849  				}
  2850  				// Found what we wanted
  2851  				return
  2852  			}
  2853  			for _, stk := range matchedStacks {
  2854  				t.Logf("matched stack=%s", stk)
  2855  				if len(stk) != depth {
  2856  					t.Errorf("want stack depth = %d, got %d", depth, len(stk))
  2857  					continue
  2858  				}
  2859  
  2860  				if rootFn, wantFn := stk[depth-1], "runtime/pprof.allocDeep"; rootFn != wantFn {
  2861  					t.Errorf("want stack stack root %s, got %v", wantFn, rootFn)
  2862  				}
  2863  			}
  2864  		})
  2865  	}
  2866  }
  2867  
  2868  func hasPrefix(stk []string, prefix []string) bool {
  2869  	return len(prefix) <= len(stk) && slices.Equal(stk[:len(prefix)], prefix)
  2870  }
  2871  
  2872  // ensure that stack records are valid map keys (comparable)
  2873  var _ = map[runtime.MemProfileRecord]struct{}{}
  2874  var _ = map[runtime.StackRecord]struct{}{}
  2875  
  2876  // allocDeep calls itself n times before calling fn.
  2877  func allocDeep(n int) {
  2878  	if n > 1 {
  2879  		allocDeep(n - 1)
  2880  		return
  2881  	}
  2882  	memSink = make([]byte, 1<<20)
  2883  }
  2884  
  2885  // blockChanDeep produces a block profile event at stack depth n, including the
  2886  // caller.
  2887  func blockChanDeep(t *testing.T, n int) {
  2888  	if n > 1 {
  2889  		blockChanDeep(t, n-1)
  2890  		return
  2891  	}
  2892  	ch := make(chan struct{})
  2893  	go func() {
  2894  		awaitBlockedGoroutine(t, "chan receive", "blockChanDeep", 1)
  2895  		ch <- struct{}{}
  2896  	}()
  2897  	<-ch
  2898  }
  2899  
  2900  // blockMutexDeep produces a block profile event at stack depth n, including the
  2901  // caller.
  2902  func blockMutexDeep(t *testing.T, n int) {
  2903  	if n > 1 {
  2904  		blockMutexDeep(t, n-1)
  2905  		return
  2906  	}
  2907  	var mu sync.Mutex
  2908  	go func() {
  2909  		mu.Lock()
  2910  		mu.Lock()
  2911  	}()
  2912  	awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutexDeep", 1)
  2913  	mu.Unlock()
  2914  }
  2915  
  2916  // goroutineDeep blocks at stack depth n, including the caller until the test is
  2917  // finished.
  2918  func goroutineDeep(t *testing.T, n int) {
  2919  	if n > 1 {
  2920  		goroutineDeep(t, n-1)
  2921  		return
  2922  	}
  2923  	wait := make(chan struct{}, 1)
  2924  	t.Cleanup(func() {
  2925  		wait <- struct{}{}
  2926  	})
  2927  	<-wait
  2928  }
  2929  
  2930  // produceProfileEvents produces pprof events at the given stack depth and then
  2931  // blocks in goroutineDeep until the test completes. The stack traces are
  2932  // guaranteed to have exactly the desired depth with produceProfileEvents as
  2933  // their root frame which is expected by TestProfilerStackDepth.
  2934  func produceProfileEvents(t *testing.T, depth int) {
  2935  	allocDeep(depth - 1)       // -1 for produceProfileEvents, **
  2936  	blockChanDeep(t, depth-2)  // -2 for produceProfileEvents, **, chanrecv1
  2937  	blockMutexDeep(t, depth-2) // -2 for produceProfileEvents, **, Unlock
  2938  	memSink = nil
  2939  	runtime.GC()
  2940  	goroutineDeep(t, depth-4) // -4 for produceProfileEvents, **, chanrecv1, chanrev, gopark
  2941  }
  2942  
  2943  func getProfileStacks(collect func([]runtime.BlockProfileRecord) (int, bool), fileLine bool, pcs bool) []string {
  2944  	var n int
  2945  	var ok bool
  2946  	var p []runtime.BlockProfileRecord
  2947  	for {
  2948  		p = make([]runtime.BlockProfileRecord, n)
  2949  		n, ok = collect(p)
  2950  		if ok {
  2951  			p = p[:n]
  2952  			break
  2953  		}
  2954  	}
  2955  	var stacks []string
  2956  	for _, r := range p {
  2957  		var stack strings.Builder
  2958  		for i, pc := range r.Stack() {
  2959  			if i > 0 {
  2960  				stack.WriteByte('\n')
  2961  			}
  2962  			if pcs {
  2963  				fmt.Fprintf(&stack, "%x ", pc)
  2964  			}
  2965  			// Use FuncForPC instead of CallersFrames,
  2966  			// because we want to see the info for exactly
  2967  			// the PCs returned by the mutex profile to
  2968  			// ensure inlined calls have already been properly
  2969  			// expanded.
  2970  			f := runtime.FuncForPC(pc - 1)
  2971  			stack.WriteString(f.Name())
  2972  			if fileLine {
  2973  				stack.WriteByte(' ')
  2974  				file, line := f.FileLine(pc - 1)
  2975  				stack.WriteString(file)
  2976  				stack.WriteByte(':')
  2977  				stack.WriteString(strconv.Itoa(line))
  2978  			}
  2979  		}
  2980  		stacks = append(stacks, stack.String())
  2981  	}
  2982  	return stacks
  2983  }
  2984  
  2985  func TestMutexBlockFullAggregation(t *testing.T) {
  2986  	// This regression test is adapted from
  2987  	// https://github.com/grafana/pyroscope-go/issues/103,
  2988  	// authored by Tolya Korniltsev
  2989  
  2990  	var m sync.Mutex
  2991  
  2992  	prev := runtime.SetMutexProfileFraction(-1)
  2993  	defer runtime.SetMutexProfileFraction(prev)
  2994  
  2995  	const fraction = 1
  2996  	const iters = 100
  2997  	const workers = 2
  2998  
  2999  	runtime.SetMutexProfileFraction(fraction)
  3000  	runtime.SetBlockProfileRate(1)
  3001  	defer runtime.SetBlockProfileRate(0)
  3002  
  3003  	wg := sync.WaitGroup{}
  3004  	wg.Add(workers)
  3005  	for range workers {
  3006  		go func() {
  3007  			for range iters {
  3008  				m.Lock()
  3009  				// Wait at least 1 millisecond to pass the
  3010  				// starvation threshold for the mutex
  3011  				time.Sleep(time.Millisecond)
  3012  				m.Unlock()
  3013  			}
  3014  			wg.Done()
  3015  		}()
  3016  	}
  3017  	wg.Wait()
  3018  
  3019  	assertNoDuplicates := func(name string, collect func([]runtime.BlockProfileRecord) (int, bool)) {
  3020  		stacks := getProfileStacks(collect, true, true)
  3021  		seen := make(map[string]struct{})
  3022  		for _, s := range stacks {
  3023  			if _, ok := seen[s]; ok {
  3024  				t.Errorf("saw duplicate entry in %s profile with stack:\n%s", name, s)
  3025  			}
  3026  			seen[s] = struct{}{}
  3027  		}
  3028  		if len(seen) == 0 {
  3029  			t.Errorf("did not see any samples in %s profile for this test", name)
  3030  		}
  3031  	}
  3032  	t.Run("mutex", func(t *testing.T) {
  3033  		assertNoDuplicates("mutex", runtime.MutexProfile)
  3034  	})
  3035  	t.Run("block", func(t *testing.T) {
  3036  		assertNoDuplicates("block", runtime.BlockProfile)
  3037  	})
  3038  }
  3039  
  3040  func inlineA(mu *sync.Mutex, wg *sync.WaitGroup) { inlineB(mu, wg) }
  3041  func inlineB(mu *sync.Mutex, wg *sync.WaitGroup) { inlineC(mu, wg) }
  3042  func inlineC(mu *sync.Mutex, wg *sync.WaitGroup) {
  3043  	defer wg.Done()
  3044  	mu.Lock()
  3045  	mu.Unlock()
  3046  }
  3047  
  3048  func inlineD(mu *sync.Mutex, wg *sync.WaitGroup) { inlineE(mu, wg) }
  3049  func inlineE(mu *sync.Mutex, wg *sync.WaitGroup) { inlineF(mu, wg) }
  3050  func inlineF(mu *sync.Mutex, wg *sync.WaitGroup) {
  3051  	defer wg.Done()
  3052  	mu.Unlock()
  3053  }
  3054  
  3055  func TestBlockMutexProfileInlineExpansion(t *testing.T) {
  3056  	runtime.SetBlockProfileRate(1)
  3057  	defer runtime.SetBlockProfileRate(0)
  3058  	prev := runtime.SetMutexProfileFraction(1)
  3059  	defer runtime.SetMutexProfileFraction(prev)
  3060  
  3061  	var mu sync.Mutex
  3062  	var wg sync.WaitGroup
  3063  	wg.Add(2)
  3064  	mu.Lock()
  3065  	go inlineA(&mu, &wg)
  3066  	awaitBlockedGoroutine(t, "sync.Mutex.Lock", "inlineC", 1)
  3067  	// inlineD will unblock inlineA
  3068  	go inlineD(&mu, &wg)
  3069  	wg.Wait()
  3070  
  3071  	tcs := []struct {
  3072  		Name     string
  3073  		Collect  func([]runtime.BlockProfileRecord) (int, bool)
  3074  		SubStack string
  3075  	}{
  3076  		{
  3077  			Name:    "mutex",
  3078  			Collect: runtime.MutexProfile,
  3079  			SubStack: `sync.(*Mutex).Unlock
  3080  runtime/pprof.inlineF
  3081  runtime/pprof.inlineE
  3082  runtime/pprof.inlineD`,
  3083  		},
  3084  		{
  3085  			Name:    "block",
  3086  			Collect: runtime.BlockProfile,
  3087  			SubStack: `sync.(*Mutex).Lock
  3088  runtime/pprof.inlineC
  3089  runtime/pprof.inlineB
  3090  runtime/pprof.inlineA`,
  3091  		},
  3092  	}
  3093  
  3094  	for _, tc := range tcs {
  3095  		t.Run(tc.Name, func(t *testing.T) {
  3096  			stacks := getProfileStacks(tc.Collect, false, false)
  3097  			for _, s := range stacks {
  3098  				if strings.Contains(s, tc.SubStack) {
  3099  					return
  3100  				}
  3101  			}
  3102  			t.Error("did not see expected stack")
  3103  			t.Logf("wanted:\n%s", tc.SubStack)
  3104  			t.Logf("got: %s", stacks)
  3105  		})
  3106  	}
  3107  }
  3108  
  3109  func TestProfileRecordNullPadding(t *testing.T) {
  3110  	// Produce events for the different profile types.
  3111  	t.Cleanup(disableSampling())
  3112  	memSink = make([]byte, 1)      // MemProfile
  3113  	<-time.After(time.Millisecond) // BlockProfile
  3114  	blockMutex(t)                  // MutexProfile
  3115  	runtime.GC()
  3116  
  3117  	// Test that all profile records are null padded.
  3118  	testProfileRecordNullPadding(t, "MutexProfile", runtime.MutexProfile)
  3119  	testProfileRecordNullPadding(t, "GoroutineProfile", runtime.GoroutineProfile)
  3120  	testProfileRecordNullPadding(t, "BlockProfile", runtime.BlockProfile)
  3121  	testProfileRecordNullPadding(t, "MemProfile/inUseZero=true", func(p []runtime.MemProfileRecord) (int, bool) {
  3122  		return runtime.MemProfile(p, true)
  3123  	})
  3124  	testProfileRecordNullPadding(t, "MemProfile/inUseZero=false", func(p []runtime.MemProfileRecord) (int, bool) {
  3125  		return runtime.MemProfile(p, false)
  3126  	})
  3127  	// Not testing ThreadCreateProfile because it is broken, see issue 6104.
  3128  }
  3129  
  3130  func testProfileRecordNullPadding[T runtime.StackRecord | runtime.MemProfileRecord | runtime.BlockProfileRecord](t *testing.T, name string, fn func([]T) (int, bool)) {
  3131  	stack0 := func(sr *T) *[32]uintptr {
  3132  		switch t := any(sr).(type) {
  3133  		case *runtime.StackRecord:
  3134  			return &t.Stack0
  3135  		case *runtime.MemProfileRecord:
  3136  			return &t.Stack0
  3137  		case *runtime.BlockProfileRecord:
  3138  			return &t.Stack0
  3139  		default:
  3140  			panic(fmt.Sprintf("unexpected type %T", sr))
  3141  		}
  3142  	}
  3143  
  3144  	t.Run(name, func(t *testing.T) {
  3145  		var p []T
  3146  		for {
  3147  			n, ok := fn(p)
  3148  			if ok {
  3149  				p = p[:n]
  3150  				break
  3151  			}
  3152  			p = make([]T, n*2)
  3153  			for i := range p {
  3154  				s0 := stack0(&p[i])
  3155  				for j := range s0 {
  3156  					// Poison the Stack0 array to identify lack of zero padding
  3157  					s0[j] = ^uintptr(0)
  3158  				}
  3159  			}
  3160  		}
  3161  
  3162  		if len(p) == 0 {
  3163  			t.Fatal("no records found")
  3164  		}
  3165  
  3166  		for _, sr := range p {
  3167  			for i, v := range stack0(&sr) {
  3168  				if v == ^uintptr(0) {
  3169  					t.Fatalf("record p[%d].Stack0 is not null padded: %+v", i, sr)
  3170  				}
  3171  			}
  3172  		}
  3173  	})
  3174  }
  3175  
  3176  // disableSampling configures the profilers to capture all events, otherwise
  3177  // it's difficult to assert anything.
  3178  func disableSampling() func() {
  3179  	oldMemRate := runtime.MemProfileRate
  3180  	runtime.MemProfileRate = 1
  3181  	runtime.SetBlockProfileRate(1)
  3182  	oldMutexRate := runtime.SetMutexProfileFraction(1)
  3183  	return func() {
  3184  		runtime.MemProfileRate = oldMemRate
  3185  		runtime.SetBlockProfileRate(0)
  3186  		runtime.SetMutexProfileFraction(oldMutexRate)
  3187  	}
  3188  }
  3189  

View as plain text