github.com/zxy12/go_duplicate_112_new@v0.0.0-20200807091221-747231827200/src/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  // +build !aix,!nacl,!js
     6  
     7  package pprof
     8  
     9  import (
    10  	"bytes"
    11  	"context"
    12  	"fmt"
    13  	"internal/testenv"
    14  	"io"
    15  	"io/ioutil"
    16  	"math/big"
    17  	"os"
    18  	"os/exec"
    19  	"regexp"
    20  	"runtime"
    21  	"runtime/pprof/internal/profile"
    22  	"strings"
    23  	"sync"
    24  	"sync/atomic"
    25  	"testing"
    26  	"time"
    27  )
    28  
    29  func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
    30  	// We only need to get one 100 Hz clock tick, so we've got
    31  	// a large safety buffer.
    32  	// But do at least 500 iterations (which should take about 100ms),
    33  	// otherwise TestCPUProfileMultithreaded can fail if only one
    34  	// thread is scheduled during the testing period.
    35  	t0 := time.Now()
    36  	accum := *y
    37  	for i := 0; i < 500 || time.Since(t0) < dur; i++ {
    38  		accum = f(accum)
    39  	}
    40  	*y = accum
    41  }
    42  
    43  var (
    44  	salt1 = 0
    45  	salt2 = 0
    46  )
    47  
    48  // The actual CPU hogging function.
    49  // Must not call other functions nor access heap/globals in the loop,
    50  // otherwise under race detector the samples will be in the race runtime.
    51  func cpuHog1(x int) int {
    52  	foo := x
    53  	for i := 0; i < 1e5; i++ {
    54  		if foo > 0 {
    55  			foo *= foo
    56  		} else {
    57  			foo *= foo + 1
    58  		}
    59  	}
    60  	return foo
    61  }
    62  
    63  func cpuHog2(x int) int {
    64  	foo := x
    65  	for i := 0; i < 1e5; i++ {
    66  		if foo > 0 {
    67  			foo *= foo
    68  		} else {
    69  			foo *= foo + 2
    70  		}
    71  	}
    72  	return foo
    73  }
    74  
    75  // Return a list of functions that we don't want to ever appear in CPU
    76  // profiles. For gccgo, that list includes the sigprof handler itself.
    77  func avoidFunctions() []string {
    78  	if runtime.Compiler == "gccgo" {
    79  		return []string{"runtime.sigprof"}
    80  	}
    81  	return nil
    82  }
    83  
    84  func TestCPUProfile(t *testing.T) {
    85  	testCPUProfile(t, stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions(), func(dur time.Duration) {
    86  		cpuHogger(cpuHog1, &salt1, dur)
    87  	})
    88  }
    89  
    90  func TestCPUProfileMultithreaded(t *testing.T) {
    91  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
    92  	testCPUProfile(t, stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions(), func(dur time.Duration) {
    93  		c := make(chan int)
    94  		go func() {
    95  			cpuHogger(cpuHog1, &salt1, dur)
    96  			c <- 1
    97  		}()
    98  		cpuHogger(cpuHog2, &salt2, dur)
    99  		<-c
   100  	})
   101  }
   102  
   103  func TestCPUProfileInlining(t *testing.T) {
   104  	testCPUProfile(t, stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions(), func(dur time.Duration) {
   105  		cpuHogger(inlinedCaller, &salt1, dur)
   106  	})
   107  }
   108  
   109  func inlinedCaller(x int) int {
   110  	x = inlinedCallee(x)
   111  	return x
   112  }
   113  
   114  func inlinedCallee(x int) int {
   115  	// We could just use cpuHog1, but for loops prevent inlining
   116  	// right now. :(
   117  	foo := x
   118  	i := 0
   119  loop:
   120  	if foo > 0 {
   121  		foo *= foo
   122  	} else {
   123  		foo *= foo + 1
   124  	}
   125  	if i++; i < 1e5 {
   126  		goto loop
   127  	}
   128  	return foo
   129  }
   130  
   131  func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) {
   132  	p, err := profile.Parse(bytes.NewReader(valBytes))
   133  	if err != nil {
   134  		t.Fatal(err)
   135  	}
   136  	for _, sample := range p.Sample {
   137  		count := uintptr(sample.Value[0])
   138  		f(count, sample.Location, sample.Label)
   139  	}
   140  }
   141  
   142  // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need,
   143  // as interpreted by matches.
   144  func testCPUProfile(t *testing.T, matches matchFunc, need []string, avoid []string, f func(dur time.Duration)) {
   145  	switch runtime.GOOS {
   146  	case "darwin":
   147  		switch runtime.GOARCH {
   148  		case "arm", "arm64":
   149  			// nothing
   150  		default:
   151  			out, err := exec.Command("uname", "-a").CombinedOutput()
   152  			if err != nil {
   153  				t.Fatal(err)
   154  			}
   155  			vers := string(out)
   156  			t.Logf("uname -a: %v", vers)
   157  		}
   158  	case "plan9":
   159  		t.Skip("skipping on plan9")
   160  	}
   161  
   162  	const maxDuration = 5 * time.Second
   163  	// If we're running a long test, start with a long duration
   164  	// for tests that try to make sure something *doesn't* happen.
   165  	duration := 5 * time.Second
   166  	if testing.Short() {
   167  		duration = 200 * time.Millisecond
   168  	}
   169  
   170  	// Profiling tests are inherently flaky, especially on a
   171  	// loaded system, such as when this test is running with
   172  	// several others under go test std. If a test fails in a way
   173  	// that could mean it just didn't run long enough, try with a
   174  	// longer duration.
   175  	for duration <= maxDuration {
   176  		var prof bytes.Buffer
   177  		if err := StartCPUProfile(&prof); err != nil {
   178  			t.Fatal(err)
   179  		}
   180  		f(duration)
   181  		StopCPUProfile()
   182  
   183  		if profileOk(t, matches, need, avoid, prof, duration) {
   184  			return
   185  		}
   186  
   187  		duration *= 2
   188  		if duration <= maxDuration {
   189  			t.Logf("retrying with %s duration", duration)
   190  		}
   191  	}
   192  
   193  	switch runtime.GOOS {
   194  	case "darwin", "dragonfly", "netbsd", "solaris":
   195  		t.Skipf("ignoring failure on %s; see golang.org/issue/13841", runtime.GOOS)
   196  	case "openbsd":
   197  		if runtime.GOARCH == "arm" {
   198  			t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH)
   199  		}
   200  	}
   201  	// Ignore the failure if the tests are running in a QEMU-based emulator,
   202  	// QEMU is not perfect at emulating everything.
   203  	// IN_QEMU environmental variable is set by some of the Go builders.
   204  	// IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
   205  	if os.Getenv("IN_QEMU") == "1" {
   206  		t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
   207  	}
   208  	t.FailNow()
   209  }
   210  
   211  func contains(slice []string, s string) bool {
   212  	for i := range slice {
   213  		if slice[i] == s {
   214  			return true
   215  		}
   216  	}
   217  	return false
   218  }
   219  
   220  // stackContains matches if a function named spec appears anywhere in the stack trace.
   221  func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   222  	for _, loc := range stk {
   223  		for _, line := range loc.Line {
   224  			if strings.Contains(line.Function.Name, spec) {
   225  				return true
   226  			}
   227  		}
   228  	}
   229  	return false
   230  }
   231  
   232  type matchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool
   233  
   234  func profileOk(t *testing.T, matches matchFunc, need []string, avoid []string, prof bytes.Buffer, duration time.Duration) (ok bool) {
   235  	ok = true
   236  
   237  	// Check that profile is well formed, contains 'need', and does not contain
   238  	// anything from 'avoid'.
   239  	have := make([]uintptr, len(need))
   240  	avoidSamples := make([]uintptr, len(avoid))
   241  	var samples uintptr
   242  	var buf bytes.Buffer
   243  	parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) {
   244  		fmt.Fprintf(&buf, "%d:", count)
   245  		fprintStack(&buf, stk)
   246  		samples += count
   247  		for i, spec := range need {
   248  			if matches(spec, count, stk, labels) {
   249  				have[i] += count
   250  			}
   251  		}
   252  		for i, name := range avoid {
   253  			for _, loc := range stk {
   254  				for _, line := range loc.Line {
   255  					if strings.Contains(line.Function.Name, name) {
   256  						avoidSamples[i] += count
   257  					}
   258  				}
   259  			}
   260  		}
   261  		fmt.Fprintf(&buf, "\n")
   262  	})
   263  	t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String())
   264  
   265  	if samples < 10 && runtime.GOOS == "windows" {
   266  		// On some windows machines we end up with
   267  		// not enough samples due to coarse timer
   268  		// resolution. Let it go.
   269  		t.Log("too few samples on Windows (golang.org/issue/10842)")
   270  		return false
   271  	}
   272  
   273  	// Check that we got a reasonable number of samples.
   274  	// We used to always require at least ideal/4 samples,
   275  	// but that is too hard to guarantee on a loaded system.
   276  	// Now we accept 10 or more samples, which we take to be
   277  	// enough to show that at least some profiling is occurring.
   278  	if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) {
   279  		t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
   280  		ok = false
   281  	}
   282  
   283  	for i, name := range avoid {
   284  		bad := avoidSamples[i]
   285  		if bad != 0 {
   286  			t.Logf("found %d samples in avoid-function %s\n", bad, name)
   287  			ok = false
   288  		}
   289  	}
   290  
   291  	if len(need) == 0 {
   292  		return ok
   293  	}
   294  
   295  	var total uintptr
   296  	for i, name := range need {
   297  		total += have[i]
   298  		t.Logf("%s: %d\n", name, have[i])
   299  	}
   300  	if total == 0 {
   301  		t.Logf("no samples in expected functions")
   302  		ok = false
   303  	}
   304  	// We'd like to check a reasonable minimum, like
   305  	// total / len(have) / smallconstant, but this test is
   306  	// pretty flaky (see bug 7095).  So we'll just test to
   307  	// make sure we got at least one sample.
   308  	min := uintptr(1)
   309  	for i, name := range need {
   310  		if have[i] < min {
   311  			t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
   312  			ok = false
   313  		}
   314  	}
   315  	return ok
   316  }
   317  
   318  // Fork can hang if preempted with signals frequently enough (see issue 5517).
   319  // Ensure that we do not do this.
   320  func TestCPUProfileWithFork(t *testing.T) {
   321  	testenv.MustHaveExec(t)
   322  
   323  	heap := 1 << 30
   324  	if runtime.GOOS == "android" {
   325  		// Use smaller size for Android to avoid crash.
   326  		heap = 100 << 20
   327  	}
   328  	if runtime.GOOS == "windows" && runtime.GOARCH == "arm" {
   329  		// Use smaller heap for Windows/ARM to avoid crash.
   330  		heap = 100 << 20
   331  	}
   332  	if testing.Short() {
   333  		heap = 100 << 20
   334  	}
   335  	// This makes fork slower.
   336  	garbage := make([]byte, heap)
   337  	// Need to touch the slice, otherwise it won't be paged in.
   338  	done := make(chan bool)
   339  	go func() {
   340  		for i := range garbage {
   341  			garbage[i] = 42
   342  		}
   343  		done <- true
   344  	}()
   345  	<-done
   346  
   347  	var prof bytes.Buffer
   348  	if err := StartCPUProfile(&prof); err != nil {
   349  		t.Fatal(err)
   350  	}
   351  	defer StopCPUProfile()
   352  
   353  	for i := 0; i < 10; i++ {
   354  		exec.Command(os.Args[0], "-h").CombinedOutput()
   355  	}
   356  }
   357  
   358  // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
   359  // If it did, it would see inconsistent state and would either record an incorrect stack
   360  // or crash because the stack was malformed.
   361  func TestGoroutineSwitch(t *testing.T) {
   362  	if runtime.Compiler == "gccgo" {
   363  		t.Skip("not applicable for gccgo")
   364  	}
   365  	// How much to try. These defaults take about 1 seconds
   366  	// on a 2012 MacBook Pro. The ones in short mode take
   367  	// about 0.1 seconds.
   368  	tries := 10
   369  	count := 1000000
   370  	if testing.Short() {
   371  		tries = 1
   372  	}
   373  	for try := 0; try < tries; try++ {
   374  		var prof bytes.Buffer
   375  		if err := StartCPUProfile(&prof); err != nil {
   376  			t.Fatal(err)
   377  		}
   378  		for i := 0; i < count; i++ {
   379  			runtime.Gosched()
   380  		}
   381  		StopCPUProfile()
   382  
   383  		// Read profile to look for entries for runtime.gogo with an attempt at a traceback.
   384  		// The special entry
   385  		parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) {
   386  			// An entry with two frames with 'System' in its top frame
   387  			// exists to record a PC without a traceback. Those are okay.
   388  			if len(stk) == 2 {
   389  				name := stk[1].Line[0].Function.Name
   390  				if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" {
   391  					return
   392  				}
   393  			}
   394  
   395  			// Otherwise, should not see runtime.gogo.
   396  			// The place we'd see it would be the inner most frame.
   397  			name := stk[0].Line[0].Function.Name
   398  			if name == "runtime.gogo" {
   399  				var buf bytes.Buffer
   400  				fprintStack(&buf, stk)
   401  				t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String())
   402  			}
   403  		})
   404  	}
   405  }
   406  
   407  func fprintStack(w io.Writer, stk []*profile.Location) {
   408  	for _, loc := range stk {
   409  		fmt.Fprintf(w, " %#x", loc.Address)
   410  		fmt.Fprintf(w, " (")
   411  		for i, line := range loc.Line {
   412  			if i > 0 {
   413  				fmt.Fprintf(w, " ")
   414  			}
   415  			fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line)
   416  		}
   417  		fmt.Fprintf(w, ")")
   418  	}
   419  	fmt.Fprintf(w, "\n")
   420  }
   421  
   422  // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
   423  func TestMathBigDivide(t *testing.T) {
   424  	testCPUProfile(t, nil, nil, nil, func(duration time.Duration) {
   425  		t := time.After(duration)
   426  		pi := new(big.Int)
   427  		for {
   428  			for i := 0; i < 100; i++ {
   429  				n := big.NewInt(2646693125139304345)
   430  				d := big.NewInt(842468587426513207)
   431  				pi.Div(n, d)
   432  			}
   433  			select {
   434  			case <-t:
   435  				return
   436  			default:
   437  			}
   438  		}
   439  	})
   440  }
   441  
   442  // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace.
   443  func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   444  	for _, f := range strings.Split(spec, ",") {
   445  		if !stackContains(f, count, stk, labels) {
   446  			return false
   447  		}
   448  	}
   449  	return true
   450  }
   451  
   452  func TestMorestack(t *testing.T) {
   453  	testCPUProfile(t, stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions(), func(duration time.Duration) {
   454  		t := time.After(duration)
   455  		c := make(chan bool)
   456  		for {
   457  			go func() {
   458  				growstack1()
   459  				c <- true
   460  			}()
   461  			select {
   462  			case <-t:
   463  				return
   464  			case <-c:
   465  			}
   466  		}
   467  	})
   468  }
   469  
   470  //go:noinline
   471  func growstack1() {
   472  	growstack()
   473  }
   474  
   475  //go:noinline
   476  func growstack() {
   477  	var buf [8 << 10]byte
   478  	use(buf)
   479  }
   480  
   481  //go:noinline
   482  func use(x [8 << 10]byte) {}
   483  
   484  func TestBlockProfile(t *testing.T) {
   485  	type TestCase struct {
   486  		name string
   487  		f    func()
   488  		stk  []string
   489  		re   string
   490  	}
   491  	tests := [...]TestCase{
   492  		{
   493  			name: "chan recv",
   494  			f:    blockChanRecv,
   495  			stk: []string{
   496  				"runtime.chanrecv1",
   497  				"runtime/pprof.blockChanRecv",
   498  				"runtime/pprof.TestBlockProfile",
   499  			},
   500  			re: `
   501  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   502  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
   503  #	0x[0-9a-f]+	runtime/pprof\.blockChanRecv\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   504  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   505  `},
   506  		{
   507  			name: "chan send",
   508  			f:    blockChanSend,
   509  			stk: []string{
   510  				"runtime.chansend1",
   511  				"runtime/pprof.blockChanSend",
   512  				"runtime/pprof.TestBlockProfile",
   513  			},
   514  			re: `
   515  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   516  #	0x[0-9a-f]+	runtime\.chansend1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
   517  #	0x[0-9a-f]+	runtime/pprof\.blockChanSend\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   518  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   519  `},
   520  		{
   521  			name: "chan close",
   522  			f:    blockChanClose,
   523  			stk: []string{
   524  				"runtime.chanrecv1",
   525  				"runtime/pprof.blockChanClose",
   526  				"runtime/pprof.TestBlockProfile",
   527  			},
   528  			re: `
   529  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   530  #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
   531  #	0x[0-9a-f]+	runtime/pprof\.blockChanClose\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   532  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   533  `},
   534  		{
   535  			name: "select recv async",
   536  			f:    blockSelectRecvAsync,
   537  			stk: []string{
   538  				"runtime.selectgo",
   539  				"runtime/pprof.blockSelectRecvAsync",
   540  				"runtime/pprof.TestBlockProfile",
   541  			},
   542  			re: `
   543  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   544  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*/src/runtime/select.go:[0-9]+
   545  #	0x[0-9a-f]+	runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   546  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   547  `},
   548  		{
   549  			name: "select send sync",
   550  			f:    blockSelectSendSync,
   551  			stk: []string{
   552  				"runtime.selectgo",
   553  				"runtime/pprof.blockSelectSendSync",
   554  				"runtime/pprof.TestBlockProfile",
   555  			},
   556  			re: `
   557  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   558  #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*/src/runtime/select.go:[0-9]+
   559  #	0x[0-9a-f]+	runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   560  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   561  `},
   562  		{
   563  			name: "mutex",
   564  			f:    blockMutex,
   565  			stk: []string{
   566  				"sync.(*Mutex).Lock",
   567  				"runtime/pprof.blockMutex",
   568  				"runtime/pprof.TestBlockProfile",
   569  			},
   570  			re: `
   571  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   572  #	0x[0-9a-f]+	sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+	.*/src/sync/mutex\.go:[0-9]+
   573  #	0x[0-9a-f]+	runtime/pprof\.blockMutex\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   574  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   575  `},
   576  		{
   577  			name: "cond",
   578  			f:    blockCond,
   579  			stk: []string{
   580  				"sync.(*Cond).Wait",
   581  				"runtime/pprof.blockCond",
   582  				"runtime/pprof.TestBlockProfile",
   583  			},
   584  			re: `
   585  [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
   586  #	0x[0-9a-f]+	sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+	.*/src/sync/cond\.go:[0-9]+
   587  #	0x[0-9a-f]+	runtime/pprof\.blockCond\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   588  #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   589  `},
   590  	}
   591  
   592  	// Generate block profile
   593  	runtime.SetBlockProfileRate(1)
   594  	defer runtime.SetBlockProfileRate(0)
   595  	for _, test := range tests {
   596  		test.f()
   597  	}
   598  
   599  	t.Run("debug=1", func(t *testing.T) {
   600  		var w bytes.Buffer
   601  		Lookup("block").WriteTo(&w, 1)
   602  		prof := w.String()
   603  
   604  		if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
   605  			t.Fatalf("Bad profile header:\n%v", prof)
   606  		}
   607  
   608  		if strings.HasSuffix(prof, "#\t0x0\n\n") {
   609  			t.Errorf("Useless 0 suffix:\n%v", prof)
   610  		}
   611  
   612  		for _, test := range tests {
   613  			if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) {
   614  				t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
   615  			}
   616  		}
   617  	})
   618  
   619  	t.Run("proto", func(t *testing.T) {
   620  		// proto format
   621  		var w bytes.Buffer
   622  		Lookup("block").WriteTo(&w, 0)
   623  		p, err := profile.Parse(&w)
   624  		if err != nil {
   625  			t.Fatalf("failed to parse profile: %v", err)
   626  		}
   627  		t.Logf("parsed proto: %s", p)
   628  		if err := p.CheckValid(); err != nil {
   629  			t.Fatalf("invalid profile: %v", err)
   630  		}
   631  
   632  		stks := stacks(p)
   633  		for _, test := range tests {
   634  			if !containsStack(stks, test.stk) {
   635  				t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk)
   636  			}
   637  		}
   638  	})
   639  
   640  }
   641  
   642  func stacks(p *profile.Profile) (res [][]string) {
   643  	for _, s := range p.Sample {
   644  		var stk []string
   645  		for _, l := range s.Location {
   646  			for _, line := range l.Line {
   647  				stk = append(stk, line.Function.Name)
   648  			}
   649  		}
   650  		res = append(res, stk)
   651  	}
   652  	return res
   653  }
   654  
   655  func containsStack(got [][]string, want []string) bool {
   656  	for _, stk := range got {
   657  		if len(stk) < len(want) {
   658  			continue
   659  		}
   660  		for i, f := range want {
   661  			if f != stk[i] {
   662  				break
   663  			}
   664  			if i == len(want)-1 {
   665  				return true
   666  			}
   667  		}
   668  	}
   669  	return false
   670  }
   671  
   672  const blockDelay = 10 * time.Millisecond
   673  
   674  func blockChanRecv() {
   675  	c := make(chan bool)
   676  	go func() {
   677  		time.Sleep(blockDelay)
   678  		c <- true
   679  	}()
   680  	<-c
   681  }
   682  
   683  func blockChanSend() {
   684  	c := make(chan bool)
   685  	go func() {
   686  		time.Sleep(blockDelay)
   687  		<-c
   688  	}()
   689  	c <- true
   690  }
   691  
   692  func blockChanClose() {
   693  	c := make(chan bool)
   694  	go func() {
   695  		time.Sleep(blockDelay)
   696  		close(c)
   697  	}()
   698  	<-c
   699  }
   700  
   701  func blockSelectRecvAsync() {
   702  	const numTries = 3
   703  	c := make(chan bool, 1)
   704  	c2 := make(chan bool, 1)
   705  	go func() {
   706  		for i := 0; i < numTries; i++ {
   707  			time.Sleep(blockDelay)
   708  			c <- true
   709  		}
   710  	}()
   711  	for i := 0; i < numTries; i++ {
   712  		select {
   713  		case <-c:
   714  		case <-c2:
   715  		}
   716  	}
   717  }
   718  
   719  func blockSelectSendSync() {
   720  	c := make(chan bool)
   721  	c2 := make(chan bool)
   722  	go func() {
   723  		time.Sleep(blockDelay)
   724  		<-c
   725  	}()
   726  	select {
   727  	case c <- true:
   728  	case c2 <- true:
   729  	}
   730  }
   731  
   732  func blockMutex() {
   733  	var mu sync.Mutex
   734  	mu.Lock()
   735  	go func() {
   736  		time.Sleep(blockDelay)
   737  		mu.Unlock()
   738  	}()
   739  	// Note: Unlock releases mu before recording the mutex event,
   740  	// so it's theoretically possible for this to proceed and
   741  	// capture the profile before the event is recorded. As long
   742  	// as this is blocked before the unlock happens, it's okay.
   743  	mu.Lock()
   744  }
   745  
   746  func blockCond() {
   747  	var mu sync.Mutex
   748  	c := sync.NewCond(&mu)
   749  	mu.Lock()
   750  	go func() {
   751  		time.Sleep(blockDelay)
   752  		mu.Lock()
   753  		c.Signal()
   754  		mu.Unlock()
   755  	}()
   756  	c.Wait()
   757  	mu.Unlock()
   758  }
   759  
   760  func TestMutexProfile(t *testing.T) {
   761  	// Generate mutex profile
   762  
   763  	old := runtime.SetMutexProfileFraction(1)
   764  	defer runtime.SetMutexProfileFraction(old)
   765  	if old != 0 {
   766  		t.Fatalf("need MutexProfileRate 0, got %d", old)
   767  	}
   768  
   769  	blockMutex()
   770  
   771  	t.Run("debug=1", func(t *testing.T) {
   772  		var w bytes.Buffer
   773  		Lookup("mutex").WriteTo(&w, 1)
   774  		prof := w.String()
   775  		t.Logf("received profile: %v", prof)
   776  
   777  		if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") {
   778  			t.Errorf("Bad profile header:\n%v", prof)
   779  		}
   780  		prof = strings.Trim(prof, "\n")
   781  		lines := strings.Split(prof, "\n")
   782  		if len(lines) != 6 {
   783  			t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof)
   784  		}
   785  		if len(lines) < 6 {
   786  			return
   787  		}
   788  		// checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931"
   789  		r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+`
   790  		//r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$"
   791  		if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok {
   792  			t.Errorf("%q didn't match %q", lines[3], r2)
   793  		}
   794  		r3 := "^#.*runtime/pprof.blockMutex.*$"
   795  		if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok {
   796  			t.Errorf("%q didn't match %q", lines[5], r3)
   797  		}
   798  		t.Logf(prof)
   799  	})
   800  	t.Run("proto", func(t *testing.T) {
   801  		// proto format
   802  		var w bytes.Buffer
   803  		Lookup("mutex").WriteTo(&w, 0)
   804  		p, err := profile.Parse(&w)
   805  		if err != nil {
   806  			t.Fatalf("failed to parse profile: %v", err)
   807  		}
   808  		t.Logf("parsed proto: %s", p)
   809  		if err := p.CheckValid(); err != nil {
   810  			t.Fatalf("invalid profile: %v", err)
   811  		}
   812  
   813  		stks := stacks(p)
   814  		for _, want := range [][]string{
   815  			{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutex.func1"},
   816  		} {
   817  			if !containsStack(stks, want) {
   818  				t.Errorf("No matching stack entry for %+v", want)
   819  			}
   820  		}
   821  	})
   822  }
   823  
   824  func func1(c chan int) { <-c }
   825  func func2(c chan int) { <-c }
   826  func func3(c chan int) { <-c }
   827  func func4(c chan int) { <-c }
   828  
   829  func TestGoroutineCounts(t *testing.T) {
   830  	// Setting GOMAXPROCS to 1 ensures we can force all goroutines to the
   831  	// desired blocking point.
   832  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
   833  
   834  	c := make(chan int)
   835  	for i := 0; i < 100; i++ {
   836  		switch {
   837  		case i%10 == 0:
   838  			go func1(c)
   839  		case i%2 == 0:
   840  			go func2(c)
   841  		default:
   842  			go func3(c)
   843  		}
   844  		// Let goroutines block on channel
   845  		for j := 0; j < 5; j++ {
   846  			runtime.Gosched()
   847  		}
   848  	}
   849  
   850  	var w bytes.Buffer
   851  	goroutineProf := Lookup("goroutine")
   852  
   853  	// Check debug profile
   854  	goroutineProf.WriteTo(&w, 1)
   855  	prof := w.String()
   856  
   857  	if !containsInOrder(prof, "\n50 @ ", "\n40 @", "\n10 @", "\n1 @") {
   858  		t.Errorf("expected sorted goroutine counts:\n%s", prof)
   859  	}
   860  
   861  	// Check proto profile
   862  	w.Reset()
   863  	goroutineProf.WriteTo(&w, 0)
   864  	p, err := profile.Parse(&w)
   865  	if err != nil {
   866  		t.Errorf("error parsing protobuf profile: %v", err)
   867  	}
   868  	if err := p.CheckValid(); err != nil {
   869  		t.Errorf("protobuf profile is invalid: %v", err)
   870  	}
   871  	if !containsCounts(p, []int64{50, 40, 10, 1}) {
   872  		t.Errorf("expected count profile to contain goroutines with counts %v, got %v",
   873  			[]int64{50, 40, 10, 1}, p)
   874  	}
   875  
   876  	close(c)
   877  
   878  	time.Sleep(10 * time.Millisecond) // let goroutines exit
   879  }
   880  
   881  func containsInOrder(s string, all ...string) bool {
   882  	for _, t := range all {
   883  		i := strings.Index(s, t)
   884  		if i < 0 {
   885  			return false
   886  		}
   887  		s = s[i+len(t):]
   888  	}
   889  	return true
   890  }
   891  
   892  func containsCounts(prof *profile.Profile, counts []int64) bool {
   893  	m := make(map[int64]int)
   894  	for _, c := range counts {
   895  		m[c]++
   896  	}
   897  	for _, s := range prof.Sample {
   898  		// The count is the single value in the sample
   899  		if len(s.Value) != 1 {
   900  			return false
   901  		}
   902  		m[s.Value[0]]--
   903  	}
   904  	for _, n := range m {
   905  		if n > 0 {
   906  			return false
   907  		}
   908  	}
   909  	return true
   910  }
   911  
   912  var emptyCallStackTestRun int64
   913  
   914  // Issue 18836.
   915  func TestEmptyCallStack(t *testing.T) {
   916  	name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun)
   917  	emptyCallStackTestRun++
   918  
   919  	t.Parallel()
   920  	var buf bytes.Buffer
   921  	p := NewProfile(name)
   922  
   923  	p.Add("foo", 47674)
   924  	p.WriteTo(&buf, 1)
   925  	p.Remove("foo")
   926  	got := buf.String()
   927  	prefix := name + " profile: total 1\n"
   928  	if !strings.HasPrefix(got, prefix) {
   929  		t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix)
   930  	}
   931  	lostevent := "lostProfileEvent"
   932  	if !strings.Contains(got, lostevent) {
   933  		t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent)
   934  	}
   935  }
   936  
   937  // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key
   938  // and value and has funcname somewhere in the stack.
   939  func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
   940  	semi := strings.Index(spec, ";")
   941  	if semi == -1 {
   942  		panic("no semicolon in key/value spec")
   943  	}
   944  	kv := strings.SplitN(spec[semi+1:], "=", 2)
   945  	if len(kv) != 2 {
   946  		panic("missing = in key/value spec")
   947  	}
   948  	if !contains(labels[kv[0]], kv[1]) {
   949  		return false
   950  	}
   951  	return stackContains(spec[:semi], count, stk, labels)
   952  }
   953  
   954  func TestCPUProfileLabel(t *testing.T) {
   955  	testCPUProfile(t, stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions(), func(dur time.Duration) {
   956  		Do(context.Background(), Labels("key", "value"), func(context.Context) {
   957  			cpuHogger(cpuHog1, &salt1, dur)
   958  		})
   959  	})
   960  }
   961  
   962  func TestLabelRace(t *testing.T) {
   963  	// Test the race detector annotations for synchronization
   964  	// between settings labels and consuming them from the
   965  	// profile.
   966  	testCPUProfile(t, stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil, func(dur time.Duration) {
   967  		start := time.Now()
   968  		var wg sync.WaitGroup
   969  		for time.Since(start) < dur {
   970  			var salts [10]int
   971  			for i := 0; i < 10; i++ {
   972  				wg.Add(1)
   973  				go func(j int) {
   974  					Do(context.Background(), Labels("key", "value"), func(context.Context) {
   975  						cpuHogger(cpuHog1, &salts[j], time.Millisecond)
   976  					})
   977  					wg.Done()
   978  				}(i)
   979  			}
   980  			wg.Wait()
   981  		}
   982  	})
   983  }
   984  
   985  // Check that there is no deadlock when the program receives SIGPROF while in
   986  // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146.
   987  func TestAtomicLoadStore64(t *testing.T) {
   988  	f, err := ioutil.TempFile("", "profatomic")
   989  	if err != nil {
   990  		t.Fatalf("TempFile: %v", err)
   991  	}
   992  	defer os.Remove(f.Name())
   993  	defer f.Close()
   994  
   995  	if err := StartCPUProfile(f); err != nil {
   996  		t.Fatal(err)
   997  	}
   998  	defer StopCPUProfile()
   999  
  1000  	var flag uint64
  1001  	done := make(chan bool, 1)
  1002  
  1003  	go func() {
  1004  		for atomic.LoadUint64(&flag) == 0 {
  1005  			runtime.Gosched()
  1006  		}
  1007  		done <- true
  1008  	}()
  1009  	time.Sleep(50 * time.Millisecond)
  1010  	atomic.StoreUint64(&flag, 1)
  1011  	<-done
  1012  }
  1013  
  1014  func TestTracebackAll(t *testing.T) {
  1015  	// With gccgo, if a profiling signal arrives at the wrong time
  1016  	// during traceback, it may crash or hang. See issue #29448.
  1017  	f, err := ioutil.TempFile("", "proftraceback")
  1018  	if err != nil {
  1019  		t.Fatalf("TempFile: %v", err)
  1020  	}
  1021  	defer os.Remove(f.Name())
  1022  	defer f.Close()
  1023  
  1024  	if err := StartCPUProfile(f); err != nil {
  1025  		t.Fatal(err)
  1026  	}
  1027  	defer StopCPUProfile()
  1028  
  1029  	ch := make(chan int)
  1030  	defer close(ch)
  1031  
  1032  	count := 10
  1033  	for i := 0; i < count; i++ {
  1034  		go func() {
  1035  			<-ch // block
  1036  		}()
  1037  	}
  1038  
  1039  	N := 10000
  1040  	if testing.Short() {
  1041  		N = 500
  1042  	}
  1043  	buf := make([]byte, 10*1024)
  1044  	for i := 0; i < N; i++ {
  1045  		runtime.Stack(buf, true)
  1046  	}
  1047  }