// Copyright 2011 The Go Authors. All rights reserved. // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. // +build !nacl package pprof_test import ( "bytes" "fmt" "math/big" "os/exec" "regexp" "runtime" . "runtime/pprof" "strings" "sync" "testing" "time" "unsafe" ) func cpuHogger(f func()) { // We only need to get one 100 Hz clock tick, so we've got // a 25x safety buffer. // But do at least 500 iterations (which should take about 100ms), // otherwise TestCPUProfileMultithreaded can fail if only one // thread is scheduled during the 250ms period. t0 := time.Now() for i := 0; i < 500 || time.Since(t0) < 250*time.Millisecond; i++ { f() } } var ( salt1 = 0 salt2 = 0 ) // The actual CPU hogging function. // Must not call other functions nor access heap/globals in the loop, // otherwise under race detector the samples will be in the race runtime. func cpuHog1() { foo := salt1 for i := 0; i < 1e5; i++ { if foo > 0 { foo *= foo } else { foo *= foo + 1 } } salt1 = foo } func cpuHog2() { foo := salt2 for i := 0; i < 1e5; i++ { if foo > 0 { foo *= foo } else { foo *= foo + 2 } } salt2 = foo } func TestCPUProfile(t *testing.T) { testCPUProfile(t, []string{"runtime/pprof_test.cpuHog1"}, func() { cpuHogger(cpuHog1) }) } func TestCPUProfileMultithreaded(t *testing.T) { defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2)) testCPUProfile(t, []string{"runtime/pprof_test.cpuHog1", "runtime/pprof_test.cpuHog2"}, func() { c := make(chan int) go func() { cpuHogger(cpuHog1) c <- 1 }() cpuHogger(cpuHog2) <-c }) } func parseProfile(t *testing.T, bytes []byte, f func(uintptr, []uintptr)) { // Convert []byte to []uintptr. l := len(bytes) / int(unsafe.Sizeof(uintptr(0))) val := *(*[]uintptr)(unsafe.Pointer(&bytes)) val = val[:l] // 5 for the header, 2 for the per-sample header on at least one sample, 3 for the trailer. if l < 5+2+3 { t.Logf("profile too short: %#x", val) if badOS[runtime.GOOS] { t.Skipf("ignoring failure on %s; see golang.org/issue/6047", runtime.GOOS) return } t.FailNow() } hd, val, tl := val[:5], val[5:l-3], val[l-3:] if hd[0] != 0 || hd[1] != 3 || hd[2] != 0 || hd[3] != 1e6/100 || hd[4] != 0 { t.Fatalf("unexpected header %#x", hd) } if tl[0] != 0 || tl[1] != 1 || tl[2] != 0 { t.Fatalf("malformed end-of-data marker %#x", tl) } for len(val) > 0 { if len(val) < 2 || val[0] < 1 || val[1] < 1 || uintptr(len(val)) < 2+val[1] { t.Fatalf("malformed profile. leftover: %#x", val) } f(val[0], val[2:2+val[1]]) val = val[2+val[1]:] } } func testCPUProfile(t *testing.T, need []string, f func()) { switch runtime.GOOS { case "darwin": out, err := exec.Command("uname", "-a").CombinedOutput() if err != nil { t.Fatal(err) } vers := string(out) t.Logf("uname -a: %v", vers) case "plan9": // unimplemented return } var prof bytes.Buffer if err := StartCPUProfile(&prof); err != nil { t.Fatal(err) } f() StopCPUProfile() // Check that profile is well formed and contains need. have := make([]uintptr, len(need)) parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) { for _, pc := range stk { f := runtime.FuncForPC(pc) if f == nil { continue } for i, name := range need { if strings.Contains(f.Name(), name) { have[i] += count } } } }) if len(need) == 0 { return } var total uintptr for i, name := range need { total += have[i] t.Logf("%s: %d\n", name, have[i]) } ok := true if total == 0 { t.Logf("no CPU profile samples collected") ok = false } // We'd like to check a reasonable minimum, like // total / len(have) / smallconstant, but this test is // pretty flaky (see bug 7095). So we'll just test to // make sure we got at least one sample. min := uintptr(1) for i, name := range need { if have[i] < min { t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have))) ok = false } } if !ok { if badOS[runtime.GOOS] { t.Skipf("ignoring failure on %s; see golang.org/issue/6047", runtime.GOOS) return } t.FailNow() } } func TestCPUProfileWithFork(t *testing.T) { // Fork can hang if preempted with signals frequently enough (see issue 5517). // Ensure that we do not do this. heap := 1 << 30 if testing.Short() { heap = 100 << 20 } // This makes fork slower. garbage := make([]byte, heap) // Need to touch the slice, otherwise it won't be paged in. done := make(chan bool) go func() { for i := range garbage { garbage[i] = 42 } done <- true }() <-done var prof bytes.Buffer if err := StartCPUProfile(&prof); err != nil { t.Fatal(err) } defer StopCPUProfile() for i := 0; i < 10; i++ { exec.Command("go").CombinedOutput() } } // Test that profiler does not observe runtime.gogo as "user" goroutine execution. // If it did, it would see inconsistent state and would either record an incorrect stack // or crash because the stack was malformed. func TestGoroutineSwitch(t *testing.T) { // How much to try. These defaults take about 1 seconds // on a 2012 MacBook Pro. The ones in short mode take // about 0.1 seconds. tries := 10 count := 1000000 if testing.Short() { tries = 1 } for try := 0; try < tries; try++ { var prof bytes.Buffer if err := StartCPUProfile(&prof); err != nil { t.Fatal(err) } for i := 0; i < count; i++ { runtime.Gosched() } StopCPUProfile() // Read profile to look for entries for runtime.gogo with an attempt at a traceback. // The special entry parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) { // An entry with two frames with 'System' in its top frame // exists to record a PC without a traceback. Those are okay. if len(stk) == 2 { f := runtime.FuncForPC(stk[1]) if f != nil && (f.Name() == "runtime._System" || f.Name() == "runtime._ExternalCode" || f.Name() == "runtime._GC") { return } } // Otherwise, should not see runtime.gogo. // The place we'd see it would be the inner most frame. f := runtime.FuncForPC(stk[0]) if f != nil && f.Name() == "runtime.gogo" { var buf bytes.Buffer for _, pc := range stk { f := runtime.FuncForPC(pc) if f == nil { fmt.Fprintf(&buf, "%#x ?:0\n", pc) } else { file, line := f.FileLine(pc) fmt.Fprintf(&buf, "%#x %s:%d\n", pc, file, line) } } t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String()) } }) } } // Test that profiling of division operations is okay, especially on ARM. See issue 6681. func TestMathBigDivide(t *testing.T) { testCPUProfile(t, nil, func() { t := time.After(5 * time.Second) pi := new(big.Int) for { for i := 0; i < 100; i++ { n := big.NewInt(2646693125139304345) d := big.NewInt(842468587426513207) pi.Div(n, d) } select { case <-t: return default: } } }) } // Operating systems that are expected to fail the tests. See issue 6047. var badOS = map[string]bool{ "darwin": true, "netbsd": true, "plan9": true, } func TestBlockProfile(t *testing.T) { type TestCase struct { name string f func() re string } tests := [...]TestCase{ {"chan recv", blockChanRecv, ` [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]+ # 0x[0-9,a-f]+ runtime\.chanrecv1\+0x[0-9,a-f]+ .*/src/runtime/chan.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockChanRecv\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, {"chan send", blockChanSend, ` [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]+ # 0x[0-9,a-f]+ runtime\.chansend1\+0x[0-9,a-f]+ .*/src/runtime/chan.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockChanSend\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, {"chan close", blockChanClose, ` [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]+ # 0x[0-9,a-f]+ runtime\.chanrecv1\+0x[0-9,a-f]+ .*/src/runtime/chan.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockChanClose\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, {"select recv async", blockSelectRecvAsync, ` [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]+ # 0x[0-9,a-f]+ runtime\.selectgo\+0x[0-9,a-f]+ .*/src/runtime/select.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockSelectRecvAsync\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, {"select send sync", blockSelectSendSync, ` [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]+ # 0x[0-9,a-f]+ runtime\.selectgo\+0x[0-9,a-f]+ .*/src/runtime/select.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockSelectSendSync\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, {"mutex", blockMutex, ` [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]+ # 0x[0-9,a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+ .*/src/sync/mutex\.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockMutex\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, {"cond", blockCond, ` [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]+ # 0x[0-9,a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9,a-f]+ .*/src/sync/cond\.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.blockCond\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ # 0x[0-9,a-f]+ runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ `}, } runtime.SetBlockProfileRate(1) defer runtime.SetBlockProfileRate(0) for _, test := range tests { test.f() } var w bytes.Buffer Lookup("block").WriteTo(&w, 1) prof := w.String() if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") { t.Fatalf("Bad profile header:\n%v", prof) } for _, test := range tests { if !regexp.MustCompile(test.re).MatchString(prof) { t.Fatalf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof) } } } const blockDelay = 10 * time.Millisecond func blockChanRecv() { c := make(chan bool) go func() { time.Sleep(blockDelay) c <- true }() <-c } func blockChanSend() { c := make(chan bool) go func() { time.Sleep(blockDelay) <-c }() c <- true } func blockChanClose() { c := make(chan bool) go func() { time.Sleep(blockDelay) close(c) }() <-c } func blockSelectRecvAsync() { c := make(chan bool, 1) c2 := make(chan bool, 1) go func() { time.Sleep(blockDelay) c <- true }() select { case <-c: case <-c2: } } func blockSelectSendSync() { c := make(chan bool) c2 := make(chan bool) go func() { time.Sleep(blockDelay) <-c }() select { case c <- true: case c2 <- true: } } func blockMutex() { var mu sync.Mutex mu.Lock() go func() { time.Sleep(blockDelay) mu.Unlock() }() mu.Lock() } func blockCond() { var mu sync.Mutex c := sync.NewCond(&mu) mu.Lock() go func() { time.Sleep(blockDelay) mu.Lock() c.Signal() mu.Unlock() }() c.Wait() mu.Unlock() }