github.com/lovishpuri/go-40569/src@v0.0.0-20230519171745-f8623e7c56cf/runtime/pprof/pprof_test.go (about)

     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/syscall/unix"
    16  	"internal/testenv"
    17  	"io"
    18  	"math"
    19  	"math/big"
    20  	"os"
    21  	"os/exec"
    22  	"regexp"
    23  	"runtime"
    24  	"runtime/debug"
    25  	"strings"
    26  	"sync"
    27  	"sync/atomic"
    28  	"testing"
    29  	"time"
    30  	_ "unsafe"
    31  )
    32  
    33  func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
    34  	// We only need to get one 100 Hz clock tick, so we've got
    35  	// a large safety buffer.
    36  	// But do at least 500 iterations (which should take about 100ms),
    37  	// otherwise TestCPUProfileMultithreaded can fail if only one
    38  	// thread is scheduled during the testing period.
    39  	t0 := time.Now()
    40  	accum := *y
    41  	for i := 0; i < 500 || time.Since(t0) < dur; i++ {
    42  		accum = f(accum)
    43  	}
    44  	*y = accum
    45  }
    46  
    47  var (
    48  	salt1 = 0
    49  	salt2 = 0
    50  )
    51  
    52  // The actual CPU hogging function.
    53  // Must not call other functions nor access heap/globals in the loop,
    54  // otherwise under race detector the samples will be in the race runtime.
    55  func cpuHog1(x int) int {
    56  	return cpuHog0(x, 1e5)
    57  }
    58  
    59  func cpuHog0(x, n int) int {
    60  	foo := x
    61  	for i := 0; i < n; i++ {
    62  		if foo > 0 {
    63  			foo *= foo
    64  		} else {
    65  			foo *= foo + 1
    66  		}
    67  	}
    68  	return foo
    69  }
    70  
    71  func cpuHog2(x int) int {
    72  	foo := x
    73  	for i := 0; i < 1e5; i++ {
    74  		if foo > 0 {
    75  			foo *= foo
    76  		} else {
    77  			foo *= foo + 2
    78  		}
    79  	}
    80  	return foo
    81  }
    82  
    83  // Return a list of functions that we don't want to ever appear in CPU
    84  // profiles. For gccgo, that list includes the sigprof handler itself.
    85  func avoidFunctions() []string {
    86  	if runtime.Compiler == "gccgo" {
    87  		return []string{"runtime.sigprof"}
    88  	}
    89  	return nil
    90  }
    91  
    92  func TestCPUProfile(t *testing.T) {
    93  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
    94  	testCPUProfile(t, matches, func(dur time.Duration) {
    95  		cpuHogger(cpuHog1, &salt1, dur)
    96  	})
    97  }
    98  
    99  func TestCPUProfileMultithreaded(t *testing.T) {
   100  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
   101  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions())
   102  	testCPUProfile(t, matches, func(dur time.Duration) {
   103  		c := make(chan int)
   104  		go func() {
   105  			cpuHogger(cpuHog1, &salt1, dur)
   106  			c <- 1
   107  		}()
   108  		cpuHogger(cpuHog2, &salt2, dur)
   109  		<-c
   110  	})
   111  }
   112  
   113  func TestCPUProfileMultithreadMagnitude(t *testing.T) {
   114  	if runtime.GOOS != "linux" {
   115  		t.Skip("issue 35057 is only confirmed on Linux")
   116  	}
   117  
   118  	// Linux [5.9,5.16) has a kernel bug that can break CPU timers on newly
   119  	// created threads, breaking our CPU accounting.
   120  	major, minor := unix.KernelVersion()
   121  	t.Logf("Running on Linux %d.%d", major, minor)
   122  	defer func() {
   123  		if t.Failed() {
   124  			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.")
   125  		}
   126  	}()
   127  
   128  	// Disable on affected builders to avoid flakiness, but otherwise keep
   129  	// it enabled to potentially warn users that they are on a broken
   130  	// kernel.
   131  	if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") {
   132  		have59 := major > 5 || (major == 5 && minor >= 9)
   133  		have516 := major > 5 || (major == 5 && minor >= 16)
   134  		if have59 && !have516 {
   135  			testenv.SkipFlaky(t, 49065)
   136  		}
   137  	}
   138  
   139  	// Run a workload in a single goroutine, then run copies of the same
   140  	// workload in several goroutines. For both the serial and parallel cases,
   141  	// the CPU time the process measures with its own profiler should match the
   142  	// total CPU usage that the OS reports.
   143  	//
   144  	// We could also check that increases in parallelism (GOMAXPROCS) lead to a
   145  	// linear increase in the CPU usage reported by both the OS and the
   146  	// profiler, but without a guarantee of exclusive access to CPU resources
   147  	// that is likely to be a flaky test.
   148  
   149  	// Require the smaller value to be within 10%, or 40% in short mode.
   150  	maxDiff := 0.10
   151  	if testing.Short() {
   152  		maxDiff = 0.40
   153  	}
   154  
   155  	compare := func(a, b time.Duration, maxDiff float64) error {
   156  		if a <= 0 || b <= 0 {
   157  			return fmt.Errorf("Expected both time reports to be positive")
   158  		}
   159  
   160  		if a < b {
   161  			a, b = b, a
   162  		}
   163  
   164  		diff := float64(a-b) / float64(a)
   165  		if diff > maxDiff {
   166  			return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100)
   167  		}
   168  
   169  		return nil
   170  	}
   171  
   172  	for _, tc := range []struct {
   173  		name    string
   174  		workers int
   175  	}{
   176  		{
   177  			name:    "serial",
   178  			workers: 1,
   179  		},
   180  		{
   181  			name:    "parallel",
   182  			workers: runtime.GOMAXPROCS(0),
   183  		},
   184  	} {
   185  		// check that the OS's perspective matches what the Go runtime measures.
   186  		t.Run(tc.name, func(t *testing.T) {
   187  			t.Logf("Running with %d workers", tc.workers)
   188  
   189  			var userTime, systemTime time.Duration
   190  			matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
   191  			acceptProfile := func(t *testing.T, p *profile.Profile) bool {
   192  				if !matches(t, p) {
   193  					return false
   194  				}
   195  
   196  				ok := true
   197  				for i, unit := range []string{"count", "nanoseconds"} {
   198  					if have, want := p.SampleType[i].Unit, unit; have != want {
   199  						t.Logf("pN SampleType[%d]; %q != %q", i, have, want)
   200  						ok = false
   201  					}
   202  				}
   203  
   204  				// cpuHog1 called below is the primary source of CPU
   205  				// load, but there may be some background work by the
   206  				// runtime. Since the OS rusage measurement will
   207  				// include all work done by the process, also compare
   208  				// against all samples in our profile.
   209  				var value time.Duration
   210  				for _, sample := range p.Sample {
   211  					value += time.Duration(sample.Value[1]) * time.Nanosecond
   212  				}
   213  
   214  				totalTime := userTime + systemTime
   215  				t.Logf("compare %s user + %s system = %s vs %s", userTime, systemTime, totalTime, value)
   216  				if err := compare(totalTime, value, maxDiff); err != nil {
   217  					t.Logf("compare got %v want nil", err)
   218  					ok = false
   219  				}
   220  
   221  				return ok
   222  			}
   223  
   224  			testCPUProfile(t, acceptProfile, func(dur time.Duration) {
   225  				userTime, systemTime = diffCPUTime(t, func() {
   226  					var wg sync.WaitGroup
   227  					var once sync.Once
   228  					for i := 0; i < tc.workers; i++ {
   229  						wg.Add(1)
   230  						go func() {
   231  							defer wg.Done()
   232  							var salt = 0
   233  							cpuHogger(cpuHog1, &salt, dur)
   234  							once.Do(func() { salt1 = salt })
   235  						}()
   236  					}
   237  					wg.Wait()
   238  				})
   239  			})
   240  		})
   241  	}
   242  }
   243  
   244  // containsInlinedCall reports whether the function body for the function f is
   245  // known to contain an inlined function call within the first maxBytes bytes.
   246  func containsInlinedCall(f any, maxBytes int) bool {
   247  	_, found := findInlinedCall(f, maxBytes)
   248  	return found
   249  }
   250  
   251  // findInlinedCall returns the PC of an inlined function call within
   252  // the function body for the function f if any.
   253  func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) {
   254  	fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f)))
   255  	if fFunc == nil || fFunc.Entry() == 0 {
   256  		panic("failed to locate function entry")
   257  	}
   258  
   259  	for offset := 0; offset < maxBytes; offset++ {
   260  		innerPC := fFunc.Entry() + uintptr(offset)
   261  		inner := runtime.FuncForPC(innerPC)
   262  		if inner == nil {
   263  			// No function known for this PC value.
   264  			// It might simply be misaligned, so keep searching.
   265  			continue
   266  		}
   267  		if inner.Entry() != fFunc.Entry() {
   268  			// Scanned past f and didn't find any inlined functions.
   269  			break
   270  		}
   271  		if inner.Name() != fFunc.Name() {
   272  			// This PC has f as its entry-point, but is not f. Therefore, it must be a
   273  			// function inlined into f.
   274  			return uint64(innerPC), true
   275  		}
   276  	}
   277  
   278  	return 0, false
   279  }
   280  
   281  func TestCPUProfileInlining(t *testing.T) {
   282  	if !containsInlinedCall(inlinedCaller, 4<<10) {
   283  		t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.")
   284  	}
   285  
   286  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions())
   287  	p := testCPUProfile(t, matches, func(dur time.Duration) {
   288  		cpuHogger(inlinedCaller, &salt1, dur)
   289  	})
   290  
   291  	// Check if inlined function locations are encoded correctly. The inlinedCalee and inlinedCaller should be in one location.
   292  	for _, loc := range p.Location {
   293  		hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false
   294  		for _, line := range loc.Line {
   295  			if line.Function.Name == "runtime/pprof.inlinedCallee" {
   296  				hasInlinedCallee = true
   297  			}
   298  			if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" {
   299  				hasInlinedCallerAfterInlinedCallee = true
   300  			}
   301  		}
   302  		if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee {
   303  			t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p)
   304  		}
   305  	}
   306  }
   307  
   308  func inlinedCaller(x int) int {
   309  	x = inlinedCallee(x, 1e5)
   310  	return x
   311  }
   312  
   313  func inlinedCallee(x, n int) int {
   314  	return cpuHog0(x, n)
   315  }
   316  
   317  //go:noinline
   318  func dumpCallers(pcs []uintptr) {
   319  	if pcs == nil {
   320  		return
   321  	}
   322  
   323  	skip := 2 // Callers and dumpCallers
   324  	runtime.Callers(skip, pcs)
   325  }
   326  
   327  //go:noinline
   328  func inlinedCallerDump(pcs []uintptr) {
   329  	inlinedCalleeDump(pcs)
   330  }
   331  
   332  func inlinedCalleeDump(pcs []uintptr) {
   333  	dumpCallers(pcs)
   334  }
   335  
   336  type inlineWrapperInterface interface {
   337  	dump(stack []uintptr)
   338  }
   339  
   340  type inlineWrapper struct {
   341  }
   342  
   343  func (h inlineWrapper) dump(pcs []uintptr) {
   344  	dumpCallers(pcs)
   345  }
   346  
   347  func inlinedWrapperCallerDump(pcs []uintptr) {
   348  	var h inlineWrapperInterface
   349  	h = &inlineWrapper{}
   350  	h.dump(pcs)
   351  }
   352  
   353  func TestCPUProfileRecursion(t *testing.T) {
   354  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions())
   355  	p := testCPUProfile(t, matches, func(dur time.Duration) {
   356  		cpuHogger(recursionCaller, &salt1, dur)
   357  	})
   358  
   359  	// check the Location encoding was not confused by recursive calls.
   360  	for i, loc := range p.Location {
   361  		recursionFunc := 0
   362  		for _, line := range loc.Line {
   363  			if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" {
   364  				recursionFunc++
   365  			}
   366  		}
   367  		if recursionFunc > 1 {
   368  			t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p)
   369  		}
   370  	}
   371  }
   372  
   373  func recursionCaller(x int) int {
   374  	y := recursionCallee(3, x)
   375  	return y
   376  }
   377  
   378  func recursionCallee(n, x int) int {
   379  	if n == 0 {
   380  		return 1
   381  	}
   382  	y := inlinedCallee(x, 1e4)
   383  	return y * recursionCallee(n-1, x)
   384  }
   385  
   386  func recursionChainTop(x int, pcs []uintptr) {
   387  	if x < 0 {
   388  		return
   389  	}
   390  	recursionChainMiddle(x, pcs)
   391  }
   392  
   393  func recursionChainMiddle(x int, pcs []uintptr) {
   394  	recursionChainBottom(x, pcs)
   395  }
   396  
   397  func recursionChainBottom(x int, pcs []uintptr) {
   398  	// This will be called each time, we only care about the last. We
   399  	// can't make this conditional or this function won't be inlined.
   400  	dumpCallers(pcs)
   401  
   402  	recursionChainTop(x-1, pcs)
   403  }
   404  
   405  func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile {
   406  	p, err := profile.Parse(bytes.NewReader(valBytes))
   407  	if err != nil {
   408  		t.Fatal(err)
   409  	}
   410  	for _, sample := range p.Sample {
   411  		count := uintptr(sample.Value[0])
   412  		f(count, sample.Location, sample.Label)
   413  	}
   414  	return p
   415  }
   416  
   417  func cpuProfilingBroken() bool {
   418  	switch runtime.GOOS {
   419  	case "plan9":
   420  		// Profiling unimplemented.
   421  		return true
   422  	case "aix":
   423  		// See https://golang.org/issue/45170.
   424  		return true
   425  	case "ios", "dragonfly", "netbsd", "illumos", "solaris":
   426  		// See https://golang.org/issue/13841.
   427  		return true
   428  	case "openbsd":
   429  		if runtime.GOARCH == "arm" || runtime.GOARCH == "arm64" {
   430  			// See https://golang.org/issue/13841.
   431  			return true
   432  		}
   433  	}
   434  
   435  	return false
   436  }
   437  
   438  // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need,
   439  // as interpreted by matches, and returns the parsed profile.
   440  func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile {
   441  	switch runtime.GOOS {
   442  	case "darwin":
   443  		out, err := exec.Command("uname", "-a").CombinedOutput()
   444  		if err != nil {
   445  			t.Fatal(err)
   446  		}
   447  		vers := string(out)
   448  		t.Logf("uname -a: %v", vers)
   449  	case "plan9":
   450  		t.Skip("skipping on plan9")
   451  	case "wasip1":
   452  		t.Skip("skipping on wasip1")
   453  	}
   454  
   455  	broken := cpuProfilingBroken()
   456  
   457  	deadline, ok := t.Deadline()
   458  	if broken || !ok {
   459  		if broken && testing.Short() {
   460  			// If it's expected to be broken, no point waiting around.
   461  			deadline = time.Now().Add(1 * time.Second)
   462  		} else {
   463  			deadline = time.Now().Add(10 * time.Second)
   464  		}
   465  	}
   466  
   467  	// If we're running a long test, start with a long duration
   468  	// for tests that try to make sure something *doesn't* happen.
   469  	duration := 5 * time.Second
   470  	if testing.Short() {
   471  		duration = 100 * time.Millisecond
   472  	}
   473  
   474  	// Profiling tests are inherently flaky, especially on a
   475  	// loaded system, such as when this test is running with
   476  	// several others under go test std. If a test fails in a way
   477  	// that could mean it just didn't run long enough, try with a
   478  	// longer duration.
   479  	for {
   480  		var prof bytes.Buffer
   481  		if err := StartCPUProfile(&prof); err != nil {
   482  			t.Fatal(err)
   483  		}
   484  		f(duration)
   485  		StopCPUProfile()
   486  
   487  		if p, ok := profileOk(t, matches, prof, duration); ok {
   488  			return p
   489  		}
   490  
   491  		duration *= 2
   492  		if time.Until(deadline) < duration {
   493  			break
   494  		}
   495  		t.Logf("retrying with %s duration", duration)
   496  	}
   497  
   498  	if broken {
   499  		t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH)
   500  	}
   501  
   502  	// Ignore the failure if the tests are running in a QEMU-based emulator,
   503  	// QEMU is not perfect at emulating everything.
   504  	// IN_QEMU environmental variable is set by some of the Go builders.
   505  	// IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
   506  	if os.Getenv("IN_QEMU") == "1" {
   507  		t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
   508  	}
   509  	t.FailNow()
   510  	return nil
   511  }
   512  
   513  var diffCPUTimeImpl func(f func()) (user, system time.Duration)
   514  
   515  func diffCPUTime(t *testing.T, f func()) (user, system time.Duration) {
   516  	if fn := diffCPUTimeImpl; fn != nil {
   517  		return fn(f)
   518  	}
   519  	t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH)
   520  	return 0, 0
   521  }
   522  
   523  func contains(slice []string, s string) bool {
   524  	for i := range slice {
   525  		if slice[i] == s {
   526  			return true
   527  		}
   528  	}
   529  	return false
   530  }
   531  
   532  // stackContains matches if a function named spec appears anywhere in the stack trace.
   533  func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   534  	for _, loc := range stk {
   535  		for _, line := range loc.Line {
   536  			if strings.Contains(line.Function.Name, spec) {
   537  				return true
   538  			}
   539  		}
   540  	}
   541  	return false
   542  }
   543  
   544  type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool
   545  
   546  func profileOk(t *testing.T, matches profileMatchFunc, prof bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) {
   547  	ok = true
   548  
   549  	var samples uintptr
   550  	var buf strings.Builder
   551  	p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) {
   552  		fmt.Fprintf(&buf, "%d:", count)
   553  		fprintStack(&buf, stk)
   554  		fmt.Fprintf(&buf, " labels: %v\n", labels)
   555  		samples += count
   556  		fmt.Fprintf(&buf, "\n")
   557  	})
   558  	t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String())
   559  
   560  	if samples < 10 && runtime.GOOS == "windows" {
   561  		// On some windows machines we end up with
   562  		// not enough samples due to coarse timer
   563  		// resolution. Let it go.
   564  		t.Log("too few samples on Windows (golang.org/issue/10842)")
   565  		return p, false
   566  	}
   567  
   568  	// Check that we got a reasonable number of samples.
   569  	// We used to always require at least ideal/4 samples,
   570  	// but that is too hard to guarantee on a loaded system.
   571  	// Now we accept 10 or more samples, which we take to be
   572  	// enough to show that at least some profiling is occurring.
   573  	if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) {
   574  		t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
   575  		ok = false
   576  	}
   577  
   578  	if matches != nil && !matches(t, p) {
   579  		ok = false
   580  	}
   581  
   582  	return p, ok
   583  }
   584  
   585  type profileMatchFunc func(*testing.T, *profile.Profile) bool
   586  
   587  func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc {
   588  	return func(t *testing.T, p *profile.Profile) (ok bool) {
   589  		ok = true
   590  
   591  		// Check that profile is well formed, contains 'need', and does not contain
   592  		// anything from 'avoid'.
   593  		have := make([]uintptr, len(need))
   594  		avoidSamples := make([]uintptr, len(avoid))
   595  
   596  		for _, sample := range p.Sample {
   597  			count := uintptr(sample.Value[0])
   598  			for i, spec := range need {
   599  				if matches(spec, count, sample.Location, sample.Label) {
   600  					have[i] += count
   601  				}
   602  			}
   603  			for i, name := range avoid {
   604  				for _, loc := range sample.Location {
   605  					for _, line := range loc.Line {
   606  						if strings.Contains(line.Function.Name, name) {
   607  							avoidSamples[i] += count
   608  						}
   609  					}
   610  				}
   611  			}
   612  		}
   613  
   614  		for i, name := range avoid {
   615  			bad := avoidSamples[i]
   616  			if bad != 0 {
   617  				t.Logf("found %d samples in avoid-function %s\n", bad, name)
   618  				ok = false
   619  			}
   620  		}
   621  
   622  		if len(need) == 0 {
   623  			return
   624  		}
   625  
   626  		var total uintptr
   627  		for i, name := range need {
   628  			total += have[i]
   629  			t.Logf("found %d samples in expected function %s\n", have[i], name)
   630  		}
   631  		if total == 0 {
   632  			t.Logf("no samples in expected functions")
   633  			ok = false
   634  		}
   635  
   636  		// We'd like to check a reasonable minimum, like
   637  		// total / len(have) / smallconstant, but this test is
   638  		// pretty flaky (see bug 7095).  So we'll just test to
   639  		// make sure we got at least one sample.
   640  		min := uintptr(1)
   641  		for i, name := range need {
   642  			if have[i] < min {
   643  				t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
   644  				ok = false
   645  			}
   646  		}
   647  		return
   648  	}
   649  }
   650  
   651  // Fork can hang if preempted with signals frequently enough (see issue 5517).
   652  // Ensure that we do not do this.
   653  func TestCPUProfileWithFork(t *testing.T) {
   654  	testenv.MustHaveExec(t)
   655  
   656  	heap := 1 << 30
   657  	if runtime.GOOS == "android" {
   658  		// Use smaller size for Android to avoid crash.
   659  		heap = 100 << 20
   660  	}
   661  	if runtime.GOOS == "windows" && runtime.GOARCH == "arm" {
   662  		// Use smaller heap for Windows/ARM to avoid crash.
   663  		heap = 100 << 20
   664  	}
   665  	if testing.Short() {
   666  		heap = 100 << 20
   667  	}
   668  	// This makes fork slower.
   669  	garbage := make([]byte, heap)
   670  	// Need to touch the slice, otherwise it won't be paged in.
   671  	done := make(chan bool)
   672  	go func() {
   673  		for i := range garbage {
   674  			garbage[i] = 42
   675  		}
   676  		done <- true
   677  	}()
   678  	<-done
   679  
   680  	var prof bytes.Buffer
   681  	if err := StartCPUProfile(&prof); err != nil {
   682  		t.Fatal(err)
   683  	}
   684  	defer StopCPUProfile()
   685  
   686  	for i := 0; i < 10; i++ {
   687  		exec.Command(os.Args[0], "-h").CombinedOutput()
   688  	}
   689  }
   690  
   691  // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
   692  // If it did, it would see inconsistent state and would either record an incorrect stack
   693  // or crash because the stack was malformed.
   694  func TestGoroutineSwitch(t *testing.T) {
   695  	if runtime.Compiler == "gccgo" {
   696  		t.Skip("not applicable for gccgo")
   697  	}
   698  	// How much to try. These defaults take about 1 seconds
   699  	// on a 2012 MacBook Pro. The ones in short mode take
   700  	// about 0.1 seconds.
   701  	tries := 10
   702  	count := 1000000
   703  	if testing.Short() {
   704  		tries = 1
   705  	}
   706  	for try := 0; try < tries; try++ {
   707  		var prof bytes.Buffer
   708  		if err := StartCPUProfile(&prof); err != nil {
   709  			t.Fatal(err)
   710  		}
   711  		for i := 0; i < count; i++ {
   712  			runtime.Gosched()
   713  		}
   714  		StopCPUProfile()
   715  
   716  		// Read profile to look for entries for gogo with an attempt at a traceback.
   717  		// "runtime.gogo" is OK, because that's the part of the context switch
   718  		// before the actual switch begins. But we should not see "gogo",
   719  		// aka "gogo<>(SB)", which does the actual switch and is marked SPWRITE.
   720  		parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) {
   721  			// An entry with two frames with 'System' in its top frame
   722  			// exists to record a PC without a traceback. Those are okay.
   723  			if len(stk) == 2 {
   724  				name := stk[1].Line[0].Function.Name
   725  				if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" {
   726  					return
   727  				}
   728  			}
   729  
   730  			// An entry with just one frame is OK too:
   731  			// it knew to stop at gogo.
   732  			if len(stk) == 1 {
   733  				return
   734  			}
   735  
   736  			// Otherwise, should not see gogo.
   737  			// The place we'd see it would be the inner most frame.
   738  			name := stk[0].Line[0].Function.Name
   739  			if name == "gogo" {
   740  				var buf strings.Builder
   741  				fprintStack(&buf, stk)
   742  				t.Fatalf("found profile entry for gogo:\n%s", buf.String())
   743  			}
   744  		})
   745  	}
   746  }
   747  
   748  func fprintStack(w io.Writer, stk []*profile.Location) {
   749  	if len(stk) == 0 {
   750  		fmt.Fprintf(w, " (stack empty)")
   751  	}
   752  	for _, loc := range stk {
   753  		fmt.Fprintf(w, " %#x", loc.Address)
   754  		fmt.Fprintf(w, " (")
   755  		for i, line := range loc.Line {
   756  			if i > 0 {
   757  				fmt.Fprintf(w, " ")
   758  			}
   759  			fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line)
   760  		}
   761  		fmt.Fprintf(w, ")")
   762  	}
   763  }
   764  
   765  // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
   766  func TestMathBigDivide(t *testing.T) {
   767  	testCPUProfile(t, nil, func(duration time.Duration) {
   768  		t := time.After(duration)
   769  		pi := new(big.Int)
   770  		for {
   771  			for i := 0; i < 100; i++ {
   772  				n := big.NewInt(2646693125139304345)
   773  				d := big.NewInt(842468587426513207)
   774  				pi.Div(n, d)
   775  			}
   776  			select {
   777  			case <-t:
   778  				return
   779  			default:
   780  			}
   781  		}
   782  	})
   783  }
   784  
   785  // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace.
   786  func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   787  	for _, f := range strings.Split(spec, ",") {
   788  		if !stackContains(f, count, stk, labels) {
   789  			return false
   790  		}
   791  	}
   792  	return true
   793  }
   794  
   795  func TestMorestack(t *testing.T) {
   796  	matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions())
   797  	testCPUProfile(t, matches, func(duration time.Duration) {
   798  		t := time.After(duration)
   799  		c := make(chan bool)
   800  		for {
   801  			go func() {
   802  				growstack1()
   803  				c <- true
   804  			}()
   805  			select {
   806  			case <-t:
   807  				return
   808  			case <-c:
   809  			}
   810  		}
   811  	})
   812  }
   813  
   814  //go:noinline
   815  func growstack1() {
   816  	growstack(10)
   817  }
   818  
   819  //go:noinline
   820  func growstack(n int) {
   821  	var buf [8 << 18]byte
   822  	use(buf)
   823  	if n > 0 {
   824  		growstack(n - 1)
   825  	}
   826  }
   827  
   828  //go:noinline
   829  func use(x [8 << 18]byte) {}
   830  
   831  func TestBlockProfile(t *testing.T) {
   832  	type TestCase struct {
   833  		name string
   834  		f    func(*testing.T)
   835  		stk  []string
   836  		re   string
   837  	}
   838  	tests := [...]TestCase{
   839  		{
   840  			name: "chan recv",
   841  			f:    blockChanRecv,
   842  			stk: []string{
   843  				"runtime.chanrecv1",
   844  				"runtime/pprof.blockChanRecv",
   845  				"runtime/pprof.TestBlockProfile",
   846  			},
   847  			re: `
   848  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   849  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*runtime/chan.go:[0-9]+
   850  #	0x[0-9a-f]+	runtime/pprof\.blockChanRecv\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   851  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   852  `},
   853  		{
   854  			name: "chan send",
   855  			f:    blockChanSend,
   856  			stk: []string{
   857  				"runtime.chansend1",
   858  				"runtime/pprof.blockChanSend",
   859  				"runtime/pprof.TestBlockProfile",
   860  			},
   861  			re: `
   862  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   863  #	0x[0-9a-f]+	runtime\.chansend1\+0x[0-9a-f]+	.*runtime/chan.go:[0-9]+
   864  #	0x[0-9a-f]+	runtime/pprof\.blockChanSend\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   865  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   866  `},
   867  		{
   868  			name: "chan close",
   869  			f:    blockChanClose,
   870  			stk: []string{
   871  				"runtime.chanrecv1",
   872  				"runtime/pprof.blockChanClose",
   873  				"runtime/pprof.TestBlockProfile",
   874  			},
   875  			re: `
   876  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   877  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*runtime/chan.go:[0-9]+
   878  #	0x[0-9a-f]+	runtime/pprof\.blockChanClose\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   879  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   880  `},
   881  		{
   882  			name: "select recv async",
   883  			f:    blockSelectRecvAsync,
   884  			stk: []string{
   885  				"runtime.selectgo",
   886  				"runtime/pprof.blockSelectRecvAsync",
   887  				"runtime/pprof.TestBlockProfile",
   888  			},
   889  			re: `
   890  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   891  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*runtime/select.go:[0-9]+
   892  #	0x[0-9a-f]+	runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   893  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   894  `},
   895  		{
   896  			name: "select send sync",
   897  			f:    blockSelectSendSync,
   898  			stk: []string{
   899  				"runtime.selectgo",
   900  				"runtime/pprof.blockSelectSendSync",
   901  				"runtime/pprof.TestBlockProfile",
   902  			},
   903  			re: `
   904  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   905  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*runtime/select.go:[0-9]+
   906  #	0x[0-9a-f]+	runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   907  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   908  `},
   909  		{
   910  			name: "mutex",
   911  			f:    blockMutex,
   912  			stk: []string{
   913  				"sync.(*Mutex).Lock",
   914  				"runtime/pprof.blockMutex",
   915  				"runtime/pprof.TestBlockProfile",
   916  			},
   917  			re: `
   918  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   919  #	0x[0-9a-f]+	sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+	.*sync/mutex\.go:[0-9]+
   920  #	0x[0-9a-f]+	runtime/pprof\.blockMutex\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   921  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   922  `},
   923  		{
   924  			name: "cond",
   925  			f:    blockCond,
   926  			stk: []string{
   927  				"sync.(*Cond).Wait",
   928  				"runtime/pprof.blockCond",
   929  				"runtime/pprof.TestBlockProfile",
   930  			},
   931  			re: `
   932  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   933  #	0x[0-9a-f]+	sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+	.*sync/cond\.go:[0-9]+
   934  #	0x[0-9a-f]+	runtime/pprof\.blockCond\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   935  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*runtime/pprof/pprof_test.go:[0-9]+
   936  `},
   937  	}
   938  
   939  	// Generate block profile
   940  	runtime.SetBlockProfileRate(1)
   941  	defer runtime.SetBlockProfileRate(0)
   942  	for _, test := range tests {
   943  		test.f(t)
   944  	}
   945  
   946  	t.Run("debug=1", func(t *testing.T) {
   947  		var w strings.Builder
   948  		Lookup("block").WriteTo(&w, 1)
   949  		prof := w.String()
   950  
   951  		if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
   952  			t.Fatalf("Bad profile header:\n%v", prof)
   953  		}
   954  
   955  		if strings.HasSuffix(prof, "#\t0x0\n\n") {
   956  			t.Errorf("Useless 0 suffix:\n%v", prof)
   957  		}
   958  
   959  		for _, test := range tests {
   960  			if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) {
   961  				t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
   962  			}
   963  		}
   964  	})
   965  
   966  	t.Run("proto", func(t *testing.T) {
   967  		// proto format
   968  		var w bytes.Buffer
   969  		Lookup("block").WriteTo(&w, 0)
   970  		p, err := profile.Parse(&w)
   971  		if err != nil {
   972  			t.Fatalf("failed to parse profile: %v", err)
   973  		}
   974  		t.Logf("parsed proto: %s", p)
   975  		if err := p.CheckValid(); err != nil {
   976  			t.Fatalf("invalid profile: %v", err)
   977  		}
   978  
   979  		stks := stacks(p)
   980  		for _, test := range tests {
   981  			if !containsStack(stks, test.stk) {
   982  				t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk)
   983  			}
   984  		}
   985  	})
   986  
   987  }
   988  
   989  func stacks(p *profile.Profile) (res [][]string) {
   990  	for _, s := range p.Sample {
   991  		var stk []string
   992  		for _, l := range s.Location {
   993  			for _, line := range l.Line {
   994  				stk = append(stk, line.Function.Name)
   995  			}
   996  		}
   997  		res = append(res, stk)
   998  	}
   999  	return res
  1000  }
  1001  
  1002  func containsStack(got [][]string, want []string) bool {
  1003  	for _, stk := range got {
  1004  		if len(stk) < len(want) {
  1005  			continue
  1006  		}
  1007  		for i, f := range want {
  1008  			if f != stk[i] {
  1009  				break
  1010  			}
  1011  			if i == len(want)-1 {
  1012  				return true
  1013  			}
  1014  		}
  1015  	}
  1016  	return false
  1017  }
  1018  
  1019  // awaitBlockedGoroutine spins on runtime.Gosched until a runtime stack dump
  1020  // shows a goroutine in the given state with a stack frame in
  1021  // runtime/pprof.<fName>.
  1022  func awaitBlockedGoroutine(t *testing.T, state, fName string) {
  1023  	re := fmt.Sprintf(`(?m)^goroutine \d+ \[%s\]:\n(?:.+\n\t.+\n)*runtime/pprof\.%s`, regexp.QuoteMeta(state), fName)
  1024  	r := regexp.MustCompile(re)
  1025  
  1026  	if deadline, ok := t.Deadline(); ok {
  1027  		if d := time.Until(deadline); d > 1*time.Second {
  1028  			timer := time.AfterFunc(d-1*time.Second, func() {
  1029  				debug.SetTraceback("all")
  1030  				panic(fmt.Sprintf("timed out waiting for %#q", re))
  1031  			})
  1032  			defer timer.Stop()
  1033  		}
  1034  	}
  1035  
  1036  	buf := make([]byte, 64<<10)
  1037  	for {
  1038  		runtime.Gosched()
  1039  		n := runtime.Stack(buf, true)
  1040  		if n == len(buf) {
  1041  			// Buffer wasn't large enough for a full goroutine dump.
  1042  			// Resize it and try again.
  1043  			buf = make([]byte, 2*len(buf))
  1044  			continue
  1045  		}
  1046  		if r.Match(buf[:n]) {
  1047  			return
  1048  		}
  1049  	}
  1050  }
  1051  
  1052  func blockChanRecv(t *testing.T) {
  1053  	c := make(chan bool)
  1054  	go func() {
  1055  		awaitBlockedGoroutine(t, "chan receive", "blockChanRecv")
  1056  		c <- true
  1057  	}()
  1058  	<-c
  1059  }
  1060  
  1061  func blockChanSend(t *testing.T) {
  1062  	c := make(chan bool)
  1063  	go func() {
  1064  		awaitBlockedGoroutine(t, "chan send", "blockChanSend")
  1065  		<-c
  1066  	}()
  1067  	c <- true
  1068  }
  1069  
  1070  func blockChanClose(t *testing.T) {
  1071  	c := make(chan bool)
  1072  	go func() {
  1073  		awaitBlockedGoroutine(t, "chan receive", "blockChanClose")
  1074  		close(c)
  1075  	}()
  1076  	<-c
  1077  }
  1078  
  1079  func blockSelectRecvAsync(t *testing.T) {
  1080  	const numTries = 3
  1081  	c := make(chan bool, 1)
  1082  	c2 := make(chan bool, 1)
  1083  	go func() {
  1084  		for i := 0; i < numTries; i++ {
  1085  			awaitBlockedGoroutine(t, "select", "blockSelectRecvAsync")
  1086  			c <- true
  1087  		}
  1088  	}()
  1089  	for i := 0; i < numTries; i++ {
  1090  		select {
  1091  		case <-c:
  1092  		case <-c2:
  1093  		}
  1094  	}
  1095  }
  1096  
  1097  func blockSelectSendSync(t *testing.T) {
  1098  	c := make(chan bool)
  1099  	c2 := make(chan bool)
  1100  	go func() {
  1101  		awaitBlockedGoroutine(t, "select", "blockSelectSendSync")
  1102  		<-c
  1103  	}()
  1104  	select {
  1105  	case c <- true:
  1106  	case c2 <- true:
  1107  	}
  1108  }
  1109  
  1110  func blockMutex(t *testing.T) {
  1111  	var mu sync.Mutex
  1112  	mu.Lock()
  1113  	go func() {
  1114  		awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex")
  1115  		mu.Unlock()
  1116  	}()
  1117  	// Note: Unlock releases mu before recording the mutex event,
  1118  	// so it's theoretically possible for this to proceed and
  1119  	// capture the profile before the event is recorded. As long
  1120  	// as this is blocked before the unlock happens, it's okay.
  1121  	mu.Lock()
  1122  }
  1123  
  1124  func blockCond(t *testing.T) {
  1125  	var mu sync.Mutex
  1126  	c := sync.NewCond(&mu)
  1127  	mu.Lock()
  1128  	go func() {
  1129  		awaitBlockedGoroutine(t, "sync.Cond.Wait", "blockCond")
  1130  		mu.Lock()
  1131  		c.Signal()
  1132  		mu.Unlock()
  1133  	}()
  1134  	c.Wait()
  1135  	mu.Unlock()
  1136  }
  1137  
  1138  // See http://golang.org/cl/299991.
  1139  func TestBlockProfileBias(t *testing.T) {
  1140  	rate := int(1000) // arbitrary value
  1141  	runtime.SetBlockProfileRate(rate)
  1142  	defer runtime.SetBlockProfileRate(0)
  1143  
  1144  	// simulate blocking events
  1145  	blockFrequentShort(rate)
  1146  	blockInfrequentLong(rate)
  1147  
  1148  	var w bytes.Buffer
  1149  	Lookup("block").WriteTo(&w, 0)
  1150  	p, err := profile.Parse(&w)
  1151  	if err != nil {
  1152  		t.Fatalf("failed to parse profile: %v", err)
  1153  	}
  1154  	t.Logf("parsed proto: %s", p)
  1155  
  1156  	il := float64(-1) // blockInfrequentLong duration
  1157  	fs := float64(-1) // blockFrequentShort duration
  1158  	for _, s := range p.Sample {
  1159  		for _, l := range s.Location {
  1160  			for _, line := range l.Line {
  1161  				if len(s.Value) < 2 {
  1162  					t.Fatal("block profile has less than 2 sample types")
  1163  				}
  1164  
  1165  				if line.Function.Name == "runtime/pprof.blockInfrequentLong" {
  1166  					il = float64(s.Value[1])
  1167  				} else if line.Function.Name == "runtime/pprof.blockFrequentShort" {
  1168  					fs = float64(s.Value[1])
  1169  				}
  1170  			}
  1171  		}
  1172  	}
  1173  	if il == -1 || fs == -1 {
  1174  		t.Fatal("block profile is missing expected functions")
  1175  	}
  1176  
  1177  	// stddev of bias from 100 runs on local machine multiplied by 10x
  1178  	const threshold = 0.2
  1179  	if bias := (il - fs) / il; math.Abs(bias) > threshold {
  1180  		t.Fatalf("bias: abs(%f) > %f", bias, threshold)
  1181  	} else {
  1182  		t.Logf("bias: abs(%f) < %f", bias, threshold)
  1183  	}
  1184  }
  1185  
  1186  // blockFrequentShort produces 100000 block events with an average duration of
  1187  // rate / 10.
  1188  func blockFrequentShort(rate int) {
  1189  	for i := 0; i < 100000; i++ {
  1190  		blockevent(int64(rate/10), 1)
  1191  	}
  1192  }
  1193  
  1194  // blockFrequentShort produces 10000 block events with an average duration of
  1195  // rate.
  1196  func blockInfrequentLong(rate int) {
  1197  	for i := 0; i < 10000; i++ {
  1198  		blockevent(int64(rate), 1)
  1199  	}
  1200  }
  1201  
  1202  // Used by TestBlockProfileBias.
  1203  //
  1204  //go:linkname blockevent runtime.blockevent
  1205  func blockevent(cycles int64, skip int)
  1206  
  1207  func TestMutexProfile(t *testing.T) {
  1208  	// Generate mutex profile
  1209  
  1210  	old := runtime.SetMutexProfileFraction(1)
  1211  	defer runtime.SetMutexProfileFraction(old)
  1212  	if old != 0 {
  1213  		t.Fatalf("need MutexProfileRate 0, got %d", old)
  1214  	}
  1215  
  1216  	blockMutex(t)
  1217  
  1218  	t.Run("debug=1", func(t *testing.T) {
  1219  		var w strings.Builder
  1220  		Lookup("mutex").WriteTo(&w, 1)
  1221  		prof := w.String()
  1222  		t.Logf("received profile: %v", prof)
  1223  
  1224  		if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") {
  1225  			t.Errorf("Bad profile header:\n%v", prof)
  1226  		}
  1227  		prof = strings.Trim(prof, "\n")
  1228  		lines := strings.Split(prof, "\n")
  1229  		if len(lines) != 6 {
  1230  			t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof)
  1231  		}
  1232  		if len(lines) < 6 {
  1233  			return
  1234  		}
  1235  		// checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931"
  1236  		r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+`
  1237  		//r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$"
  1238  		if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok {
  1239  			t.Errorf("%q didn't match %q", lines[3], r2)
  1240  		}
  1241  		r3 := "^#.*runtime/pprof.blockMutex.*$"
  1242  		if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok {
  1243  			t.Errorf("%q didn't match %q", lines[5], r3)
  1244  		}
  1245  		t.Logf(prof)
  1246  	})
  1247  	t.Run("proto", func(t *testing.T) {
  1248  		// proto format
  1249  		var w bytes.Buffer
  1250  		Lookup("mutex").WriteTo(&w, 0)
  1251  		p, err := profile.Parse(&w)
  1252  		if err != nil {
  1253  			t.Fatalf("failed to parse profile: %v", err)
  1254  		}
  1255  		t.Logf("parsed proto: %s", p)
  1256  		if err := p.CheckValid(); err != nil {
  1257  			t.Fatalf("invalid profile: %v", err)
  1258  		}
  1259  
  1260  		stks := stacks(p)
  1261  		for _, want := range [][]string{
  1262  			{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutex.func1"},
  1263  		} {
  1264  			if !containsStack(stks, want) {
  1265  				t.Errorf("No matching stack entry for %+v", want)
  1266  			}
  1267  		}
  1268  	})
  1269  }
  1270  
  1271  func TestMutexProfileRateAdjust(t *testing.T) {
  1272  	old := runtime.SetMutexProfileFraction(1)
  1273  	defer runtime.SetMutexProfileFraction(old)
  1274  	if old != 0 {
  1275  		t.Fatalf("need MutexProfileRate 0, got %d", old)
  1276  	}
  1277  
  1278  	readProfile := func() (contentions int64, delay int64) {
  1279  		var w bytes.Buffer
  1280  		Lookup("mutex").WriteTo(&w, 0)
  1281  		p, err := profile.Parse(&w)
  1282  		if err != nil {
  1283  			t.Fatalf("failed to parse profile: %v", err)
  1284  		}
  1285  		t.Logf("parsed proto: %s", p)
  1286  		if err := p.CheckValid(); err != nil {
  1287  			t.Fatalf("invalid profile: %v", err)
  1288  		}
  1289  
  1290  		for _, s := range p.Sample {
  1291  			for _, l := range s.Location {
  1292  				for _, line := range l.Line {
  1293  					if line.Function.Name == "runtime/pprof.blockMutex.func1" {
  1294  						contentions += s.Value[0]
  1295  						delay += s.Value[1]
  1296  					}
  1297  				}
  1298  			}
  1299  		}
  1300  		return
  1301  	}
  1302  
  1303  	blockMutex(t)
  1304  	contentions, delay := readProfile()
  1305  	if contentions == 0 || delay == 0 {
  1306  		t.Fatal("did not see expected function in profile")
  1307  	}
  1308  	runtime.SetMutexProfileFraction(0)
  1309  	newContentions, newDelay := readProfile()
  1310  	if newContentions != contentions || newDelay != delay {
  1311  		t.Fatalf("sample value changed: got [%d, %d], want [%d, %d]", newContentions, newDelay, contentions, delay)
  1312  	}
  1313  }
  1314  
  1315  func func1(c chan int) { <-c }
  1316  func func2(c chan int) { <-c }
  1317  func func3(c chan int) { <-c }
  1318  func func4(c chan int) { <-c }
  1319  
  1320  func TestGoroutineCounts(t *testing.T) {
  1321  	// Setting GOMAXPROCS to 1 ensures we can force all goroutines to the
  1322  	// desired blocking point.
  1323  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
  1324  
  1325  	c := make(chan int)
  1326  	for i := 0; i < 100; i++ {
  1327  		switch {
  1328  		case i%10 == 0:
  1329  			go func1(c)
  1330  		case i%2 == 0:
  1331  			go func2(c)
  1332  		default:
  1333  			go func3(c)
  1334  		}
  1335  		// Let goroutines block on channel
  1336  		for j := 0; j < 5; j++ {
  1337  			runtime.Gosched()
  1338  		}
  1339  	}
  1340  	ctx := context.Background()
  1341  
  1342  	// ... and again, with labels this time (just with fewer iterations to keep
  1343  	// sorting deterministic).
  1344  	Do(ctx, Labels("label", "value"), func(context.Context) {
  1345  		for i := 0; i < 89; i++ {
  1346  			switch {
  1347  			case i%10 == 0:
  1348  				go func1(c)
  1349  			case i%2 == 0:
  1350  				go func2(c)
  1351  			default:
  1352  				go func3(c)
  1353  			}
  1354  			// Let goroutines block on channel
  1355  			for j := 0; j < 5; j++ {
  1356  				runtime.Gosched()
  1357  			}
  1358  		}
  1359  	})
  1360  
  1361  	var w bytes.Buffer
  1362  	goroutineProf := Lookup("goroutine")
  1363  
  1364  	// Check debug profile
  1365  	goroutineProf.WriteTo(&w, 1)
  1366  	prof := w.String()
  1367  
  1368  	labels := labelMap{"label": "value"}
  1369  	labelStr := "\n# labels: " + labels.String()
  1370  	if !containsInOrder(prof, "\n50 @ ", "\n44 @", labelStr,
  1371  		"\n40 @", "\n36 @", labelStr, "\n10 @", "\n9 @", labelStr, "\n1 @") {
  1372  		t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
  1373  	}
  1374  
  1375  	// Check proto profile
  1376  	w.Reset()
  1377  	goroutineProf.WriteTo(&w, 0)
  1378  	p, err := profile.Parse(&w)
  1379  	if err != nil {
  1380  		t.Errorf("error parsing protobuf profile: %v", err)
  1381  	}
  1382  	if err := p.CheckValid(); err != nil {
  1383  		t.Errorf("protobuf profile is invalid: %v", err)
  1384  	}
  1385  	expectedLabels := map[int64]map[string]string{
  1386  		50: {},
  1387  		44: {"label": "value"},
  1388  		40: {},
  1389  		36: {"label": "value"},
  1390  		10: {},
  1391  		9:  {"label": "value"},
  1392  		1:  {},
  1393  	}
  1394  	if !containsCountsLabels(p, expectedLabels) {
  1395  		t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v",
  1396  			expectedLabels, p)
  1397  	}
  1398  
  1399  	close(c)
  1400  
  1401  	time.Sleep(10 * time.Millisecond) // let goroutines exit
  1402  }
  1403  
  1404  func containsInOrder(s string, all ...string) bool {
  1405  	for _, t := range all {
  1406  		var ok bool
  1407  		if _, s, ok = strings.Cut(s, t); !ok {
  1408  			return false
  1409  		}
  1410  	}
  1411  	return true
  1412  }
  1413  
  1414  func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool {
  1415  	m := make(map[int64]int)
  1416  	type nkey struct {
  1417  		count    int64
  1418  		key, val string
  1419  	}
  1420  	n := make(map[nkey]int)
  1421  	for c, kv := range countLabels {
  1422  		m[c]++
  1423  		for k, v := range kv {
  1424  			n[nkey{
  1425  				count: c,
  1426  				key:   k,
  1427  				val:   v,
  1428  			}]++
  1429  
  1430  		}
  1431  	}
  1432  	for _, s := range prof.Sample {
  1433  		// The count is the single value in the sample
  1434  		if len(s.Value) != 1 {
  1435  			return false
  1436  		}
  1437  		m[s.Value[0]]--
  1438  		for k, vs := range s.Label {
  1439  			for _, v := range vs {
  1440  				n[nkey{
  1441  					count: s.Value[0],
  1442  					key:   k,
  1443  					val:   v,
  1444  				}]--
  1445  			}
  1446  		}
  1447  	}
  1448  	for _, n := range m {
  1449  		if n > 0 {
  1450  			return false
  1451  		}
  1452  	}
  1453  	for _, ncnt := range n {
  1454  		if ncnt != 0 {
  1455  			return false
  1456  		}
  1457  	}
  1458  	return true
  1459  }
  1460  
  1461  func TestGoroutineProfileConcurrency(t *testing.T) {
  1462  	testenv.MustHaveParallelism(t)
  1463  
  1464  	goroutineProf := Lookup("goroutine")
  1465  
  1466  	profilerCalls := func(s string) int {
  1467  		return strings.Count(s, "\truntime/pprof.runtime_goroutineProfileWithLabels+")
  1468  	}
  1469  
  1470  	includesFinalizer := func(s string) bool {
  1471  		return strings.Contains(s, "runtime.runfinq")
  1472  	}
  1473  
  1474  	// Concurrent calls to the goroutine profiler should not trigger data races
  1475  	// or corruption.
  1476  	t.Run("overlapping profile requests", func(t *testing.T) {
  1477  		ctx := context.Background()
  1478  		ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
  1479  		defer cancel()
  1480  
  1481  		var wg sync.WaitGroup
  1482  		for i := 0; i < 2; i++ {
  1483  			wg.Add(1)
  1484  			Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
  1485  				go func() {
  1486  					defer wg.Done()
  1487  					for ctx.Err() == nil {
  1488  						var w strings.Builder
  1489  						goroutineProf.WriteTo(&w, 1)
  1490  						prof := w.String()
  1491  						count := profilerCalls(prof)
  1492  						if count >= 2 {
  1493  							t.Logf("prof %d\n%s", count, prof)
  1494  							cancel()
  1495  						}
  1496  					}
  1497  				}()
  1498  			})
  1499  		}
  1500  		wg.Wait()
  1501  	})
  1502  
  1503  	// The finalizer goroutine should not show up in most profiles, since it's
  1504  	// marked as a system goroutine when idle.
  1505  	t.Run("finalizer not present", func(t *testing.T) {
  1506  		var w strings.Builder
  1507  		goroutineProf.WriteTo(&w, 1)
  1508  		prof := w.String()
  1509  		if includesFinalizer(prof) {
  1510  			t.Errorf("profile includes finalizer (but finalizer should be marked as system):\n%s", prof)
  1511  		}
  1512  	})
  1513  
  1514  	// The finalizer goroutine should show up when it's running user code.
  1515  	t.Run("finalizer present", func(t *testing.T) {
  1516  		obj := new(byte)
  1517  		ch1, ch2 := make(chan int), make(chan int)
  1518  		defer close(ch2)
  1519  		runtime.SetFinalizer(obj, func(_ interface{}) {
  1520  			close(ch1)
  1521  			<-ch2
  1522  		})
  1523  		obj = nil
  1524  		for i := 10; i >= 0; i-- {
  1525  			select {
  1526  			case <-ch1:
  1527  			default:
  1528  				if i == 0 {
  1529  					t.Fatalf("finalizer did not run")
  1530  				}
  1531  				runtime.GC()
  1532  			}
  1533  		}
  1534  		var w strings.Builder
  1535  		goroutineProf.WriteTo(&w, 1)
  1536  		prof := w.String()
  1537  		if !includesFinalizer(prof) {
  1538  			t.Errorf("profile does not include finalizer (and it should be marked as user):\n%s", prof)
  1539  		}
  1540  	})
  1541  
  1542  	// Check that new goroutines only show up in order.
  1543  	testLaunches := func(t *testing.T) {
  1544  		var done sync.WaitGroup
  1545  		defer done.Wait()
  1546  
  1547  		ctx := context.Background()
  1548  		ctx, cancel := context.WithCancel(ctx)
  1549  		defer cancel()
  1550  
  1551  		ch := make(chan int)
  1552  		defer close(ch)
  1553  
  1554  		var ready sync.WaitGroup
  1555  
  1556  		// These goroutines all survive until the end of the subtest, so we can
  1557  		// check that a (numbered) goroutine appearing in the profile implies
  1558  		// that all older goroutines also appear in the profile.
  1559  		ready.Add(1)
  1560  		done.Add(1)
  1561  		go func() {
  1562  			defer done.Done()
  1563  			for i := 0; ctx.Err() == nil; i++ {
  1564  				// Use SetGoroutineLabels rather than Do we can always expect an
  1565  				// extra goroutine (this one) with most recent label.
  1566  				SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-loop-i", fmt.Sprint(i))))
  1567  				done.Add(1)
  1568  				go func() {
  1569  					<-ch
  1570  					done.Done()
  1571  				}()
  1572  				for j := 0; j < i; j++ {
  1573  					// Spin for longer and longer as the test goes on. This
  1574  					// goroutine will do O(N^2) work with the number of
  1575  					// goroutines it launches. This should be slow relative to
  1576  					// the work involved in collecting a goroutine profile,
  1577  					// which is O(N) with the high-water mark of the number of
  1578  					// goroutines in this process (in the allgs slice).
  1579  					runtime.Gosched()
  1580  				}
  1581  				if i == 0 {
  1582  					ready.Done()
  1583  				}
  1584  			}
  1585  		}()
  1586  
  1587  		// Short-lived goroutines exercise different code paths (goroutines with
  1588  		// status _Gdead, for instance). This churn doesn't have behavior that
  1589  		// we can test directly, but does help to shake out data races.
  1590  		ready.Add(1)
  1591  		var churn func(i int)
  1592  		churn = func(i int) {
  1593  			SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-churn-i", fmt.Sprint(i))))
  1594  			if i == 0 {
  1595  				ready.Done()
  1596  			} else if i%16 == 0 {
  1597  				// Yield on occasion so this sequence of goroutine launches
  1598  				// doesn't monopolize a P. See issue #52934.
  1599  				runtime.Gosched()
  1600  			}
  1601  			if ctx.Err() == nil {
  1602  				go churn(i + 1)
  1603  			}
  1604  		}
  1605  		go func() {
  1606  			churn(0)
  1607  		}()
  1608  
  1609  		ready.Wait()
  1610  
  1611  		var w [3]bytes.Buffer
  1612  		for i := range w {
  1613  			goroutineProf.WriteTo(&w[i], 0)
  1614  		}
  1615  		for i := range w {
  1616  			p, err := profile.Parse(bytes.NewReader(w[i].Bytes()))
  1617  			if err != nil {
  1618  				t.Errorf("error parsing protobuf profile: %v", err)
  1619  			}
  1620  
  1621  			// High-numbered loop-i goroutines imply that every lower-numbered
  1622  			// loop-i goroutine should be present in the profile too.
  1623  			counts := make(map[string]int)
  1624  			for _, s := range p.Sample {
  1625  				label := s.Label[t.Name()+"-loop-i"]
  1626  				if len(label) > 0 {
  1627  					counts[label[0]]++
  1628  				}
  1629  			}
  1630  			for j, max := 0, len(counts)-1; j <= max; j++ {
  1631  				n := counts[fmt.Sprint(j)]
  1632  				if n == 1 || (n == 2 && j == max) {
  1633  					continue
  1634  				}
  1635  				t.Errorf("profile #%d's goroutines with label loop-i:%d; %d != 1 (or 2 for the last entry, %d)",
  1636  					i+1, j, n, max)
  1637  				t.Logf("counts %v", counts)
  1638  				break
  1639  			}
  1640  		}
  1641  	}
  1642  
  1643  	runs := 100
  1644  	if testing.Short() {
  1645  		runs = 5
  1646  	}
  1647  	for i := 0; i < runs; i++ {
  1648  		// Run multiple times to shake out data races
  1649  		t.Run("goroutine launches", testLaunches)
  1650  	}
  1651  }
  1652  
  1653  func BenchmarkGoroutine(b *testing.B) {
  1654  	withIdle := func(n int, fn func(b *testing.B)) func(b *testing.B) {
  1655  		return func(b *testing.B) {
  1656  			c := make(chan int)
  1657  			var ready, done sync.WaitGroup
  1658  			defer func() {
  1659  				close(c)
  1660  				done.Wait()
  1661  			}()
  1662  
  1663  			for i := 0; i < n; i++ {
  1664  				ready.Add(1)
  1665  				done.Add(1)
  1666  				go func() {
  1667  					ready.Done()
  1668  					<-c
  1669  					done.Done()
  1670  				}()
  1671  			}
  1672  			// Let goroutines block on channel
  1673  			ready.Wait()
  1674  			for i := 0; i < 5; i++ {
  1675  				runtime.Gosched()
  1676  			}
  1677  
  1678  			fn(b)
  1679  		}
  1680  	}
  1681  
  1682  	withChurn := func(fn func(b *testing.B)) func(b *testing.B) {
  1683  		return func(b *testing.B) {
  1684  			ctx := context.Background()
  1685  			ctx, cancel := context.WithCancel(ctx)
  1686  			defer cancel()
  1687  
  1688  			var ready sync.WaitGroup
  1689  			ready.Add(1)
  1690  			var count int64
  1691  			var churn func(i int)
  1692  			churn = func(i int) {
  1693  				SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
  1694  				atomic.AddInt64(&count, 1)
  1695  				if i == 0 {
  1696  					ready.Done()
  1697  				}
  1698  				if ctx.Err() == nil {
  1699  					go churn(i + 1)
  1700  				}
  1701  			}
  1702  			go func() {
  1703  				churn(0)
  1704  			}()
  1705  			ready.Wait()
  1706  
  1707  			fn(b)
  1708  			b.ReportMetric(float64(atomic.LoadInt64(&count))/float64(b.N), "concurrent_launches/op")
  1709  		}
  1710  	}
  1711  
  1712  	benchWriteTo := func(b *testing.B) {
  1713  		goroutineProf := Lookup("goroutine")
  1714  		b.ResetTimer()
  1715  		for i := 0; i < b.N; i++ {
  1716  			goroutineProf.WriteTo(io.Discard, 0)
  1717  		}
  1718  		b.StopTimer()
  1719  	}
  1720  
  1721  	benchGoroutineProfile := func(b *testing.B) {
  1722  		p := make([]runtime.StackRecord, 10000)
  1723  		b.ResetTimer()
  1724  		for i := 0; i < b.N; i++ {
  1725  			runtime.GoroutineProfile(p)
  1726  		}
  1727  		b.StopTimer()
  1728  	}
  1729  
  1730  	// Note that some costs of collecting a goroutine profile depend on the
  1731  	// length of the runtime.allgs slice, which never shrinks. Stay within race
  1732  	// detector's 8k-goroutine limit
  1733  	for _, n := range []int{50, 500, 5000} {
  1734  		b.Run(fmt.Sprintf("Profile.WriteTo idle %d", n), withIdle(n, benchWriteTo))
  1735  		b.Run(fmt.Sprintf("Profile.WriteTo churn %d", n), withIdle(n, withChurn(benchWriteTo)))
  1736  		b.Run(fmt.Sprintf("runtime.GoroutineProfile churn %d", n), withIdle(n, withChurn(benchGoroutineProfile)))
  1737  	}
  1738  }
  1739  
  1740  var emptyCallStackTestRun int64
  1741  
  1742  // Issue 18836.
  1743  func TestEmptyCallStack(t *testing.T) {
  1744  	name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun)
  1745  	emptyCallStackTestRun++
  1746  
  1747  	t.Parallel()
  1748  	var buf strings.Builder
  1749  	p := NewProfile(name)
  1750  
  1751  	p.Add("foo", 47674)
  1752  	p.WriteTo(&buf, 1)
  1753  	p.Remove("foo")
  1754  	got := buf.String()
  1755  	prefix := name + " profile: total 1\n"
  1756  	if !strings.HasPrefix(got, prefix) {
  1757  		t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix)
  1758  	}
  1759  	lostevent := "lostProfileEvent"
  1760  	if !strings.Contains(got, lostevent) {
  1761  		t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent)
  1762  	}
  1763  }
  1764  
  1765  // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key
  1766  // and value and has funcname somewhere in the stack.
  1767  func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
  1768  	base, kv, ok := strings.Cut(spec, ";")
  1769  	if !ok {
  1770  		panic("no semicolon in key/value spec")
  1771  	}
  1772  	k, v, ok := strings.Cut(kv, "=")
  1773  	if !ok {
  1774  		panic("missing = in key/value spec")
  1775  	}
  1776  	if !contains(labels[k], v) {
  1777  		return false
  1778  	}
  1779  	return stackContains(base, count, stk, labels)
  1780  }
  1781  
  1782  func TestCPUProfileLabel(t *testing.T) {
  1783  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions())
  1784  	testCPUProfile(t, matches, func(dur time.Duration) {
  1785  		Do(context.Background(), Labels("key", "value"), func(context.Context) {
  1786  			cpuHogger(cpuHog1, &salt1, dur)
  1787  		})
  1788  	})
  1789  }
  1790  
  1791  func TestLabelRace(t *testing.T) {
  1792  	testenv.MustHaveParallelism(t)
  1793  	// Test the race detector annotations for synchronization
  1794  	// between setting labels and consuming them from the
  1795  	// profile.
  1796  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil)
  1797  	testCPUProfile(t, matches, func(dur time.Duration) {
  1798  		start := time.Now()
  1799  		var wg sync.WaitGroup
  1800  		for time.Since(start) < dur {
  1801  			var salts [10]int
  1802  			for i := 0; i < 10; i++ {
  1803  				wg.Add(1)
  1804  				go func(j int) {
  1805  					Do(context.Background(), Labels("key", "value"), func(context.Context) {
  1806  						cpuHogger(cpuHog1, &salts[j], time.Millisecond)
  1807  					})
  1808  					wg.Done()
  1809  				}(i)
  1810  			}
  1811  			wg.Wait()
  1812  		}
  1813  	})
  1814  }
  1815  
  1816  func TestGoroutineProfileLabelRace(t *testing.T) {
  1817  	testenv.MustHaveParallelism(t)
  1818  	// Test the race detector annotations for synchronization
  1819  	// between setting labels and consuming them from the
  1820  	// goroutine profile. See issue #50292.
  1821  
  1822  	t.Run("reset", func(t *testing.T) {
  1823  		ctx := context.Background()
  1824  		ctx, cancel := context.WithCancel(ctx)
  1825  		defer cancel()
  1826  
  1827  		go func() {
  1828  			goroutineProf := Lookup("goroutine")
  1829  			for ctx.Err() == nil {
  1830  				var w strings.Builder
  1831  				goroutineProf.WriteTo(&w, 1)
  1832  				prof := w.String()
  1833  				if strings.Contains(prof, "loop-i") {
  1834  					cancel()
  1835  				}
  1836  			}
  1837  		}()
  1838  
  1839  		for i := 0; ctx.Err() == nil; i++ {
  1840  			Do(ctx, Labels("loop-i", fmt.Sprint(i)), func(ctx context.Context) {
  1841  			})
  1842  		}
  1843  	})
  1844  
  1845  	t.Run("churn", func(t *testing.T) {
  1846  		ctx := context.Background()
  1847  		ctx, cancel := context.WithCancel(ctx)
  1848  		defer cancel()
  1849  
  1850  		var ready sync.WaitGroup
  1851  		ready.Add(1)
  1852  		var churn func(i int)
  1853  		churn = func(i int) {
  1854  			SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
  1855  			if i == 0 {
  1856  				ready.Done()
  1857  			}
  1858  			if ctx.Err() == nil {
  1859  				go churn(i + 1)
  1860  			}
  1861  		}
  1862  		go func() {
  1863  			churn(0)
  1864  		}()
  1865  		ready.Wait()
  1866  
  1867  		goroutineProf := Lookup("goroutine")
  1868  		for i := 0; i < 10; i++ {
  1869  			goroutineProf.WriteTo(io.Discard, 1)
  1870  		}
  1871  	})
  1872  }
  1873  
  1874  // TestLabelSystemstack makes sure CPU profiler samples of goroutines running
  1875  // on systemstack include the correct pprof labels. See issue #48577
  1876  func TestLabelSystemstack(t *testing.T) {
  1877  	// Grab and re-set the initial value before continuing to ensure
  1878  	// GOGC doesn't actually change following the test.
  1879  	gogc := debug.SetGCPercent(100)
  1880  	debug.SetGCPercent(gogc)
  1881  
  1882  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions())
  1883  	p := testCPUProfile(t, matches, func(dur time.Duration) {
  1884  		Do(context.Background(), Labels("key", "value"), func(ctx context.Context) {
  1885  			parallelLabelHog(ctx, dur, gogc)
  1886  		})
  1887  	})
  1888  
  1889  	// Two conditions to check:
  1890  	// * labelHog should always be labeled.
  1891  	// * The label should _only_ appear on labelHog and the Do call above.
  1892  	for _, s := range p.Sample {
  1893  		isLabeled := s.Label != nil && contains(s.Label["key"], "value")
  1894  		var (
  1895  			mayBeLabeled     bool
  1896  			mustBeLabeled    string
  1897  			mustNotBeLabeled string
  1898  		)
  1899  		for _, loc := range s.Location {
  1900  			for _, l := range loc.Line {
  1901  				switch l.Function.Name {
  1902  				case "runtime/pprof.labelHog", "runtime/pprof.parallelLabelHog", "runtime/pprof.parallelLabelHog.func1":
  1903  					mustBeLabeled = l.Function.Name
  1904  				case "runtime/pprof.Do":
  1905  					// Do sets the labels, so samples may
  1906  					// or may not be labeled depending on
  1907  					// which part of the function they are
  1908  					// at.
  1909  					mayBeLabeled = true
  1910  				case "runtime.bgsweep", "runtime.bgscavenge", "runtime.forcegchelper", "runtime.gcBgMarkWorker", "runtime.runfinq", "runtime.sysmon":
  1911  					// Runtime system goroutines or threads
  1912  					// (such as those identified by
  1913  					// runtime.isSystemGoroutine). These
  1914  					// should never be labeled.
  1915  					mustNotBeLabeled = l.Function.Name
  1916  				case "gogo", "gosave_systemstack_switch", "racecall":
  1917  					// These are context switch/race
  1918  					// critical that we can't do a full
  1919  					// traceback from. Typically this would
  1920  					// be covered by the runtime check
  1921  					// below, but these symbols don't have
  1922  					// the package name.
  1923  					mayBeLabeled = true
  1924  				}
  1925  
  1926  				if strings.HasPrefix(l.Function.Name, "runtime.") {
  1927  					// There are many places in the runtime
  1928  					// where we can't do a full traceback.
  1929  					// Ideally we'd list them all, but
  1930  					// barring that allow anything in the
  1931  					// runtime, unless explicitly excluded
  1932  					// above.
  1933  					mayBeLabeled = true
  1934  				}
  1935  			}
  1936  		}
  1937  		errorStack := func(f string, args ...any) {
  1938  			var buf strings.Builder
  1939  			fprintStack(&buf, s.Location)
  1940  			t.Errorf("%s: %s", fmt.Sprintf(f, args...), buf.String())
  1941  		}
  1942  		if mustBeLabeled != "" && mustNotBeLabeled != "" {
  1943  			errorStack("sample contains both %s, which must be labeled, and %s, which must not be labeled", mustBeLabeled, mustNotBeLabeled)
  1944  			continue
  1945  		}
  1946  		if mustBeLabeled != "" || mustNotBeLabeled != "" {
  1947  			// We found a definitive frame, so mayBeLabeled hints are not relevant.
  1948  			mayBeLabeled = false
  1949  		}
  1950  		if mayBeLabeled {
  1951  			// This sample may or may not be labeled, so there's nothing we can check.
  1952  			continue
  1953  		}
  1954  		if mustBeLabeled != "" && !isLabeled {
  1955  			errorStack("sample must be labeled because of %s, but is not", mustBeLabeled)
  1956  		}
  1957  		if mustNotBeLabeled != "" && isLabeled {
  1958  			errorStack("sample must not be labeled because of %s, but is", mustNotBeLabeled)
  1959  		}
  1960  	}
  1961  }
  1962  
  1963  // labelHog is designed to burn CPU time in a way that a high number of CPU
  1964  // samples end up running on systemstack.
  1965  func labelHog(stop chan struct{}, gogc int) {
  1966  	// Regression test for issue 50032. We must give GC an opportunity to
  1967  	// be initially triggered by a labelled goroutine.
  1968  	runtime.GC()
  1969  
  1970  	for i := 0; ; i++ {
  1971  		select {
  1972  		case <-stop:
  1973  			return
  1974  		default:
  1975  			debug.SetGCPercent(gogc)
  1976  		}
  1977  	}
  1978  }
  1979  
  1980  // parallelLabelHog runs GOMAXPROCS goroutines running labelHog.
  1981  func parallelLabelHog(ctx context.Context, dur time.Duration, gogc int) {
  1982  	var wg sync.WaitGroup
  1983  	stop := make(chan struct{})
  1984  	for i := 0; i < runtime.GOMAXPROCS(0); i++ {
  1985  		wg.Add(1)
  1986  		go func() {
  1987  			defer wg.Done()
  1988  			labelHog(stop, gogc)
  1989  		}()
  1990  	}
  1991  
  1992  	time.Sleep(dur)
  1993  	close(stop)
  1994  	wg.Wait()
  1995  }
  1996  
  1997  // Check that there is no deadlock when the program receives SIGPROF while in
  1998  // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146.
  1999  func TestAtomicLoadStore64(t *testing.T) {
  2000  	f, err := os.CreateTemp("", "profatomic")
  2001  	if err != nil {
  2002  		t.Fatalf("TempFile: %v", err)
  2003  	}
  2004  	defer os.Remove(f.Name())
  2005  	defer f.Close()
  2006  
  2007  	if err := StartCPUProfile(f); err != nil {
  2008  		t.Fatal(err)
  2009  	}
  2010  	defer StopCPUProfile()
  2011  
  2012  	var flag uint64
  2013  	done := make(chan bool, 1)
  2014  
  2015  	go func() {
  2016  		for atomic.LoadUint64(&flag) == 0 {
  2017  			runtime.Gosched()
  2018  		}
  2019  		done <- true
  2020  	}()
  2021  	time.Sleep(50 * time.Millisecond)
  2022  	atomic.StoreUint64(&flag, 1)
  2023  	<-done
  2024  }
  2025  
  2026  func TestTracebackAll(t *testing.T) {
  2027  	// With gccgo, if a profiling signal arrives at the wrong time
  2028  	// during traceback, it may crash or hang. See issue #29448.
  2029  	f, err := os.CreateTemp("", "proftraceback")
  2030  	if err != nil {
  2031  		t.Fatalf("TempFile: %v", err)
  2032  	}
  2033  	defer os.Remove(f.Name())
  2034  	defer f.Close()
  2035  
  2036  	if err := StartCPUProfile(f); err != nil {
  2037  		t.Fatal(err)
  2038  	}
  2039  	defer StopCPUProfile()
  2040  
  2041  	ch := make(chan int)
  2042  	defer close(ch)
  2043  
  2044  	count := 10
  2045  	for i := 0; i < count; i++ {
  2046  		go func() {
  2047  			<-ch // block
  2048  		}()
  2049  	}
  2050  
  2051  	N := 10000
  2052  	if testing.Short() {
  2053  		N = 500
  2054  	}
  2055  	buf := make([]byte, 10*1024)
  2056  	for i := 0; i < N; i++ {
  2057  		runtime.Stack(buf, true)
  2058  	}
  2059  }
  2060  
  2061  // TestTryAdd tests the cases that are hard to test with real program execution.
  2062  //
  2063  // For example, the current go compilers may not always inline functions
  2064  // involved in recursion but that may not be true in the future compilers. This
  2065  // tests such cases by using fake call sequences and forcing the profile build
  2066  // utilizing translateCPUProfile defined in proto_test.go
  2067  func TestTryAdd(t *testing.T) {
  2068  	if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found {
  2069  		t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.")
  2070  	}
  2071  
  2072  	// inlinedCallerDump
  2073  	//   inlinedCalleeDump
  2074  	pcs := make([]uintptr, 2)
  2075  	inlinedCallerDump(pcs)
  2076  	inlinedCallerStack := make([]uint64, 2)
  2077  	for i := range pcs {
  2078  		inlinedCallerStack[i] = uint64(pcs[i])
  2079  	}
  2080  	wrapperPCs := make([]uintptr, 1)
  2081  	inlinedWrapperCallerDump(wrapperPCs)
  2082  
  2083  	if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found {
  2084  		t.Skip("Can't determine whether anything was inlined into recursionChainBottom.")
  2085  	}
  2086  
  2087  	// recursionChainTop
  2088  	//   recursionChainMiddle
  2089  	//     recursionChainBottom
  2090  	//       recursionChainTop
  2091  	//         recursionChainMiddle
  2092  	//           recursionChainBottom
  2093  	pcs = make([]uintptr, 6)
  2094  	recursionChainTop(1, pcs)
  2095  	recursionStack := make([]uint64, len(pcs))
  2096  	for i := range pcs {
  2097  		recursionStack[i] = uint64(pcs[i])
  2098  	}
  2099  
  2100  	period := int64(2000 * 1000) // 1/500*1e9 nanosec.
  2101  
  2102  	testCases := []struct {
  2103  		name        string
  2104  		input       []uint64          // following the input format assumed by profileBuilder.addCPUData.
  2105  		count       int               // number of records in input.
  2106  		wantLocs    [][]string        // ordered location entries with function names.
  2107  		wantSamples []*profile.Sample // ordered samples, we care only about Value and the profile location IDs.
  2108  	}{{
  2109  		// Sanity test for a normal, complete stack trace.
  2110  		name: "full_stack_trace",
  2111  		input: []uint64{
  2112  			3, 0, 500, // hz = 500. Must match the period.
  2113  			5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
  2114  		},
  2115  		count: 2,
  2116  		wantLocs: [][]string{
  2117  			{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
  2118  		},
  2119  		wantSamples: []*profile.Sample{
  2120  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  2121  		},
  2122  	}, {
  2123  		name: "bug35538",
  2124  		input: []uint64{
  2125  			3, 0, 500, // hz = 500. Must match the period.
  2126  			// Fake frame: tryAdd will have inlinedCallerDump
  2127  			// (stack[1]) on the deck when it encounters the next
  2128  			// inline function. It should accept this.
  2129  			7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1],
  2130  			5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1],
  2131  		},
  2132  		count:    3,
  2133  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2134  		wantSamples: []*profile.Sample{
  2135  			{Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}},
  2136  			{Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}},
  2137  		},
  2138  	}, {
  2139  		name: "bug38096",
  2140  		input: []uint64{
  2141  			3, 0, 500, // hz = 500. Must match the period.
  2142  			// count (data[2]) == 0 && len(stk) == 1 is an overflow
  2143  			// entry. The "stk" entry is actually the count.
  2144  			4, 0, 0, 4242,
  2145  		},
  2146  		count:    2,
  2147  		wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}},
  2148  		wantSamples: []*profile.Sample{
  2149  			{Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}},
  2150  		},
  2151  	}, {
  2152  		// If a function is directly called recursively then it must
  2153  		// not be inlined in the caller.
  2154  		//
  2155  		// N.B. We're generating an impossible profile here, with a
  2156  		// recursive inlineCalleeDump call. This is simulating a non-Go
  2157  		// function that looks like an inlined Go function other than
  2158  		// its recursive property. See pcDeck.tryAdd.
  2159  		name: "directly_recursive_func_is_not_inlined",
  2160  		input: []uint64{
  2161  			3, 0, 500, // hz = 500. Must match the period.
  2162  			5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0],
  2163  			4, 0, 40, inlinedCallerStack[0],
  2164  		},
  2165  		count: 3,
  2166  		// inlinedCallerDump shows up here because
  2167  		// runtime_expandFinalInlineFrame adds it to the stack frame.
  2168  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}},
  2169  		wantSamples: []*profile.Sample{
  2170  			{Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}},
  2171  			{Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}},
  2172  		},
  2173  	}, {
  2174  		name: "recursion_chain_inline",
  2175  		input: []uint64{
  2176  			3, 0, 500, // hz = 500. Must match the period.
  2177  			9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5],
  2178  		},
  2179  		count: 2,
  2180  		wantLocs: [][]string{
  2181  			{"runtime/pprof.recursionChainBottom"},
  2182  			{
  2183  				"runtime/pprof.recursionChainMiddle",
  2184  				"runtime/pprof.recursionChainTop",
  2185  				"runtime/pprof.recursionChainBottom",
  2186  			},
  2187  			{
  2188  				"runtime/pprof.recursionChainMiddle",
  2189  				"runtime/pprof.recursionChainTop",
  2190  				"runtime/pprof.TestTryAdd", // inlined into the test.
  2191  			},
  2192  		},
  2193  		wantSamples: []*profile.Sample{
  2194  			{Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}},
  2195  		},
  2196  	}, {
  2197  		name: "truncated_stack_trace_later",
  2198  		input: []uint64{
  2199  			3, 0, 500, // hz = 500. Must match the period.
  2200  			5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
  2201  			4, 0, 60, inlinedCallerStack[0],
  2202  		},
  2203  		count:    3,
  2204  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2205  		wantSamples: []*profile.Sample{
  2206  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  2207  			{Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}},
  2208  		},
  2209  	}, {
  2210  		name: "truncated_stack_trace_first",
  2211  		input: []uint64{
  2212  			3, 0, 500, // hz = 500. Must match the period.
  2213  			4, 0, 70, inlinedCallerStack[0],
  2214  			5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1],
  2215  		},
  2216  		count:    3,
  2217  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2218  		wantSamples: []*profile.Sample{
  2219  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  2220  			{Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}},
  2221  		},
  2222  	}, {
  2223  		// We can recover the inlined caller from a truncated stack.
  2224  		name: "truncated_stack_trace_only",
  2225  		input: []uint64{
  2226  			3, 0, 500, // hz = 500. Must match the period.
  2227  			4, 0, 70, inlinedCallerStack[0],
  2228  		},
  2229  		count:    2,
  2230  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  2231  		wantSamples: []*profile.Sample{
  2232  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  2233  		},
  2234  	}, {
  2235  		// The same location is used for duplicated stacks.
  2236  		name: "truncated_stack_trace_twice",
  2237  		input: []uint64{
  2238  			3, 0, 500, // hz = 500. Must match the period.
  2239  			4, 0, 70, inlinedCallerStack[0],
  2240  			// Fake frame: add a fake call to
  2241  			// inlinedCallerDump to prevent this sample
  2242  			// from getting merged into above.
  2243  			5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0],
  2244  		},
  2245  		count: 3,
  2246  		wantLocs: [][]string{
  2247  			{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
  2248  			{"runtime/pprof.inlinedCallerDump"},
  2249  		},
  2250  		wantSamples: []*profile.Sample{
  2251  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  2252  			{Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}},
  2253  		},
  2254  	}, {
  2255  		name: "expand_wrapper_function",
  2256  		input: []uint64{
  2257  			3, 0, 500, // hz = 500. Must match the period.
  2258  			4, 0, 50, uint64(wrapperPCs[0]),
  2259  		},
  2260  		count:    2,
  2261  		wantLocs: [][]string{{"runtime/pprof.inlineWrapper.dump"}},
  2262  		wantSamples: []*profile.Sample{
  2263  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  2264  		},
  2265  	}}
  2266  
  2267  	for _, tc := range testCases {
  2268  		t.Run(tc.name, func(t *testing.T) {
  2269  			p, err := translateCPUProfile(tc.input, tc.count)
  2270  			if err != nil {
  2271  				t.Fatalf("translating profile: %v", err)
  2272  			}
  2273  			t.Logf("Profile: %v\n", p)
  2274  
  2275  			// One location entry with all inlined functions.
  2276  			var gotLoc [][]string
  2277  			for _, loc := range p.Location {
  2278  				var names []string
  2279  				for _, line := range loc.Line {
  2280  					names = append(names, line.Function.Name)
  2281  				}
  2282  				gotLoc = append(gotLoc, names)
  2283  			}
  2284  			if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want {
  2285  				t.Errorf("Got Location = %+v\n\twant %+v", got, want)
  2286  			}
  2287  			// All samples should point to one location.
  2288  			var gotSamples []*profile.Sample
  2289  			for _, sample := range p.Sample {
  2290  				var locs []*profile.Location
  2291  				for _, loc := range sample.Location {
  2292  					locs = append(locs, &profile.Location{ID: loc.ID})
  2293  				}
  2294  				gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs})
  2295  			}
  2296  			if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want {
  2297  				t.Errorf("Got Samples = %+v\n\twant %+v", got, want)
  2298  			}
  2299  		})
  2300  	}
  2301  }
  2302  
  2303  func TestTimeVDSO(t *testing.T) {
  2304  	// Test that time functions have the right stack trace. In particular,
  2305  	// it shouldn't be recursive.
  2306  
  2307  	if runtime.GOOS == "android" {
  2308  		// Flaky on Android, issue 48655. VDSO may not be enabled.
  2309  		testenv.SkipFlaky(t, 48655)
  2310  	}
  2311  
  2312  	matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions())
  2313  	p := testCPUProfile(t, matches, func(dur time.Duration) {
  2314  		t0 := time.Now()
  2315  		for {
  2316  			t := time.Now()
  2317  			if t.Sub(t0) >= dur {
  2318  				return
  2319  			}
  2320  		}
  2321  	})
  2322  
  2323  	// Check for recursive time.now sample.
  2324  	for _, sample := range p.Sample {
  2325  		var seenNow bool
  2326  		for _, loc := range sample.Location {
  2327  			for _, line := range loc.Line {
  2328  				if line.Function.Name == "time.now" {
  2329  					if seenNow {
  2330  						t.Fatalf("unexpected recursive time.now")
  2331  					}
  2332  					seenNow = true
  2333  				}
  2334  			}
  2335  		}
  2336  	}
  2337  }