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

View as plain text