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 }