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

View as plain text