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 }