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

View as plain text