Source file src/runtime/pprof/pprof_test.go

Documentation: runtime/pprof

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

View as plain text