github.com/m10x/go/src@v0.0.0-20220112094212-ba61592315da/runtime/pprof/pprof_test.go (about)

     1  // Copyright 2011 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  //go:build !js
     6  
     7  package pprof
     8  
     9  import (
    10  	"bytes"
    11  	"context"
    12  	"fmt"
    13  	"internal/abi"
    14  	"internal/profile"
    15  	"internal/testenv"
    16  	"io"
    17  	"math"
    18  	"math/big"
    19  	"os"
    20  	"os/exec"
    21  	"regexp"
    22  	"runtime"
    23  	"runtime/debug"
    24  	"strings"
    25  	"sync"
    26  	"sync/atomic"
    27  	"testing"
    28  	"time"
    29  	_ "unsafe"
    30  )
    31  
    32  func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
    33  	// We only need to get one 100 Hz clock tick, so we've got
    34  	// a large safety buffer.
    35  	// But do at least 500 iterations (which should take about 100ms),
    36  	// otherwise TestCPUProfileMultithreaded can fail if only one
    37  	// thread is scheduled during the testing period.
    38  	t0 := time.Now()
    39  	accum := *y
    40  	for i := 0; i < 500 || time.Since(t0) < dur; i++ {
    41  		accum = f(accum)
    42  	}
    43  	*y = accum
    44  }
    45  
    46  var (
    47  	salt1 = 0
    48  	salt2 = 0
    49  )
    50  
    51  // The actual CPU hogging function.
    52  // Must not call other functions nor access heap/globals in the loop,
    53  // otherwise under race detector the samples will be in the race runtime.
    54  func cpuHog1(x int) int {
    55  	return cpuHog0(x, 1e5)
    56  }
    57  
    58  func cpuHog0(x, n int) int {
    59  	foo := x
    60  	for i := 0; i < n; i++ {
    61  		if foo > 0 {
    62  			foo *= foo
    63  		} else {
    64  			foo *= foo + 1
    65  		}
    66  	}
    67  	return foo
    68  }
    69  
    70  func cpuHog2(x int) int {
    71  	foo := x
    72  	for i := 0; i < 1e5; i++ {
    73  		if foo > 0 {
    74  			foo *= foo
    75  		} else {
    76  			foo *= foo + 2
    77  		}
    78  	}
    79  	return foo
    80  }
    81  
    82  // Return a list of functions that we don't want to ever appear in CPU
    83  // profiles. For gccgo, that list includes the sigprof handler itself.
    84  func avoidFunctions() []string {
    85  	if runtime.Compiler == "gccgo" {
    86  		return []string{"runtime.sigprof"}
    87  	}
    88  	return nil
    89  }
    90  
    91  func TestCPUProfile(t *testing.T) {
    92  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
    93  	testCPUProfile(t, matches, func(dur time.Duration) {
    94  		cpuHogger(cpuHog1, &salt1, dur)
    95  	})
    96  }
    97  
    98  func TestCPUProfileMultithreaded(t *testing.T) {
    99  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
   100  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions())
   101  	testCPUProfile(t, matches, func(dur time.Duration) {
   102  		c := make(chan int)
   103  		go func() {
   104  			cpuHogger(cpuHog1, &salt1, dur)
   105  			c <- 1
   106  		}()
   107  		cpuHogger(cpuHog2, &salt2, dur)
   108  		<-c
   109  	})
   110  }
   111  
   112  func TestCPUProfileMultithreadMagnitude(t *testing.T) {
   113  	if runtime.GOOS != "linux" {
   114  		t.Skip("issue 35057 is only confirmed on Linux")
   115  	}
   116  
   117  	// Linux [5.9,5.16) has a kernel bug that can break CPU timers on newly
   118  	// created threads, breaking our CPU accounting.
   119  	major, minor, patch, err := linuxKernelVersion()
   120  	if err != nil {
   121  		t.Errorf("Error determining kernel version: %v", err)
   122  	}
   123  	t.Logf("Running on Linux %d.%d.%d", major, minor, patch)
   124  	defer func() {
   125  		if t.Failed() {
   126  			t.Logf("Failure of this test may indicate that your system suffers from a known Linux kernel bug fixed on newer kernels. See https://golang.org/issue/49065.")
   127  		}
   128  	}()
   129  
   130  	// Disable on affected builders to avoid flakiness, but otherwise keep
   131  	// it enabled to potentially warn users that they are on a broken
   132  	// kernel.
   133  	if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") {
   134  		have59 := major > 5 || (major == 5 && minor >= 9)
   135  		have516 := major > 5 || (major == 5 && minor >= 16)
   136  		if have59 && !have516 {
   137  			testenv.SkipFlaky(t, 49065)
   138  		}
   139  	}
   140  
   141  	// Run a workload in a single goroutine, then run copies of the same
   142  	// workload in several goroutines. For both the serial and parallel cases,
   143  	// the CPU time the process measures with its own profiler should match the
   144  	// total CPU usage that the OS reports.
   145  	//
   146  	// We could also check that increases in parallelism (GOMAXPROCS) lead to a
   147  	// linear increase in the CPU usage reported by both the OS and the
   148  	// profiler, but without a guarantee of exclusive access to CPU resources
   149  	// that is likely to be a flaky test.
   150  
   151  	// Require the smaller value to be within 10%, or 40% in short mode.
   152  	maxDiff := 0.10
   153  	if testing.Short() {
   154  		maxDiff = 0.40
   155  	}
   156  
   157  	// This test compares the process's total CPU time against the CPU
   158  	// profiler's view of time spent in direct execution of user code.
   159  	// Background work, especially from the garbage collector, adds noise to
   160  	// that measurement. Disable automatic triggering of the GC, and then
   161  	// request a complete GC cycle (up through sweep termination).
   162  	defer debug.SetGCPercent(debug.SetGCPercent(-1))
   163  	runtime.GC()
   164  
   165  	compare := func(a, b time.Duration, maxDiff float64) error {
   166  		if a <= 0 || b <= 0 {
   167  			return fmt.Errorf("Expected both time reports to be positive")
   168  		}
   169  
   170  		if a < b {
   171  			a, b = b, a
   172  		}
   173  
   174  		diff := float64(a-b) / float64(a)
   175  		if diff > maxDiff {
   176  			return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100)
   177  		}
   178  
   179  		return nil
   180  	}
   181  
   182  	for _, tc := range []struct {
   183  		name    string
   184  		workers int
   185  	}{
   186  		{
   187  			name:    "serial",
   188  			workers: 1,
   189  		},
   190  		{
   191  			name:    "parallel",
   192  			workers: runtime.GOMAXPROCS(0),
   193  		},
   194  	} {
   195  		// check that the OS's perspective matches what the Go runtime measures.
   196  		t.Run(tc.name, func(t *testing.T) {
   197  			t.Logf("Running with %d workers", tc.workers)
   198  
   199  			var cpuTime time.Duration
   200  			matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
   201  			p := testCPUProfile(t, matches, func(dur time.Duration) {
   202  				cpuTime = diffCPUTime(t, func() {
   203  					var wg sync.WaitGroup
   204  					var once sync.Once
   205  					for i := 0; i < tc.workers; i++ {
   206  						wg.Add(1)
   207  						go func() {
   208  							defer wg.Done()
   209  							var salt = 0
   210  							cpuHogger(cpuHog1, &salt, dur)
   211  							once.Do(func() { salt1 = salt })
   212  						}()
   213  					}
   214  					wg.Wait()
   215  				})
   216  			})
   217  
   218  			for i, unit := range []string{"count", "nanoseconds"} {
   219  				if have, want := p.SampleType[i].Unit, unit; have != want {
   220  					t.Errorf("pN SampleType[%d]; %q != %q", i, have, want)
   221  				}
   222  			}
   223  
   224  			var value time.Duration
   225  			for _, sample := range p.Sample {
   226  				if stackContains("runtime/pprof.cpuHog1", uintptr(sample.Value[0]), sample.Location, sample.Label) {
   227  					value += time.Duration(sample.Value[1]) * time.Nanosecond
   228  				}
   229  			}
   230  
   231  			t.Logf("compare %s vs %s", cpuTime, value)
   232  			if err := compare(cpuTime, value, maxDiff); err != nil {
   233  				t.Errorf("compare got %v want nil", err)
   234  			}
   235  		})
   236  	}
   237  }
   238  
   239  // containsInlinedCall reports whether the function body for the function f is
   240  // known to contain an inlined function call within the first maxBytes bytes.
   241  func containsInlinedCall(f any, maxBytes int) bool {
   242  	_, found := findInlinedCall(f, maxBytes)
   243  	return found
   244  }
   245  
   246  // findInlinedCall returns the PC of an inlined function call within
   247  // the function body for the function f if any.
   248  func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) {
   249  	fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f)))
   250  	if fFunc == nil || fFunc.Entry() == 0 {
   251  		panic("failed to locate function entry")
   252  	}
   253  
   254  	for offset := 0; offset < maxBytes; offset++ {
   255  		innerPC := fFunc.Entry() + uintptr(offset)
   256  		inner := runtime.FuncForPC(innerPC)
   257  		if inner == nil {
   258  			// No function known for this PC value.
   259  			// It might simply be misaligned, so keep searching.
   260  			continue
   261  		}
   262  		if inner.Entry() != fFunc.Entry() {
   263  			// Scanned past f and didn't find any inlined functions.
   264  			break
   265  		}
   266  		if inner.Name() != fFunc.Name() {
   267  			// This PC has f as its entry-point, but is not f. Therefore, it must be a
   268  			// function inlined into f.
   269  			return uint64(innerPC), true
   270  		}
   271  	}
   272  
   273  	return 0, false
   274  }
   275  
   276  func TestCPUProfileInlining(t *testing.T) {
   277  	if !containsInlinedCall(inlinedCaller, 4<<10) {
   278  		t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.")
   279  	}
   280  
   281  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions())
   282  	p := testCPUProfile(t, matches, func(dur time.Duration) {
   283  		cpuHogger(inlinedCaller, &salt1, dur)
   284  	})
   285  
   286  	// Check if inlined function locations are encoded correctly. The inlinedCalee and inlinedCaller should be in one location.
   287  	for _, loc := range p.Location {
   288  		hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false
   289  		for _, line := range loc.Line {
   290  			if line.Function.Name == "runtime/pprof.inlinedCallee" {
   291  				hasInlinedCallee = true
   292  			}
   293  			if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" {
   294  				hasInlinedCallerAfterInlinedCallee = true
   295  			}
   296  		}
   297  		if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee {
   298  			t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p)
   299  		}
   300  	}
   301  }
   302  
   303  func inlinedCaller(x int) int {
   304  	x = inlinedCallee(x, 1e5)
   305  	return x
   306  }
   307  
   308  func inlinedCallee(x, n int) int {
   309  	return cpuHog0(x, n)
   310  }
   311  
   312  //go:noinline
   313  func dumpCallers(pcs []uintptr) {
   314  	if pcs == nil {
   315  		return
   316  	}
   317  
   318  	skip := 2 // Callers and dumpCallers
   319  	runtime.Callers(skip, pcs)
   320  }
   321  
   322  //go:noinline
   323  func inlinedCallerDump(pcs []uintptr) {
   324  	inlinedCalleeDump(pcs)
   325  }
   326  
   327  func inlinedCalleeDump(pcs []uintptr) {
   328  	dumpCallers(pcs)
   329  }
   330  
   331  func TestCPUProfileRecursion(t *testing.T) {
   332  	matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions())
   333  	p := testCPUProfile(t, matches, func(dur time.Duration) {
   334  		cpuHogger(recursionCaller, &salt1, dur)
   335  	})
   336  
   337  	// check the Location encoding was not confused by recursive calls.
   338  	for i, loc := range p.Location {
   339  		recursionFunc := 0
   340  		for _, line := range loc.Line {
   341  			if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" {
   342  				recursionFunc++
   343  			}
   344  		}
   345  		if recursionFunc > 1 {
   346  			t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p)
   347  		}
   348  	}
   349  }
   350  
   351  func recursionCaller(x int) int {
   352  	y := recursionCallee(3, x)
   353  	return y
   354  }
   355  
   356  func recursionCallee(n, x int) int {
   357  	if n == 0 {
   358  		return 1
   359  	}
   360  	y := inlinedCallee(x, 1e4)
   361  	return y * recursionCallee(n-1, x)
   362  }
   363  
   364  func recursionChainTop(x int, pcs []uintptr) {
   365  	if x < 0 {
   366  		return
   367  	}
   368  	recursionChainMiddle(x, pcs)
   369  }
   370  
   371  func recursionChainMiddle(x int, pcs []uintptr) {
   372  	recursionChainBottom(x, pcs)
   373  }
   374  
   375  func recursionChainBottom(x int, pcs []uintptr) {
   376  	// This will be called each time, we only care about the last. We
   377  	// can't make this conditional or this function won't be inlined.
   378  	dumpCallers(pcs)
   379  
   380  	recursionChainTop(x-1, pcs)
   381  }
   382  
   383  func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile {
   384  	p, err := profile.Parse(bytes.NewReader(valBytes))
   385  	if err != nil {
   386  		t.Fatal(err)
   387  	}
   388  	for _, sample := range p.Sample {
   389  		count := uintptr(sample.Value[0])
   390  		f(count, sample.Location, sample.Label)
   391  	}
   392  	return p
   393  }
   394  
   395  func cpuProfilingBroken() bool {
   396  	switch runtime.GOOS {
   397  	case "plan9":
   398  		// Profiling unimplemented.
   399  		return true
   400  	case "aix":
   401  		// See https://golang.org/issue/45170.
   402  		return true
   403  	case "ios", "dragonfly", "netbsd", "illumos", "solaris":
   404  		// See https://golang.org/issue/13841.
   405  		return true
   406  	case "openbsd":
   407  		if runtime.GOARCH == "arm" || runtime.GOARCH == "arm64" {
   408  			// See https://golang.org/issue/13841.
   409  			return true
   410  		}
   411  	}
   412  
   413  	return false
   414  }
   415  
   416  // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need,
   417  // as interpreted by matches, and returns the parsed profile.
   418  func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile {
   419  	switch runtime.GOOS {
   420  	case "darwin":
   421  		out, err := exec.Command("uname", "-a").CombinedOutput()
   422  		if err != nil {
   423  			t.Fatal(err)
   424  		}
   425  		vers := string(out)
   426  		t.Logf("uname -a: %v", vers)
   427  	case "plan9":
   428  		t.Skip("skipping on plan9")
   429  	}
   430  
   431  	broken := cpuProfilingBroken()
   432  
   433  	maxDuration := 5 * time.Second
   434  	if testing.Short() && broken {
   435  		// If it's expected to be broken, no point waiting around.
   436  		maxDuration /= 10
   437  	}
   438  
   439  	// If we're running a long test, start with a long duration
   440  	// for tests that try to make sure something *doesn't* happen.
   441  	duration := 5 * time.Second
   442  	if testing.Short() {
   443  		duration = 100 * time.Millisecond
   444  	}
   445  
   446  	// Profiling tests are inherently flaky, especially on a
   447  	// loaded system, such as when this test is running with
   448  	// several others under go test std. If a test fails in a way
   449  	// that could mean it just didn't run long enough, try with a
   450  	// longer duration.
   451  	for duration <= maxDuration {
   452  		var prof bytes.Buffer
   453  		if err := StartCPUProfile(&prof); err != nil {
   454  			t.Fatal(err)
   455  		}
   456  		f(duration)
   457  		StopCPUProfile()
   458  
   459  		if p, ok := profileOk(t, matches, prof, duration); ok {
   460  			return p
   461  		}
   462  
   463  		duration *= 2
   464  		if duration <= maxDuration {
   465  			t.Logf("retrying with %s duration", duration)
   466  		}
   467  	}
   468  
   469  	if broken {
   470  		t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH)
   471  	}
   472  
   473  	// Ignore the failure if the tests are running in a QEMU-based emulator,
   474  	// QEMU is not perfect at emulating everything.
   475  	// IN_QEMU environmental variable is set by some of the Go builders.
   476  	// IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
   477  	if os.Getenv("IN_QEMU") == "1" {
   478  		t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
   479  	}
   480  	t.FailNow()
   481  	return nil
   482  }
   483  
   484  var diffCPUTimeImpl func(f func()) time.Duration
   485  
   486  func diffCPUTime(t *testing.T, f func()) time.Duration {
   487  	if fn := diffCPUTimeImpl; fn != nil {
   488  		return fn(f)
   489  	}
   490  	t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH)
   491  	return 0
   492  }
   493  
   494  func contains(slice []string, s string) bool {
   495  	for i := range slice {
   496  		if slice[i] == s {
   497  			return true
   498  		}
   499  	}
   500  	return false
   501  }
   502  
   503  // stackContains matches if a function named spec appears anywhere in the stack trace.
   504  func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   505  	for _, loc := range stk {
   506  		for _, line := range loc.Line {
   507  			if strings.Contains(line.Function.Name, spec) {
   508  				return true
   509  			}
   510  		}
   511  	}
   512  	return false
   513  }
   514  
   515  type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool
   516  
   517  func profileOk(t *testing.T, matches profileMatchFunc, prof bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) {
   518  	ok = true
   519  
   520  	var samples uintptr
   521  	var buf bytes.Buffer
   522  	p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) {
   523  		fmt.Fprintf(&buf, "%d:", count)
   524  		fprintStack(&buf, stk)
   525  		fmt.Fprintf(&buf, " labels: %v\n", labels)
   526  		samples += count
   527  		fmt.Fprintf(&buf, "\n")
   528  	})
   529  	t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String())
   530  
   531  	if samples < 10 && runtime.GOOS == "windows" {
   532  		// On some windows machines we end up with
   533  		// not enough samples due to coarse timer
   534  		// resolution. Let it go.
   535  		t.Log("too few samples on Windows (golang.org/issue/10842)")
   536  		return p, false
   537  	}
   538  
   539  	// Check that we got a reasonable number of samples.
   540  	// We used to always require at least ideal/4 samples,
   541  	// but that is too hard to guarantee on a loaded system.
   542  	// Now we accept 10 or more samples, which we take to be
   543  	// enough to show that at least some profiling is occurring.
   544  	if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) {
   545  		t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
   546  		ok = false
   547  	}
   548  
   549  	if matches != nil && !matches(t, p) {
   550  		ok = false
   551  	}
   552  
   553  	return p, ok
   554  }
   555  
   556  type profileMatchFunc func(*testing.T, *profile.Profile) bool
   557  
   558  func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc {
   559  	return func(t *testing.T, p *profile.Profile) (ok bool) {
   560  		ok = true
   561  
   562  		// Check that profile is well formed, contains 'need', and does not contain
   563  		// anything from 'avoid'.
   564  		have := make([]uintptr, len(need))
   565  		avoidSamples := make([]uintptr, len(avoid))
   566  
   567  		for _, sample := range p.Sample {
   568  			count := uintptr(sample.Value[0])
   569  			for i, spec := range need {
   570  				if matches(spec, count, sample.Location, sample.Label) {
   571  					have[i] += count
   572  				}
   573  			}
   574  			for i, name := range avoid {
   575  				for _, loc := range sample.Location {
   576  					for _, line := range loc.Line {
   577  						if strings.Contains(line.Function.Name, name) {
   578  							avoidSamples[i] += count
   579  						}
   580  					}
   581  				}
   582  			}
   583  		}
   584  
   585  		for i, name := range avoid {
   586  			bad := avoidSamples[i]
   587  			if bad != 0 {
   588  				t.Logf("found %d samples in avoid-function %s\n", bad, name)
   589  				ok = false
   590  			}
   591  		}
   592  
   593  		if len(need) == 0 {
   594  			return
   595  		}
   596  
   597  		var total uintptr
   598  		for i, name := range need {
   599  			total += have[i]
   600  			t.Logf("%s: %d\n", name, have[i])
   601  		}
   602  		if total == 0 {
   603  			t.Logf("no samples in expected functions")
   604  			ok = false
   605  		}
   606  
   607  		// We'd like to check a reasonable minimum, like
   608  		// total / len(have) / smallconstant, but this test is
   609  		// pretty flaky (see bug 7095).  So we'll just test to
   610  		// make sure we got at least one sample.
   611  		min := uintptr(1)
   612  		for i, name := range need {
   613  			if have[i] < min {
   614  				t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
   615  				ok = false
   616  			}
   617  		}
   618  		return
   619  	}
   620  }
   621  
   622  // Fork can hang if preempted with signals frequently enough (see issue 5517).
   623  // Ensure that we do not do this.
   624  func TestCPUProfileWithFork(t *testing.T) {
   625  	testenv.MustHaveExec(t)
   626  
   627  	heap := 1 << 30
   628  	if runtime.GOOS == "android" {
   629  		// Use smaller size for Android to avoid crash.
   630  		heap = 100 << 20
   631  	}
   632  	if runtime.GOOS == "windows" && runtime.GOARCH == "arm" {
   633  		// Use smaller heap for Windows/ARM to avoid crash.
   634  		heap = 100 << 20
   635  	}
   636  	if testing.Short() {
   637  		heap = 100 << 20
   638  	}
   639  	// This makes fork slower.
   640  	garbage := make([]byte, heap)
   641  	// Need to touch the slice, otherwise it won't be paged in.
   642  	done := make(chan bool)
   643  	go func() {
   644  		for i := range garbage {
   645  			garbage[i] = 42
   646  		}
   647  		done <- true
   648  	}()
   649  	<-done
   650  
   651  	var prof bytes.Buffer
   652  	if err := StartCPUProfile(&prof); err != nil {
   653  		t.Fatal(err)
   654  	}
   655  	defer StopCPUProfile()
   656  
   657  	for i := 0; i < 10; i++ {
   658  		exec.Command(os.Args[0], "-h").CombinedOutput()
   659  	}
   660  }
   661  
   662  // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
   663  // If it did, it would see inconsistent state and would either record an incorrect stack
   664  // or crash because the stack was malformed.
   665  func TestGoroutineSwitch(t *testing.T) {
   666  	if runtime.Compiler == "gccgo" {
   667  		t.Skip("not applicable for gccgo")
   668  	}
   669  	// How much to try. These defaults take about 1 seconds
   670  	// on a 2012 MacBook Pro. The ones in short mode take
   671  	// about 0.1 seconds.
   672  	tries := 10
   673  	count := 1000000
   674  	if testing.Short() {
   675  		tries = 1
   676  	}
   677  	for try := 0; try < tries; try++ {
   678  		var prof bytes.Buffer
   679  		if err := StartCPUProfile(&prof); err != nil {
   680  			t.Fatal(err)
   681  		}
   682  		for i := 0; i < count; i++ {
   683  			runtime.Gosched()
   684  		}
   685  		StopCPUProfile()
   686  
   687  		// Read profile to look for entries for gogo with an attempt at a traceback.
   688  		// "runtime.gogo" is OK, because that's the part of the context switch
   689  		// before the actual switch begins. But we should not see "gogo",
   690  		// aka "gogo<>(SB)", which does the actual switch and is marked SPWRITE.
   691  		parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) {
   692  			// An entry with two frames with 'System' in its top frame
   693  			// exists to record a PC without a traceback. Those are okay.
   694  			if len(stk) == 2 {
   695  				name := stk[1].Line[0].Function.Name
   696  				if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" {
   697  					return
   698  				}
   699  			}
   700  
   701  			// An entry with just one frame is OK too:
   702  			// it knew to stop at gogo.
   703  			if len(stk) == 1 {
   704  				return
   705  			}
   706  
   707  			// Otherwise, should not see gogo.
   708  			// The place we'd see it would be the inner most frame.
   709  			name := stk[0].Line[0].Function.Name
   710  			if name == "gogo" {
   711  				var buf bytes.Buffer
   712  				fprintStack(&buf, stk)
   713  				t.Fatalf("found profile entry for gogo:\n%s", buf.String())
   714  			}
   715  		})
   716  	}
   717  }
   718  
   719  func fprintStack(w io.Writer, stk []*profile.Location) {
   720  	for _, loc := range stk {
   721  		fmt.Fprintf(w, " %#x", loc.Address)
   722  		fmt.Fprintf(w, " (")
   723  		for i, line := range loc.Line {
   724  			if i > 0 {
   725  				fmt.Fprintf(w, " ")
   726  			}
   727  			fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line)
   728  		}
   729  		fmt.Fprintf(w, ")")
   730  	}
   731  }
   732  
   733  // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
   734  func TestMathBigDivide(t *testing.T) {
   735  	testCPUProfile(t, nil, func(duration time.Duration) {
   736  		t := time.After(duration)
   737  		pi := new(big.Int)
   738  		for {
   739  			for i := 0; i < 100; i++ {
   740  				n := big.NewInt(2646693125139304345)
   741  				d := big.NewInt(842468587426513207)
   742  				pi.Div(n, d)
   743  			}
   744  			select {
   745  			case <-t:
   746  				return
   747  			default:
   748  			}
   749  		}
   750  	})
   751  }
   752  
   753  // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace.
   754  func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   755  	for _, f := range strings.Split(spec, ",") {
   756  		if !stackContains(f, count, stk, labels) {
   757  			return false
   758  		}
   759  	}
   760  	return true
   761  }
   762  
   763  func TestMorestack(t *testing.T) {
   764  	matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions())
   765  	testCPUProfile(t, matches, func(duration time.Duration) {
   766  		t := time.After(duration)
   767  		c := make(chan bool)
   768  		for {
   769  			go func() {
   770  				growstack1()
   771  				c <- true
   772  			}()
   773  			select {
   774  			case <-t:
   775  				return
   776  			case <-c:
   777  			}
   778  		}
   779  	})
   780  }
   781  
   782  //go:noinline
   783  func growstack1() {
   784  	growstack(10)
   785  }
   786  
   787  //go:noinline
   788  func growstack(n int) {
   789  	var buf [8 << 18]byte
   790  	use(buf)
   791  	if n > 0 {
   792  		growstack(n - 1)
   793  	}
   794  }
   795  
   796  //go:noinline
   797  func use(x [8 << 18]byte) {}
   798  
   799  func TestBlockProfile(t *testing.T) {
   800  	type TestCase struct {
   801  		name string
   802  		f    func()
   803  		stk  []string
   804  		re   string
   805  	}
   806  	tests := [...]TestCase{
   807  		{
   808  			name: "chan recv",
   809  			f:    blockChanRecv,
   810  			stk: []string{
   811  				"runtime.chanrecv1",
   812  				"runtime/pprof.blockChanRecv",
   813  				"runtime/pprof.TestBlockProfile",
   814  			},
   815  			re: `
   816  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   817  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
   818  #	0x[0-9a-f]+	runtime/pprof\.blockChanRecv\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   819  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   820  `},
   821  		{
   822  			name: "chan send",
   823  			f:    blockChanSend,
   824  			stk: []string{
   825  				"runtime.chansend1",
   826  				"runtime/pprof.blockChanSend",
   827  				"runtime/pprof.TestBlockProfile",
   828  			},
   829  			re: `
   830  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   831  #	0x[0-9a-f]+	runtime\.chansend1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
   832  #	0x[0-9a-f]+	runtime/pprof\.blockChanSend\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   833  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   834  `},
   835  		{
   836  			name: "chan close",
   837  			f:    blockChanClose,
   838  			stk: []string{
   839  				"runtime.chanrecv1",
   840  				"runtime/pprof.blockChanClose",
   841  				"runtime/pprof.TestBlockProfile",
   842  			},
   843  			re: `
   844  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   845  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
   846  #	0x[0-9a-f]+	runtime/pprof\.blockChanClose\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   847  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   848  `},
   849  		{
   850  			name: "select recv async",
   851  			f:    blockSelectRecvAsync,
   852  			stk: []string{
   853  				"runtime.selectgo",
   854  				"runtime/pprof.blockSelectRecvAsync",
   855  				"runtime/pprof.TestBlockProfile",
   856  			},
   857  			re: `
   858  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   859  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*/src/runtime/select.go:[0-9]+
   860  #	0x[0-9a-f]+	runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   861  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   862  `},
   863  		{
   864  			name: "select send sync",
   865  			f:    blockSelectSendSync,
   866  			stk: []string{
   867  				"runtime.selectgo",
   868  				"runtime/pprof.blockSelectSendSync",
   869  				"runtime/pprof.TestBlockProfile",
   870  			},
   871  			re: `
   872  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   873  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*/src/runtime/select.go:[0-9]+
   874  #	0x[0-9a-f]+	runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   875  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   876  `},
   877  		{
   878  			name: "mutex",
   879  			f:    blockMutex,
   880  			stk: []string{
   881  				"sync.(*Mutex).Lock",
   882  				"runtime/pprof.blockMutex",
   883  				"runtime/pprof.TestBlockProfile",
   884  			},
   885  			re: `
   886  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   887  #	0x[0-9a-f]+	sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+	.*/src/sync/mutex\.go:[0-9]+
   888  #	0x[0-9a-f]+	runtime/pprof\.blockMutex\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   889  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   890  `},
   891  		{
   892  			name: "cond",
   893  			f:    blockCond,
   894  			stk: []string{
   895  				"sync.(*Cond).Wait",
   896  				"runtime/pprof.blockCond",
   897  				"runtime/pprof.TestBlockProfile",
   898  			},
   899  			re: `
   900  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   901  #	0x[0-9a-f]+	sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+	.*/src/sync/cond\.go:[0-9]+
   902  #	0x[0-9a-f]+	runtime/pprof\.blockCond\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   903  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   904  `},
   905  	}
   906  
   907  	// Generate block profile
   908  	runtime.SetBlockProfileRate(1)
   909  	defer runtime.SetBlockProfileRate(0)
   910  	for _, test := range tests {
   911  		test.f()
   912  	}
   913  
   914  	t.Run("debug=1", func(t *testing.T) {
   915  		var w bytes.Buffer
   916  		Lookup("block").WriteTo(&w, 1)
   917  		prof := w.String()
   918  
   919  		if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
   920  			t.Fatalf("Bad profile header:\n%v", prof)
   921  		}
   922  
   923  		if strings.HasSuffix(prof, "#\t0x0\n\n") {
   924  			t.Errorf("Useless 0 suffix:\n%v", prof)
   925  		}
   926  
   927  		for _, test := range tests {
   928  			if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) {
   929  				t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
   930  			}
   931  		}
   932  	})
   933  
   934  	t.Run("proto", func(t *testing.T) {
   935  		// proto format
   936  		var w bytes.Buffer
   937  		Lookup("block").WriteTo(&w, 0)
   938  		p, err := profile.Parse(&w)
   939  		if err != nil {
   940  			t.Fatalf("failed to parse profile: %v", err)
   941  		}
   942  		t.Logf("parsed proto: %s", p)
   943  		if err := p.CheckValid(); err != nil {
   944  			t.Fatalf("invalid profile: %v", err)
   945  		}
   946  
   947  		stks := stacks(p)
   948  		for _, test := range tests {
   949  			if !containsStack(stks, test.stk) {
   950  				t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk)
   951  			}
   952  		}
   953  	})
   954  
   955  }
   956  
   957  func stacks(p *profile.Profile) (res [][]string) {
   958  	for _, s := range p.Sample {
   959  		var stk []string
   960  		for _, l := range s.Location {
   961  			for _, line := range l.Line {
   962  				stk = append(stk, line.Function.Name)
   963  			}
   964  		}
   965  		res = append(res, stk)
   966  	}
   967  	return res
   968  }
   969  
   970  func containsStack(got [][]string, want []string) bool {
   971  	for _, stk := range got {
   972  		if len(stk) < len(want) {
   973  			continue
   974  		}
   975  		for i, f := range want {
   976  			if f != stk[i] {
   977  				break
   978  			}
   979  			if i == len(want)-1 {
   980  				return true
   981  			}
   982  		}
   983  	}
   984  	return false
   985  }
   986  
   987  const blockDelay = 10 * time.Millisecond
   988  
   989  func blockChanRecv() {
   990  	c := make(chan bool)
   991  	go func() {
   992  		time.Sleep(blockDelay)
   993  		c <- true
   994  	}()
   995  	<-c
   996  }
   997  
   998  func blockChanSend() {
   999  	c := make(chan bool)
  1000  	go func() {
  1001  		time.Sleep(blockDelay)
  1002  		<-c
  1003  	}()
  1004  	c <- true
  1005  }
  1006  
  1007  func blockChanClose() {
  1008  	c := make(chan bool)
  1009  	go func() {
  1010  		time.Sleep(blockDelay)
  1011  		close(c)
  1012  	}()
  1013  	<-c
  1014  }
  1015  
  1016  func blockSelectRecvAsync() {
  1017  	const numTries = 3
  1018  	c := make(chan bool, 1)
  1019  	c2 := make(chan bool, 1)
  1020  	go func() {
  1021  		for i := 0; i < numTries; i++ {
  1022  			time.Sleep(blockDelay)
  1023  			c <- true
  1024  		}
  1025  	}()
  1026  	for i := 0; i < numTries; i++ {
  1027  		select {
  1028  		case <-c:
  1029  		case <-c2:
  1030  		}
  1031  	}
  1032  }
  1033  
  1034  func blockSelectSendSync() {
  1035  	c := make(chan bool)
  1036  	c2 := make(chan bool)
  1037  	go func() {
  1038  		time.Sleep(blockDelay)
  1039  		<-c
  1040  	}()
  1041  	select {
  1042  	case c <- true:
  1043  	case c2 <- true:
  1044  	}
  1045  }
  1046  
  1047  func blockMutex() {
  1048  	var mu sync.Mutex
  1049  	mu.Lock()
  1050  	go func() {
  1051  		time.Sleep(blockDelay)
  1052  		mu.Unlock()
  1053  	}()
  1054  	// Note: Unlock releases mu before recording the mutex event,
  1055  	// so it's theoretically possible for this to proceed and
  1056  	// capture the profile before the event is recorded. As long
  1057  	// as this is blocked before the unlock happens, it's okay.
  1058  	mu.Lock()
  1059  }
  1060  
  1061  func blockCond() {
  1062  	var mu sync.Mutex
  1063  	c := sync.NewCond(&mu)
  1064  	mu.Lock()
  1065  	go func() {
  1066  		time.Sleep(blockDelay)
  1067  		mu.Lock()
  1068  		c.Signal()
  1069  		mu.Unlock()
  1070  	}()
  1071  	c.Wait()
  1072  	mu.Unlock()
  1073  }
  1074  
  1075  // See http://golang.org/cl/299991.
  1076  func TestBlockProfileBias(t *testing.T) {
  1077  	rate := int(1000) // arbitrary value
  1078  	runtime.SetBlockProfileRate(rate)
  1079  	defer runtime.SetBlockProfileRate(0)
  1080  
  1081  	// simulate blocking events
  1082  	blockFrequentShort(rate)
  1083  	blockInfrequentLong(rate)
  1084  
  1085  	var w bytes.Buffer
  1086  	Lookup("block").WriteTo(&w, 0)
  1087  	p, err := profile.Parse(&w)
  1088  	if err != nil {
  1089  		t.Fatalf("failed to parse profile: %v", err)
  1090  	}
  1091  	t.Logf("parsed proto: %s", p)
  1092  
  1093  	il := float64(-1) // blockInfrequentLong duration
  1094  	fs := float64(-1) // blockFrequentShort duration
  1095  	for _, s := range p.Sample {
  1096  		for _, l := range s.Location {
  1097  			for _, line := range l.Line {
  1098  				if len(s.Value) < 2 {
  1099  					t.Fatal("block profile has less than 2 sample types")
  1100  				}
  1101  
  1102  				if line.Function.Name == "runtime/pprof.blockInfrequentLong" {
  1103  					il = float64(s.Value[1])
  1104  				} else if line.Function.Name == "runtime/pprof.blockFrequentShort" {
  1105  					fs = float64(s.Value[1])
  1106  				}
  1107  			}
  1108  		}
  1109  	}
  1110  	if il == -1 || fs == -1 {
  1111  		t.Fatal("block profile is missing expected functions")
  1112  	}
  1113  
  1114  	// stddev of bias from 100 runs on local machine multiplied by 10x
  1115  	const threshold = 0.2
  1116  	if bias := (il - fs) / il; math.Abs(bias) > threshold {
  1117  		t.Fatalf("bias: abs(%f) > %f", bias, threshold)
  1118  	} else {
  1119  		t.Logf("bias: abs(%f) < %f", bias, threshold)
  1120  	}
  1121  }
  1122  
  1123  // blockFrequentShort produces 100000 block events with an average duration of
  1124  // rate / 10.
  1125  func blockFrequentShort(rate int) {
  1126  	for i := 0; i < 100000; i++ {
  1127  		blockevent(int64(rate/10), 1)
  1128  	}
  1129  }
  1130  
  1131  // blockFrequentShort produces 10000 block events with an average duration of
  1132  // rate.
  1133  func blockInfrequentLong(rate int) {
  1134  	for i := 0; i < 10000; i++ {
  1135  		blockevent(int64(rate), 1)
  1136  	}
  1137  }
  1138  
  1139  // Used by TestBlockProfileBias.
  1140  //go:linkname blockevent runtime.blockevent
  1141  func blockevent(cycles int64, skip int)
  1142  
  1143  func TestMutexProfile(t *testing.T) {
  1144  	// Generate mutex profile
  1145  
  1146  	old := runtime.SetMutexProfileFraction(1)
  1147  	defer runtime.SetMutexProfileFraction(old)
  1148  	if old != 0 {
  1149  		t.Fatalf("need MutexProfileRate 0, got %d", old)
  1150  	}
  1151  
  1152  	blockMutex()
  1153  
  1154  	t.Run("debug=1", func(t *testing.T) {
  1155  		var w bytes.Buffer
  1156  		Lookup("mutex").WriteTo(&w, 1)
  1157  		prof := w.String()
  1158  		t.Logf("received profile: %v", prof)
  1159  
  1160  		if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") {
  1161  			t.Errorf("Bad profile header:\n%v", prof)
  1162  		}
  1163  		prof = strings.Trim(prof, "\n")
  1164  		lines := strings.Split(prof, "\n")
  1165  		if len(lines) != 6 {
  1166  			t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof)
  1167  		}
  1168  		if len(lines) < 6 {
  1169  			return
  1170  		}
  1171  		// checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931"
  1172  		r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+`
  1173  		//r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$"
  1174  		if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok {
  1175  			t.Errorf("%q didn't match %q", lines[3], r2)
  1176  		}
  1177  		r3 := "^#.*runtime/pprof.blockMutex.*$"
  1178  		if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok {
  1179  			t.Errorf("%q didn't match %q", lines[5], r3)
  1180  		}
  1181  		t.Logf(prof)
  1182  	})
  1183  	t.Run("proto", func(t *testing.T) {
  1184  		// proto format
  1185  		var w bytes.Buffer
  1186  		Lookup("mutex").WriteTo(&w, 0)
  1187  		p, err := profile.Parse(&w)
  1188  		if err != nil {
  1189  			t.Fatalf("failed to parse profile: %v", err)
  1190  		}
  1191  		t.Logf("parsed proto: %s", p)
  1192  		if err := p.CheckValid(); err != nil {
  1193  			t.Fatalf("invalid profile: %v", err)
  1194  		}
  1195  
  1196  		stks := stacks(p)
  1197  		for _, want := range [][]string{
  1198  			{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutex.func1"},
  1199  		} {
  1200  			if !containsStack(stks, want) {
  1201  				t.Errorf("No matching stack entry for %+v", want)
  1202  			}
  1203  		}
  1204  	})
  1205  }
  1206  
  1207  func func1(c chan int) { <-c }
  1208  func func2(c chan int) { <-c }
  1209  func func3(c chan int) { <-c }
  1210  func func4(c chan int) { <-c }
  1211  
  1212  func TestGoroutineCounts(t *testing.T) {
  1213  	// Setting GOMAXPROCS to 1 ensures we can force all goroutines to the
  1214  	// desired blocking point.
  1215  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
  1216  
  1217  	c := make(chan int)
  1218  	for i := 0; i < 100; i++ {
  1219  		switch {
  1220  		case i%10 == 0:
  1221  			go func1(c)
  1222  		case i%2 == 0:
  1223  			go func2(c)
  1224  		default:
  1225  			go func3(c)
  1226  		}
  1227  		// Let goroutines block on channel
  1228  		for j := 0; j < 5; j++ {
  1229  			runtime.Gosched()
  1230  		}
  1231  	}
  1232  	ctx := context.Background()
  1233  
  1234  	// ... and again, with labels this time (just with fewer iterations to keep
  1235  	// sorting deterministic).
  1236  	Do(ctx, Labels("label", "value"), func(context.Context) {
  1237  		for i := 0; i < 89; i++ {
  1238  			switch {
  1239  			case i%10 == 0:
  1240  				go func1(c)
  1241  			case i%2 == 0:
  1242  				go func2(c)
  1243  			default:
  1244  				go func3(c)
  1245  			}
  1246  			// Let goroutines block on channel
  1247  			for j := 0; j < 5; j++ {
  1248  				runtime.Gosched()
  1249  			}
  1250  		}
  1251  	})
  1252  
  1253  	var w bytes.Buffer
  1254  	goroutineProf := Lookup("goroutine")
  1255  
  1256  	// Check debug profile
  1257  	goroutineProf.WriteTo(&w, 1)
  1258  	prof := w.String()
  1259  
  1260  	labels := labelMap{"label": "value"}
  1261  	labelStr := "\n# labels: " + labels.String()
  1262  	if !containsInOrder(prof, "\n50 @ ", "\n44 @", labelStr,
  1263  		"\n40 @", "\n36 @", labelStr, "\n10 @", "\n9 @", labelStr, "\n1 @") {
  1264  		t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
  1265  	}
  1266  
  1267  	// Check proto profile
  1268  	w.Reset()
  1269  	goroutineProf.WriteTo(&w, 0)
  1270  	p, err := profile.Parse(&w)
  1271  	if err != nil {
  1272  		t.Errorf("error parsing protobuf profile: %v", err)
  1273  	}
  1274  	if err := p.CheckValid(); err != nil {
  1275  		t.Errorf("protobuf profile is invalid: %v", err)
  1276  	}
  1277  	expectedLabels := map[int64]map[string]string{
  1278  		50: map[string]string{},
  1279  		44: map[string]string{"label": "value"},
  1280  		40: map[string]string{},
  1281  		36: map[string]string{"label": "value"},
  1282  		10: map[string]string{},
  1283  		9:  map[string]string{"label": "value"},
  1284  		1:  map[string]string{},
  1285  	}
  1286  	if !containsCountsLabels(p, expectedLabels) {
  1287  		t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v",
  1288  			expectedLabels, p)
  1289  	}
  1290  
  1291  	close(c)
  1292  
  1293  	time.Sleep(10 * time.Millisecond) // let goroutines exit
  1294  }
  1295  
  1296  func containsInOrder(s string, all ...string) bool {
  1297  	for _, t := range all {
  1298  		var ok bool
  1299  		if _, s, ok = strings.Cut(s, t); !ok {
  1300  			return false
  1301  		}
  1302  	}
  1303  	return true
  1304  }
  1305  
  1306  func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool {
  1307  	m := make(map[int64]int)
  1308  	type nkey struct {
  1309  		count    int64
  1310  		key, val string
  1311  	}
  1312  	n := make(map[nkey]int)
  1313  	for c, kv := range countLabels {
  1314  		m[c]++
  1315  		for k, v := range kv {
  1316  			n[nkey{
  1317  				count: c,
  1318  				key:   k,
  1319  				val:   v,
  1320  			}]++
  1321  
  1322  		}
  1323  	}
  1324  	for _, s := range prof.Sample {
  1325  		// The count is the single value in the sample
  1326  		if len(s.Value) != 1 {
  1327  			return false
  1328  		}
  1329  		m[s.Value[0]]--
  1330  		for k, vs := range s.Label {
  1331  			for _, v := range vs {
  1332  				n[nkey{
  1333  					count: s.Value[0],
  1334  					key:   k,
  1335  					val:   v,
  1336  				}]--
  1337  			}
  1338  		}
  1339  	}
  1340  	for _, n := range m {
  1341  		if n > 0 {
  1342  			return false
  1343  		}
  1344  	}
  1345  	for _, ncnt := range n {
  1346  		if ncnt != 0 {
  1347  			return false
  1348  		}
  1349  	}
  1350  	return true
  1351  }
  1352  
  1353  var emptyCallStackTestRun int64
  1354  
  1355  // Issue 18836.
  1356  func TestEmptyCallStack(t *testing.T) {
  1357  	name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun)
  1358  	emptyCallStackTestRun++
  1359  
  1360  	t.Parallel()
  1361  	var buf bytes.Buffer
  1362  	p := NewProfile(name)
  1363  
  1364  	p.Add("foo", 47674)
  1365  	p.WriteTo(&buf, 1)
  1366  	p.Remove("foo")
  1367  	got := buf.String()
  1368  	prefix := name + " profile: total 1\n"
  1369  	if !strings.HasPrefix(got, prefix) {
  1370  		t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix)
  1371  	}
  1372  	lostevent := "lostProfileEvent"
  1373  	if !strings.Contains(got, lostevent) {
  1374  		t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent)
  1375  	}
  1376  }
  1377  
  1378  // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key
  1379  // and value and has funcname somewhere in the stack.
  1380  func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
  1381  	base, kv, ok := strings.Cut(spec, ";")
  1382  	if !ok {
  1383  		panic("no semicolon in key/value spec")
  1384  	}
  1385  	k, v, ok := strings.Cut(kv, "=")
  1386  	if !ok {
  1387  		panic("missing = in key/value spec")
  1388  	}
  1389  	if !contains(labels[k], v) {
  1390  		return false
  1391  	}
  1392  	return stackContains(base, count, stk, labels)
  1393  }
  1394  
  1395  func TestCPUProfileLabel(t *testing.T) {
  1396  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions())
  1397  	testCPUProfile(t, matches, func(dur time.Duration) {
  1398  		Do(context.Background(), Labels("key", "value"), func(context.Context) {
  1399  			cpuHogger(cpuHog1, &salt1, dur)
  1400  		})
  1401  	})
  1402  }
  1403  
  1404  func TestLabelRace(t *testing.T) {
  1405  	// Test the race detector annotations for synchronization
  1406  	// between settings labels and consuming them from the
  1407  	// profile.
  1408  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil)
  1409  	testCPUProfile(t, matches, func(dur time.Duration) {
  1410  		start := time.Now()
  1411  		var wg sync.WaitGroup
  1412  		for time.Since(start) < dur {
  1413  			var salts [10]int
  1414  			for i := 0; i < 10; i++ {
  1415  				wg.Add(1)
  1416  				go func(j int) {
  1417  					Do(context.Background(), Labels("key", "value"), func(context.Context) {
  1418  						cpuHogger(cpuHog1, &salts[j], time.Millisecond)
  1419  					})
  1420  					wg.Done()
  1421  				}(i)
  1422  			}
  1423  			wg.Wait()
  1424  		}
  1425  	})
  1426  }
  1427  
  1428  // TestLabelSystemstack makes sure CPU profiler samples of goroutines running
  1429  // on systemstack include the correct pprof labels. See issue #48577
  1430  func TestLabelSystemstack(t *testing.T) {
  1431  	// Grab and re-set the initial value before continuing to ensure
  1432  	// GOGC doesn't actually change following the test.
  1433  	gogc := debug.SetGCPercent(100)
  1434  	debug.SetGCPercent(gogc)
  1435  
  1436  	matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions())
  1437  	p := testCPUProfile(t, matches, func(dur time.Duration) {
  1438  		Do(context.Background(), Labels("key", "value"), func(context.Context) {
  1439  			var wg sync.WaitGroup
  1440  			stop := make(chan struct{})
  1441  			for i := 0; i < runtime.GOMAXPROCS(0); i++ {
  1442  				wg.Add(1)
  1443  				go func() {
  1444  					defer wg.Done()
  1445  					labelHog(stop, gogc)
  1446  				}()
  1447  			}
  1448  
  1449  			time.Sleep(dur)
  1450  			close(stop)
  1451  			wg.Wait()
  1452  		})
  1453  	})
  1454  
  1455  	// labelHog should always be labeled.
  1456  	for _, s := range p.Sample {
  1457  		for _, loc := range s.Location {
  1458  			for _, l := range loc.Line {
  1459  				if l.Function.Name != "runtime/pprof.labelHog" {
  1460  					continue
  1461  				}
  1462  
  1463  				if s.Label == nil {
  1464  					t.Errorf("labelHog sample labels got nil want key=value")
  1465  					continue
  1466  				}
  1467  				if !contains(s.Label["key"], "value") {
  1468  					t.Errorf("labelHog sample labels got %+v want contains key=value", s.Label)
  1469  					continue
  1470  				}
  1471  			}
  1472  		}
  1473  	}
  1474  }
  1475  
  1476  // labelHog is designed to burn CPU time in a way that a high number of CPU
  1477  // samples end up running on systemstack.
  1478  func labelHog(stop chan struct{}, gogc int) {
  1479  	for i := 0; ; i++ {
  1480  		select {
  1481  		case <-stop:
  1482  			return
  1483  		default:
  1484  			debug.SetGCPercent(gogc)
  1485  		}
  1486  	}
  1487  }
  1488  
  1489  // Check that there is no deadlock when the program receives SIGPROF while in
  1490  // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146.
  1491  func TestAtomicLoadStore64(t *testing.T) {
  1492  	f, err := os.CreateTemp("", "profatomic")
  1493  	if err != nil {
  1494  		t.Fatalf("TempFile: %v", err)
  1495  	}
  1496  	defer os.Remove(f.Name())
  1497  	defer f.Close()
  1498  
  1499  	if err := StartCPUProfile(f); err != nil {
  1500  		t.Fatal(err)
  1501  	}
  1502  	defer StopCPUProfile()
  1503  
  1504  	var flag uint64
  1505  	done := make(chan bool, 1)
  1506  
  1507  	go func() {
  1508  		for atomic.LoadUint64(&flag) == 0 {
  1509  			runtime.Gosched()
  1510  		}
  1511  		done <- true
  1512  	}()
  1513  	time.Sleep(50 * time.Millisecond)
  1514  	atomic.StoreUint64(&flag, 1)
  1515  	<-done
  1516  }
  1517  
  1518  func TestTracebackAll(t *testing.T) {
  1519  	// With gccgo, if a profiling signal arrives at the wrong time
  1520  	// during traceback, it may crash or hang. See issue #29448.
  1521  	f, err := os.CreateTemp("", "proftraceback")
  1522  	if err != nil {
  1523  		t.Fatalf("TempFile: %v", err)
  1524  	}
  1525  	defer os.Remove(f.Name())
  1526  	defer f.Close()
  1527  
  1528  	if err := StartCPUProfile(f); err != nil {
  1529  		t.Fatal(err)
  1530  	}
  1531  	defer StopCPUProfile()
  1532  
  1533  	ch := make(chan int)
  1534  	defer close(ch)
  1535  
  1536  	count := 10
  1537  	for i := 0; i < count; i++ {
  1538  		go func() {
  1539  			<-ch // block
  1540  		}()
  1541  	}
  1542  
  1543  	N := 10000
  1544  	if testing.Short() {
  1545  		N = 500
  1546  	}
  1547  	buf := make([]byte, 10*1024)
  1548  	for i := 0; i < N; i++ {
  1549  		runtime.Stack(buf, true)
  1550  	}
  1551  }
  1552  
  1553  // TestTryAdd tests the cases that are hard to test with real program execution.
  1554  //
  1555  // For example, the current go compilers may not always inline functions
  1556  // involved in recursion but that may not be true in the future compilers. This
  1557  // tests such cases by using fake call sequences and forcing the profile build
  1558  // utilizing translateCPUProfile defined in proto_test.go
  1559  func TestTryAdd(t *testing.T) {
  1560  	if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found {
  1561  		t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.")
  1562  	}
  1563  
  1564  	// inlinedCallerDump
  1565  	//   inlinedCalleeDump
  1566  	pcs := make([]uintptr, 2)
  1567  	inlinedCallerDump(pcs)
  1568  	inlinedCallerStack := make([]uint64, 2)
  1569  	for i := range pcs {
  1570  		inlinedCallerStack[i] = uint64(pcs[i])
  1571  	}
  1572  
  1573  	if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found {
  1574  		t.Skip("Can't determine whether anything was inlined into recursionChainBottom.")
  1575  	}
  1576  
  1577  	// recursionChainTop
  1578  	//   recursionChainMiddle
  1579  	//     recursionChainBottom
  1580  	//       recursionChainTop
  1581  	//         recursionChainMiddle
  1582  	//           recursionChainBottom
  1583  	pcs = make([]uintptr, 6)
  1584  	recursionChainTop(1, pcs)
  1585  	recursionStack := make([]uint64, len(pcs))
  1586  	for i := range pcs {
  1587  		recursionStack[i] = uint64(pcs[i])
  1588  	}
  1589  
  1590  	period := int64(2000 * 1000) // 1/500*1e9 nanosec.
  1591  
  1592  	testCases := []struct {
  1593  		name        string
  1594  		input       []uint64          // following the input format assumed by profileBuilder.addCPUData.
  1595  		count       int               // number of records in input.
  1596  		wantLocs    [][]string        // ordered location entries with function names.
  1597  		wantSamples []*profile.Sample // ordered samples, we care only about Value and the profile location IDs.
  1598  	}{{
  1599  		// Sanity test for a normal, complete stack trace.
  1600  		name: "full_stack_trace",
  1601  		input: []uint64{
  1602  			3, 0, 500, // hz = 500. Must match the period.
  1603  			5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
  1604  		},
  1605  		count: 2,
  1606  		wantLocs: [][]string{
  1607  			{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
  1608  		},
  1609  		wantSamples: []*profile.Sample{
  1610  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  1611  		},
  1612  	}, {
  1613  		name: "bug35538",
  1614  		input: []uint64{
  1615  			3, 0, 500, // hz = 500. Must match the period.
  1616  			// Fake frame: tryAdd will have inlinedCallerDump
  1617  			// (stack[1]) on the deck when it encounters the next
  1618  			// inline function. It should accept this.
  1619  			7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1],
  1620  			5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1],
  1621  		},
  1622  		count:    3,
  1623  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  1624  		wantSamples: []*profile.Sample{
  1625  			{Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}},
  1626  			{Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}},
  1627  		},
  1628  	}, {
  1629  		name: "bug38096",
  1630  		input: []uint64{
  1631  			3, 0, 500, // hz = 500. Must match the period.
  1632  			// count (data[2]) == 0 && len(stk) == 1 is an overflow
  1633  			// entry. The "stk" entry is actually the count.
  1634  			4, 0, 0, 4242,
  1635  		},
  1636  		count:    2,
  1637  		wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}},
  1638  		wantSamples: []*profile.Sample{
  1639  			{Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}},
  1640  		},
  1641  	}, {
  1642  		// If a function is directly called recursively then it must
  1643  		// not be inlined in the caller.
  1644  		//
  1645  		// N.B. We're generating an impossible profile here, with a
  1646  		// recursive inlineCalleeDump call. This is simulating a non-Go
  1647  		// function that looks like an inlined Go function other than
  1648  		// its recursive property. See pcDeck.tryAdd.
  1649  		name: "directly_recursive_func_is_not_inlined",
  1650  		input: []uint64{
  1651  			3, 0, 500, // hz = 500. Must match the period.
  1652  			5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0],
  1653  			4, 0, 40, inlinedCallerStack[0],
  1654  		},
  1655  		count: 3,
  1656  		// inlinedCallerDump shows up here because
  1657  		// runtime_expandFinalInlineFrame adds it to the stack frame.
  1658  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}},
  1659  		wantSamples: []*profile.Sample{
  1660  			{Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}},
  1661  			{Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}},
  1662  		},
  1663  	}, {
  1664  		name: "recursion_chain_inline",
  1665  		input: []uint64{
  1666  			3, 0, 500, // hz = 500. Must match the period.
  1667  			9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5],
  1668  		},
  1669  		count: 2,
  1670  		wantLocs: [][]string{
  1671  			{"runtime/pprof.recursionChainBottom"},
  1672  			{
  1673  				"runtime/pprof.recursionChainMiddle",
  1674  				"runtime/pprof.recursionChainTop",
  1675  				"runtime/pprof.recursionChainBottom",
  1676  			},
  1677  			{
  1678  				"runtime/pprof.recursionChainMiddle",
  1679  				"runtime/pprof.recursionChainTop",
  1680  				"runtime/pprof.TestTryAdd", // inlined into the test.
  1681  			},
  1682  		},
  1683  		wantSamples: []*profile.Sample{
  1684  			{Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}},
  1685  		},
  1686  	}, {
  1687  		name: "truncated_stack_trace_later",
  1688  		input: []uint64{
  1689  			3, 0, 500, // hz = 500. Must match the period.
  1690  			5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
  1691  			4, 0, 60, inlinedCallerStack[0],
  1692  		},
  1693  		count:    3,
  1694  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  1695  		wantSamples: []*profile.Sample{
  1696  			{Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
  1697  			{Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}},
  1698  		},
  1699  	}, {
  1700  		name: "truncated_stack_trace_first",
  1701  		input: []uint64{
  1702  			3, 0, 500, // hz = 500. Must match the period.
  1703  			4, 0, 70, inlinedCallerStack[0],
  1704  			5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1],
  1705  		},
  1706  		count:    3,
  1707  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  1708  		wantSamples: []*profile.Sample{
  1709  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  1710  			{Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}},
  1711  		},
  1712  	}, {
  1713  		// We can recover the inlined caller from a truncated stack.
  1714  		name: "truncated_stack_trace_only",
  1715  		input: []uint64{
  1716  			3, 0, 500, // hz = 500. Must match the period.
  1717  			4, 0, 70, inlinedCallerStack[0],
  1718  		},
  1719  		count:    2,
  1720  		wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
  1721  		wantSamples: []*profile.Sample{
  1722  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  1723  		},
  1724  	}, {
  1725  		// The same location is used for duplicated stacks.
  1726  		name: "truncated_stack_trace_twice",
  1727  		input: []uint64{
  1728  			3, 0, 500, // hz = 500. Must match the period.
  1729  			4, 0, 70, inlinedCallerStack[0],
  1730  			// Fake frame: add a fake call to
  1731  			// inlinedCallerDump to prevent this sample
  1732  			// from getting merged into above.
  1733  			5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0],
  1734  		},
  1735  		count: 3,
  1736  		wantLocs: [][]string{
  1737  			{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
  1738  			{"runtime/pprof.inlinedCallerDump"},
  1739  		},
  1740  		wantSamples: []*profile.Sample{
  1741  			{Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
  1742  			{Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}},
  1743  		},
  1744  	}}
  1745  
  1746  	for _, tc := range testCases {
  1747  		t.Run(tc.name, func(t *testing.T) {
  1748  			p, err := translateCPUProfile(tc.input, tc.count)
  1749  			if err != nil {
  1750  				t.Fatalf("translating profile: %v", err)
  1751  			}
  1752  			t.Logf("Profile: %v\n", p)
  1753  
  1754  			// One location entry with all inlined functions.
  1755  			var gotLoc [][]string
  1756  			for _, loc := range p.Location {
  1757  				var names []string
  1758  				for _, line := range loc.Line {
  1759  					names = append(names, line.Function.Name)
  1760  				}
  1761  				gotLoc = append(gotLoc, names)
  1762  			}
  1763  			if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want {
  1764  				t.Errorf("Got Location = %+v\n\twant %+v", got, want)
  1765  			}
  1766  			// All samples should point to one location.
  1767  			var gotSamples []*profile.Sample
  1768  			for _, sample := range p.Sample {
  1769  				var locs []*profile.Location
  1770  				for _, loc := range sample.Location {
  1771  					locs = append(locs, &profile.Location{ID: loc.ID})
  1772  				}
  1773  				gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs})
  1774  			}
  1775  			if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want {
  1776  				t.Errorf("Got Samples = %+v\n\twant %+v", got, want)
  1777  			}
  1778  		})
  1779  	}
  1780  }
  1781  
  1782  func TestTimeVDSO(t *testing.T) {
  1783  	// Test that time functions have the right stack trace. In particular,
  1784  	// it shouldn't be recursive.
  1785  
  1786  	if runtime.GOOS == "android" {
  1787  		// Flaky on Android, issue 48655. VDSO may not be enabled.
  1788  		testenv.SkipFlaky(t, 48655)
  1789  	}
  1790  
  1791  	matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions())
  1792  	p := testCPUProfile(t, matches, func(dur time.Duration) {
  1793  		t0 := time.Now()
  1794  		for {
  1795  			t := time.Now()
  1796  			if t.Sub(t0) >= dur {
  1797  				return
  1798  			}
  1799  		}
  1800  	})
  1801  
  1802  	// Check for recursive time.now sample.
  1803  	for _, sample := range p.Sample {
  1804  		var seenNow bool
  1805  		for _, loc := range sample.Location {
  1806  			for _, line := range loc.Line {
  1807  				if line.Function.Name == "time.now" {
  1808  					if seenNow {
  1809  						t.Fatalf("unexpected recursive time.now")
  1810  					}
  1811  					seenNow = true
  1812  				}
  1813  			}
  1814  		}
  1815  	}
  1816  }