github.com/fjballest/golang@v0.0.0-20151209143359-e4c5fe594ca8/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 !nacl
     6  
     7  package pprof_test
     8  
     9  import (
    10  	"bytes"
    11  	"fmt"
    12  	"internal/testenv"
    13  	"math/big"
    14  	"os"
    15  	"os/exec"
    16  	"regexp"
    17  	"runtime"
    18  	. "runtime/pprof"
    19  	"strings"
    20  	"sync"
    21  	"testing"
    22  	"time"
    23  	"unsafe"
    24  )
    25  
    26  func cpuHogger(f func()) {
    27  	// We only need to get one 100 Hz clock tick, so we've got
    28  	// a 25x safety buffer.
    29  	// But do at least 500 iterations (which should take about 100ms),
    30  	// otherwise TestCPUProfileMultithreaded can fail if only one
    31  	// thread is scheduled during the 250ms period.
    32  	t0 := time.Now()
    33  	for i := 0; i < 500 || time.Since(t0) < 250*time.Millisecond; i++ {
    34  		f()
    35  	}
    36  }
    37  
    38  var (
    39  	salt1 = 0
    40  	salt2 = 0
    41  )
    42  
    43  // The actual CPU hogging function.
    44  // Must not call other functions nor access heap/globals in the loop,
    45  // otherwise under race detector the samples will be in the race runtime.
    46  func cpuHog1() {
    47  	foo := salt1
    48  	for i := 0; i < 1e5; i++ {
    49  		if foo > 0 {
    50  			foo *= foo
    51  		} else {
    52  			foo *= foo + 1
    53  		}
    54  	}
    55  	salt1 = foo
    56  }
    57  
    58  func cpuHog2() {
    59  	foo := salt2
    60  	for i := 0; i < 1e5; i++ {
    61  		if foo > 0 {
    62  			foo *= foo
    63  		} else {
    64  			foo *= foo + 2
    65  		}
    66  	}
    67  	salt2 = foo
    68  }
    69  
    70  func TestCPUProfile(t *testing.T) {
    71  	testCPUProfile(t, []string{"runtime/pprof_test.cpuHog1"}, func() {
    72  		cpuHogger(cpuHog1)
    73  	})
    74  }
    75  
    76  func TestCPUProfileMultithreaded(t *testing.T) {
    77  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
    78  	testCPUProfile(t, []string{"runtime/pprof_test.cpuHog1", "runtime/pprof_test.cpuHog2"}, func() {
    79  		c := make(chan int)
    80  		go func() {
    81  			cpuHogger(cpuHog1)
    82  			c <- 1
    83  		}()
    84  		cpuHogger(cpuHog2)
    85  		<-c
    86  	})
    87  }
    88  
    89  func parseProfile(t *testing.T, bytes []byte, f func(uintptr, []uintptr)) {
    90  	// Convert []byte to []uintptr.
    91  	l := len(bytes) / int(unsafe.Sizeof(uintptr(0)))
    92  	val := *(*[]uintptr)(unsafe.Pointer(&bytes))
    93  	val = val[:l]
    94  
    95  	// 5 for the header, 2 for the per-sample header on at least one sample, 3 for the trailer.
    96  	if l < 5+2+3 {
    97  		t.Logf("profile too short: %#x", val)
    98  		if badOS[runtime.GOOS] {
    99  			t.Skipf("ignoring failure on %s; see golang.org/issue/6047", runtime.GOOS)
   100  			return
   101  		}
   102  		t.FailNow()
   103  	}
   104  
   105  	hd, val, tl := val[:5], val[5:l-3], val[l-3:]
   106  	if hd[0] != 0 || hd[1] != 3 || hd[2] != 0 || hd[3] != 1e6/100 || hd[4] != 0 {
   107  		t.Fatalf("unexpected header %#x", hd)
   108  	}
   109  
   110  	if tl[0] != 0 || tl[1] != 1 || tl[2] != 0 {
   111  		t.Fatalf("malformed end-of-data marker %#x", tl)
   112  	}
   113  
   114  	for len(val) > 0 {
   115  		if len(val) < 2 || val[0] < 1 || val[1] < 1 || uintptr(len(val)) < 2+val[1] {
   116  			t.Fatalf("malformed profile.  leftover: %#x", val)
   117  		}
   118  		f(val[0], val[2:2+val[1]])
   119  		val = val[2+val[1]:]
   120  	}
   121  }
   122  
   123  func testCPUProfile(t *testing.T, need []string, f func()) {
   124  	switch runtime.GOOS {
   125  	case "darwin":
   126  		switch runtime.GOARCH {
   127  		case "arm", "arm64":
   128  			// nothing
   129  		default:
   130  			out, err := exec.Command("uname", "-a").CombinedOutput()
   131  			if err != nil {
   132  				t.Fatal(err)
   133  			}
   134  			vers := string(out)
   135  			t.Logf("uname -a: %v", vers)
   136  		}
   137  	case "plan9":
   138  		t.Skip("skipping on plan9")
   139  	}
   140  
   141  	var prof bytes.Buffer
   142  	if err := StartCPUProfile(&prof); err != nil {
   143  		t.Fatal(err)
   144  	}
   145  	f()
   146  	StopCPUProfile()
   147  
   148  	// Check that profile is well formed and contains need.
   149  	have := make([]uintptr, len(need))
   150  	var samples uintptr
   151  	parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) {
   152  		samples += count
   153  		for _, pc := range stk {
   154  			f := runtime.FuncForPC(pc)
   155  			if f == nil {
   156  				continue
   157  			}
   158  			for i, name := range need {
   159  				if strings.Contains(f.Name(), name) {
   160  					have[i] += count
   161  				}
   162  			}
   163  			if strings.Contains(f.Name(), "stackBarrier") {
   164  				// The runtime should have unwound this.
   165  				t.Fatalf("profile includes stackBarrier")
   166  			}
   167  		}
   168  	})
   169  	t.Logf("total %d CPU profile samples collected", samples)
   170  
   171  	if samples < 10 && runtime.GOOS == "windows" {
   172  		// On some windows machines we end up with
   173  		// not enough samples due to coarse timer
   174  		// resolution. Let it go.
   175  		t.Skip("too few samples on Windows (golang.org/issue/10842)")
   176  	}
   177  
   178  	if len(need) == 0 {
   179  		return
   180  	}
   181  
   182  	var total uintptr
   183  	for i, name := range need {
   184  		total += have[i]
   185  		t.Logf("%s: %d\n", name, have[i])
   186  	}
   187  	ok := true
   188  	if total == 0 {
   189  		t.Logf("no CPU profile samples collected")
   190  		ok = false
   191  	}
   192  	// We'd like to check a reasonable minimum, like
   193  	// total / len(have) / smallconstant, but this test is
   194  	// pretty flaky (see bug 7095).  So we'll just test to
   195  	// make sure we got at least one sample.
   196  	min := uintptr(1)
   197  	for i, name := range need {
   198  		if have[i] < min {
   199  			t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
   200  			ok = false
   201  		}
   202  	}
   203  
   204  	if !ok {
   205  		if badOS[runtime.GOOS] {
   206  			t.Skipf("ignoring failure on %s; see golang.org/issue/6047", runtime.GOOS)
   207  			return
   208  		}
   209  		// Ignore the failure if the tests are running in a QEMU-based emulator,
   210  		// QEMU is not perfect at emulating everything.
   211  		// IN_QEMU environmental variable is set by some of the Go builders.
   212  		// IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
   213  		if os.Getenv("IN_QEMU") == "1" {
   214  			t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
   215  			return
   216  		}
   217  		t.FailNow()
   218  	}
   219  }
   220  
   221  // Fork can hang if preempted with signals frequently enough (see issue 5517).
   222  // Ensure that we do not do this.
   223  func TestCPUProfileWithFork(t *testing.T) {
   224  	testenv.MustHaveExec(t)
   225  
   226  	heap := 1 << 30
   227  	if runtime.GOOS == "android" {
   228  		// Use smaller size for Android to avoid crash.
   229  		heap = 100 << 20
   230  	}
   231  	if testing.Short() {
   232  		heap = 100 << 20
   233  	}
   234  	// This makes fork slower.
   235  	garbage := make([]byte, heap)
   236  	// Need to touch the slice, otherwise it won't be paged in.
   237  	done := make(chan bool)
   238  	go func() {
   239  		for i := range garbage {
   240  			garbage[i] = 42
   241  		}
   242  		done <- true
   243  	}()
   244  	<-done
   245  
   246  	var prof bytes.Buffer
   247  	if err := StartCPUProfile(&prof); err != nil {
   248  		t.Fatal(err)
   249  	}
   250  	defer StopCPUProfile()
   251  
   252  	for i := 0; i < 10; i++ {
   253  		exec.Command(os.Args[0], "-h").CombinedOutput()
   254  	}
   255  }
   256  
   257  // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
   258  // If it did, it would see inconsistent state and would either record an incorrect stack
   259  // or crash because the stack was malformed.
   260  func TestGoroutineSwitch(t *testing.T) {
   261  	// How much to try. These defaults take about 1 seconds
   262  	// on a 2012 MacBook Pro. The ones in short mode take
   263  	// about 0.1 seconds.
   264  	tries := 10
   265  	count := 1000000
   266  	if testing.Short() {
   267  		tries = 1
   268  	}
   269  	for try := 0; try < tries; try++ {
   270  		var prof bytes.Buffer
   271  		if err := StartCPUProfile(&prof); err != nil {
   272  			t.Fatal(err)
   273  		}
   274  		for i := 0; i < count; i++ {
   275  			runtime.Gosched()
   276  		}
   277  		StopCPUProfile()
   278  
   279  		// Read profile to look for entries for runtime.gogo with an attempt at a traceback.
   280  		// The special entry
   281  		parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) {
   282  			// An entry with two frames with 'System' in its top frame
   283  			// exists to record a PC without a traceback. Those are okay.
   284  			if len(stk) == 2 {
   285  				f := runtime.FuncForPC(stk[1])
   286  				if f != nil && (f.Name() == "runtime._System" || f.Name() == "runtime._ExternalCode" || f.Name() == "runtime._GC") {
   287  					return
   288  				}
   289  			}
   290  
   291  			// Otherwise, should not see runtime.gogo.
   292  			// The place we'd see it would be the inner most frame.
   293  			f := runtime.FuncForPC(stk[0])
   294  			if f != nil && f.Name() == "runtime.gogo" {
   295  				var buf bytes.Buffer
   296  				for _, pc := range stk {
   297  					f := runtime.FuncForPC(pc)
   298  					if f == nil {
   299  						fmt.Fprintf(&buf, "%#x ?:0\n", pc)
   300  					} else {
   301  						file, line := f.FileLine(pc)
   302  						fmt.Fprintf(&buf, "%#x %s:%d\n", pc, file, line)
   303  					}
   304  				}
   305  				t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String())
   306  			}
   307  		})
   308  	}
   309  }
   310  
   311  // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
   312  func TestMathBigDivide(t *testing.T) {
   313  	testCPUProfile(t, nil, func() {
   314  		t := time.After(5 * time.Second)
   315  		pi := new(big.Int)
   316  		for {
   317  			for i := 0; i < 100; i++ {
   318  				n := big.NewInt(2646693125139304345)
   319  				d := big.NewInt(842468587426513207)
   320  				pi.Div(n, d)
   321  			}
   322  			select {
   323  			case <-t:
   324  				return
   325  			default:
   326  			}
   327  		}
   328  	})
   329  }
   330  
   331  func TestStackBarrierProfiling(t *testing.T) {
   332  	if !strings.Contains(os.Getenv("GODEBUG"), "gcstackbarrierall=1") {
   333  		// Re-execute this test with constant GC and stack
   334  		// barriers at every frame.
   335  		testenv.MustHaveExec(t)
   336  		if runtime.GOARCH == "ppc64" || runtime.GOARCH == "ppc64le" {
   337  			t.Skip("gcstackbarrierall doesn't work on ppc64")
   338  		}
   339  		cmd := exec.Command(os.Args[0], "-test.run=TestStackBarrierProfiling")
   340  		cmd.Env = append([]string{"GODEBUG=gcstackbarrierall=1", "GOGC=1"}, os.Environ()...)
   341  		if out, err := cmd.CombinedOutput(); err != nil {
   342  			t.Fatalf("subprocess failed with %v:\n%s", err, out)
   343  		}
   344  		return
   345  	}
   346  
   347  	testCPUProfile(t, nil, func() {
   348  		// This is long enough that we're likely to get one or
   349  		// two samples in stackBarrier.
   350  		duration := 5 * time.Second
   351  		if testing.Short() {
   352  			duration = 1 * time.Second
   353  		}
   354  		t := time.After(duration)
   355  		for {
   356  			deepStack(1000)
   357  			select {
   358  			case <-t:
   359  				return
   360  			default:
   361  			}
   362  		}
   363  	})
   364  }
   365  
   366  var x []byte
   367  
   368  func deepStack(depth int) int {
   369  	if depth == 0 {
   370  		return 0
   371  	}
   372  	x = make([]byte, 1024)
   373  	return deepStack(depth-1) + 1
   374  }
   375  
   376  // Operating systems that are expected to fail the tests. See issue 6047.
   377  var badOS = map[string]bool{
   378  	"darwin": true,
   379  	"netbsd": true,
   380  	"plan9":  true,
   381  }
   382  
   383  func TestBlockProfile(t *testing.T) {
   384  	type TestCase struct {
   385  		name string
   386  		f    func()
   387  		re   string
   388  	}
   389  	tests := [...]TestCase{
   390  		{"chan recv", blockChanRecv, `
   391  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   392  #	0x[0-9,a-f]+	runtime\.chanrecv1\+0x[0-9,a-f]+	.*/src/runtime/chan.go:[0-9]+
   393  #	0x[0-9,a-f]+	runtime/pprof_test\.blockChanRecv\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   394  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   395  `},
   396  		{"chan send", blockChanSend, `
   397  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   398  #	0x[0-9,a-f]+	runtime\.chansend1\+0x[0-9,a-f]+	.*/src/runtime/chan.go:[0-9]+
   399  #	0x[0-9,a-f]+	runtime/pprof_test\.blockChanSend\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   400  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   401  `},
   402  		{"chan close", blockChanClose, `
   403  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   404  #	0x[0-9,a-f]+	runtime\.chanrecv1\+0x[0-9,a-f]+	.*/src/runtime/chan.go:[0-9]+
   405  #	0x[0-9,a-f]+	runtime/pprof_test\.blockChanClose\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   406  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   407  `},
   408  		{"select recv async", blockSelectRecvAsync, `
   409  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   410  #	0x[0-9,a-f]+	runtime\.selectgo\+0x[0-9,a-f]+	.*/src/runtime/select.go:[0-9]+
   411  #	0x[0-9,a-f]+	runtime/pprof_test\.blockSelectRecvAsync\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   412  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   413  `},
   414  		{"select send sync", blockSelectSendSync, `
   415  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   416  #	0x[0-9,a-f]+	runtime\.selectgo\+0x[0-9,a-f]+	.*/src/runtime/select.go:[0-9]+
   417  #	0x[0-9,a-f]+	runtime/pprof_test\.blockSelectSendSync\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   418  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   419  `},
   420  		{"mutex", blockMutex, `
   421  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   422  #	0x[0-9,a-f]+	sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+	.*/src/sync/mutex\.go:[0-9]+
   423  #	0x[0-9,a-f]+	runtime/pprof_test\.blockMutex\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   424  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   425  `},
   426  		{"cond", blockCond, `
   427  [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
   428  #	0x[0-9,a-f]+	sync\.\(\*Cond\)\.Wait\+0x[0-9,a-f]+	.*/src/sync/cond\.go:[0-9]+
   429  #	0x[0-9,a-f]+	runtime/pprof_test\.blockCond\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   430  #	0x[0-9,a-f]+	runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
   431  `},
   432  	}
   433  
   434  	runtime.SetBlockProfileRate(1)
   435  	defer runtime.SetBlockProfileRate(0)
   436  	for _, test := range tests {
   437  		test.f()
   438  	}
   439  	var w bytes.Buffer
   440  	Lookup("block").WriteTo(&w, 1)
   441  	prof := w.String()
   442  
   443  	if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
   444  		t.Fatalf("Bad profile header:\n%v", prof)
   445  	}
   446  
   447  	for _, test := range tests {
   448  		if !regexp.MustCompile(strings.Replace(test.re, "\t", "\t+", -1)).MatchString(prof) {
   449  			t.Fatalf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
   450  		}
   451  	}
   452  }
   453  
   454  const blockDelay = 10 * time.Millisecond
   455  
   456  func blockChanRecv() {
   457  	c := make(chan bool)
   458  	go func() {
   459  		time.Sleep(blockDelay)
   460  		c <- true
   461  	}()
   462  	<-c
   463  }
   464  
   465  func blockChanSend() {
   466  	c := make(chan bool)
   467  	go func() {
   468  		time.Sleep(blockDelay)
   469  		<-c
   470  	}()
   471  	c <- true
   472  }
   473  
   474  func blockChanClose() {
   475  	c := make(chan bool)
   476  	go func() {
   477  		time.Sleep(blockDelay)
   478  		close(c)
   479  	}()
   480  	<-c
   481  }
   482  
   483  func blockSelectRecvAsync() {
   484  	c := make(chan bool, 1)
   485  	c2 := make(chan bool, 1)
   486  	go func() {
   487  		time.Sleep(blockDelay)
   488  		c <- true
   489  	}()
   490  	select {
   491  	case <-c:
   492  	case <-c2:
   493  	}
   494  }
   495  
   496  func blockSelectSendSync() {
   497  	c := make(chan bool)
   498  	c2 := make(chan bool)
   499  	go func() {
   500  		time.Sleep(blockDelay)
   501  		<-c
   502  	}()
   503  	select {
   504  	case c <- true:
   505  	case c2 <- true:
   506  	}
   507  }
   508  
   509  func blockMutex() {
   510  	var mu sync.Mutex
   511  	mu.Lock()
   512  	go func() {
   513  		time.Sleep(blockDelay)
   514  		mu.Unlock()
   515  	}()
   516  	mu.Lock()
   517  }
   518  
   519  func blockCond() {
   520  	var mu sync.Mutex
   521  	c := sync.NewCond(&mu)
   522  	mu.Lock()
   523  	go func() {
   524  		time.Sleep(blockDelay)
   525  		mu.Lock()
   526  		c.Signal()
   527  		mu.Unlock()
   528  	}()
   529  	c.Wait()
   530  	mu.Unlock()
   531  }