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