github.com/slayercat/go@v0.0.0-20170428012452-c51559813f61/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 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/internal/profile" 19 "strings" 20 "sync" 21 "testing" 22 "time" 23 ) 24 25 func cpuHogger(f func(), dur time.Duration) { 26 // We only need to get one 100 Hz clock tick, so we've got 27 // a large 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 testing period. 31 t0 := time.Now() 32 for i := 0; i < 500 || time.Since(t0) < dur; 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.cpuHog1"}, func(dur time.Duration) { 71 cpuHogger(cpuHog1, dur) 72 }) 73 } 74 75 func TestCPUProfileMultithreaded(t *testing.T) { 76 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2)) 77 testCPUProfile(t, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, func(dur time.Duration) { 78 c := make(chan int) 79 go func() { 80 cpuHogger(cpuHog1, dur) 81 c <- 1 82 }() 83 cpuHogger(cpuHog2, dur) 84 <-c 85 }) 86 } 87 88 func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []uintptr)) { 89 p, err := profile.Parse(bytes.NewReader(valBytes)) 90 if err != nil { 91 t.Fatal(err) 92 } 93 for _, sample := range p.Sample { 94 count := uintptr(sample.Value[0]) 95 stk := make([]uintptr, len(sample.Location)) 96 for i := range sample.Location { 97 stk[i] = uintptr(sample.Location[i].Address) 98 } 99 f(count, stk) 100 } 101 } 102 103 func testCPUProfile(t *testing.T, need []string, f func(dur time.Duration)) { 104 switch runtime.GOOS { 105 case "darwin": 106 switch runtime.GOARCH { 107 case "arm", "arm64": 108 // nothing 109 default: 110 out, err := exec.Command("uname", "-a").CombinedOutput() 111 if err != nil { 112 t.Fatal(err) 113 } 114 vers := string(out) 115 t.Logf("uname -a: %v", vers) 116 } 117 case "plan9": 118 t.Skip("skipping on plan9") 119 } 120 121 const maxDuration = 5 * time.Second 122 // If we're running a long test, start with a long duration 123 // for tests that try to make sure something *doesn't* happen. 124 duration := 5 * time.Second 125 if testing.Short() { 126 duration = 200 * time.Millisecond 127 } 128 129 // Profiling tests are inherently flaky, especially on a 130 // loaded system, such as when this test is running with 131 // several others under go test std. If a test fails in a way 132 // that could mean it just didn't run long enough, try with a 133 // longer duration. 134 for duration <= maxDuration { 135 var prof bytes.Buffer 136 if err := StartCPUProfile(&prof); err != nil { 137 t.Fatal(err) 138 } 139 f(duration) 140 StopCPUProfile() 141 142 if profileOk(t, need, prof, duration) { 143 return 144 } 145 146 duration *= 2 147 if duration <= maxDuration { 148 t.Logf("retrying with %s duration", duration) 149 } 150 } 151 152 if badOS[runtime.GOOS] { 153 t.Skipf("ignoring failure on %s; see golang.org/issue/13841", runtime.GOOS) 154 return 155 } 156 // Ignore the failure if the tests are running in a QEMU-based emulator, 157 // QEMU is not perfect at emulating everything. 158 // IN_QEMU environmental variable is set by some of the Go builders. 159 // IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605. 160 if os.Getenv("IN_QEMU") == "1" { 161 t.Skip("ignore the failure in QEMU; see golang.org/issue/9605") 162 return 163 } 164 t.FailNow() 165 } 166 167 func profileOk(t *testing.T, need []string, prof bytes.Buffer, duration time.Duration) (ok bool) { 168 ok = true 169 170 // Check that profile is well formed and contains need. 171 have := make([]uintptr, len(need)) 172 var samples uintptr 173 var buf bytes.Buffer 174 parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) { 175 fmt.Fprintf(&buf, "%d:", count) 176 samples += count 177 for _, pc := range stk { 178 fmt.Fprintf(&buf, " %#x", pc) 179 f := runtime.FuncForPC(pc) 180 if f == nil { 181 continue 182 } 183 fmt.Fprintf(&buf, "(%s)", f.Name()) 184 for i, name := range need { 185 if strings.Contains(f.Name(), name) { 186 have[i] += count 187 } 188 } 189 } 190 fmt.Fprintf(&buf, "\n") 191 }) 192 t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String()) 193 194 if samples < 10 && runtime.GOOS == "windows" { 195 // On some windows machines we end up with 196 // not enough samples due to coarse timer 197 // resolution. Let it go. 198 t.Log("too few samples on Windows (golang.org/issue/10842)") 199 return false 200 } 201 202 // Check that we got a reasonable number of samples. 203 // We used to always require at least ideal/4 samples, 204 // but that is too hard to guarantee on a loaded system. 205 // Now we accept 10 or more samples, which we take to be 206 // enough to show that at least some profiling is occurring. 207 if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) { 208 t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal) 209 ok = false 210 } 211 212 if len(need) == 0 { 213 return ok 214 } 215 216 var total uintptr 217 for i, name := range need { 218 total += have[i] 219 t.Logf("%s: %d\n", name, have[i]) 220 } 221 if total == 0 { 222 t.Logf("no samples in expected functions") 223 ok = false 224 } 225 // We'd like to check a reasonable minimum, like 226 // total / len(have) / smallconstant, but this test is 227 // pretty flaky (see bug 7095). So we'll just test to 228 // make sure we got at least one sample. 229 min := uintptr(1) 230 for i, name := range need { 231 if have[i] < min { 232 t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have))) 233 ok = false 234 } 235 } 236 return ok 237 } 238 239 // Fork can hang if preempted with signals frequently enough (see issue 5517). 240 // Ensure that we do not do this. 241 func TestCPUProfileWithFork(t *testing.T) { 242 testenv.MustHaveExec(t) 243 244 heap := 1 << 30 245 if runtime.GOOS == "android" { 246 // Use smaller size for Android to avoid crash. 247 heap = 100 << 20 248 } 249 if testing.Short() { 250 heap = 100 << 20 251 } 252 // This makes fork slower. 253 garbage := make([]byte, heap) 254 // Need to touch the slice, otherwise it won't be paged in. 255 done := make(chan bool) 256 go func() { 257 for i := range garbage { 258 garbage[i] = 42 259 } 260 done <- true 261 }() 262 <-done 263 264 var prof bytes.Buffer 265 if err := StartCPUProfile(&prof); err != nil { 266 t.Fatal(err) 267 } 268 defer StopCPUProfile() 269 270 for i := 0; i < 10; i++ { 271 exec.Command(os.Args[0], "-h").CombinedOutput() 272 } 273 } 274 275 // Test that profiler does not observe runtime.gogo as "user" goroutine execution. 276 // If it did, it would see inconsistent state and would either record an incorrect stack 277 // or crash because the stack was malformed. 278 func TestGoroutineSwitch(t *testing.T) { 279 // How much to try. These defaults take about 1 seconds 280 // on a 2012 MacBook Pro. The ones in short mode take 281 // about 0.1 seconds. 282 tries := 10 283 count := 1000000 284 if testing.Short() { 285 tries = 1 286 } 287 for try := 0; try < tries; try++ { 288 var prof bytes.Buffer 289 if err := StartCPUProfile(&prof); err != nil { 290 t.Fatal(err) 291 } 292 for i := 0; i < count; i++ { 293 runtime.Gosched() 294 } 295 StopCPUProfile() 296 297 // Read profile to look for entries for runtime.gogo with an attempt at a traceback. 298 // The special entry 299 parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) { 300 // An entry with two frames with 'System' in its top frame 301 // exists to record a PC without a traceback. Those are okay. 302 if len(stk) == 2 { 303 f := runtime.FuncForPC(stk[1]) 304 if f != nil && (f.Name() == "runtime._System" || f.Name() == "runtime._ExternalCode" || f.Name() == "runtime._GC") { 305 return 306 } 307 } 308 309 // Otherwise, should not see runtime.gogo. 310 // The place we'd see it would be the inner most frame. 311 f := runtime.FuncForPC(stk[0]) 312 if f != nil && f.Name() == "runtime.gogo" { 313 var buf bytes.Buffer 314 for _, pc := range stk { 315 f := runtime.FuncForPC(pc) 316 if f == nil { 317 fmt.Fprintf(&buf, "%#x ?:0\n", pc) 318 } else { 319 file, line := f.FileLine(pc) 320 fmt.Fprintf(&buf, "%#x %s:%d\n", pc, file, line) 321 } 322 } 323 t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String()) 324 } 325 }) 326 } 327 } 328 329 // Test that profiling of division operations is okay, especially on ARM. See issue 6681. 330 func TestMathBigDivide(t *testing.T) { 331 testCPUProfile(t, nil, func(duration time.Duration) { 332 t := time.After(duration) 333 pi := new(big.Int) 334 for { 335 for i := 0; i < 100; i++ { 336 n := big.NewInt(2646693125139304345) 337 d := big.NewInt(842468587426513207) 338 pi.Div(n, d) 339 } 340 select { 341 case <-t: 342 return 343 default: 344 } 345 } 346 }) 347 } 348 349 // Operating systems that are expected to fail the tests. See issue 13841. 350 var badOS = map[string]bool{ 351 "darwin": true, 352 "netbsd": true, 353 "plan9": true, 354 "dragonfly": true, 355 "solaris": true, 356 } 357 358 func TestBlockProfile(t *testing.T) { 359 type TestCase struct { 360 name string 361 f func() 362 re string 363 } 364 tests := [...]TestCase{ 365 {"chan recv", blockChanRecv, ` 366 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 367 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 368 # 0x[0-9a-f]+ runtime/pprof\.blockChanRecv\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 369 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 370 `}, 371 {"chan send", blockChanSend, ` 372 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 373 # 0x[0-9a-f]+ runtime\.chansend1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 374 # 0x[0-9a-f]+ runtime/pprof\.blockChanSend\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 375 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 376 `}, 377 {"chan close", blockChanClose, ` 378 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 379 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 380 # 0x[0-9a-f]+ runtime/pprof\.blockChanClose\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 381 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 382 `}, 383 {"select recv async", blockSelectRecvAsync, ` 384 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 385 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*/src/runtime/select.go:[0-9]+ 386 # 0x[0-9a-f]+ runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 387 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 388 `}, 389 {"select send sync", blockSelectSendSync, ` 390 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 391 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*/src/runtime/select.go:[0-9]+ 392 # 0x[0-9a-f]+ runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 393 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 394 `}, 395 {"mutex", blockMutex, ` 396 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 397 # 0x[0-9a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+ .*/src/sync/mutex\.go:[0-9]+ 398 # 0x[0-9a-f]+ runtime/pprof\.blockMutex\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 399 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 400 `}, 401 {"cond", blockCond, ` 402 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 403 # 0x[0-9a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+ .*/src/sync/cond\.go:[0-9]+ 404 # 0x[0-9a-f]+ runtime/pprof\.blockCond\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 405 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 406 `}, 407 } 408 409 runtime.SetBlockProfileRate(1) 410 defer runtime.SetBlockProfileRate(0) 411 for _, test := range tests { 412 test.f() 413 } 414 var w bytes.Buffer 415 Lookup("block").WriteTo(&w, 1) 416 prof := w.String() 417 418 if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") { 419 t.Fatalf("Bad profile header:\n%v", prof) 420 } 421 422 if strings.HasSuffix(prof, "#\t0x0\n\n") { 423 t.Errorf("Useless 0 suffix:\n%v", prof) 424 } 425 426 for _, test := range tests { 427 if !regexp.MustCompile(strings.Replace(test.re, "\t", "\t+", -1)).MatchString(prof) { 428 t.Fatalf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof) 429 } 430 } 431 } 432 433 const blockDelay = 10 * time.Millisecond 434 435 func blockChanRecv() { 436 c := make(chan bool) 437 go func() { 438 time.Sleep(blockDelay) 439 c <- true 440 }() 441 <-c 442 } 443 444 func blockChanSend() { 445 c := make(chan bool) 446 go func() { 447 time.Sleep(blockDelay) 448 <-c 449 }() 450 c <- true 451 } 452 453 func blockChanClose() { 454 c := make(chan bool) 455 go func() { 456 time.Sleep(blockDelay) 457 close(c) 458 }() 459 <-c 460 } 461 462 func blockSelectRecvAsync() { 463 const numTries = 3 464 c := make(chan bool, 1) 465 c2 := make(chan bool, 1) 466 go func() { 467 for i := 0; i < numTries; i++ { 468 time.Sleep(blockDelay) 469 c <- true 470 } 471 }() 472 for i := 0; i < numTries; i++ { 473 select { 474 case <-c: 475 case <-c2: 476 } 477 } 478 } 479 480 func blockSelectSendSync() { 481 c := make(chan bool) 482 c2 := make(chan bool) 483 go func() { 484 time.Sleep(blockDelay) 485 <-c 486 }() 487 select { 488 case c <- true: 489 case c2 <- true: 490 } 491 } 492 493 func blockMutex() { 494 var mu sync.Mutex 495 mu.Lock() 496 go func() { 497 time.Sleep(blockDelay) 498 mu.Unlock() 499 }() 500 mu.Lock() 501 } 502 503 func blockCond() { 504 var mu sync.Mutex 505 c := sync.NewCond(&mu) 506 mu.Lock() 507 go func() { 508 time.Sleep(blockDelay) 509 mu.Lock() 510 c.Signal() 511 mu.Unlock() 512 }() 513 c.Wait() 514 mu.Unlock() 515 } 516 517 func TestMutexProfile(t *testing.T) { 518 testenv.SkipFlaky(t, 19139) 519 old := runtime.SetMutexProfileFraction(1) 520 defer runtime.SetMutexProfileFraction(old) 521 if old != 0 { 522 t.Fatalf("need MutexProfileRate 0, got %d", old) 523 } 524 525 blockMutex() 526 527 var w bytes.Buffer 528 Lookup("mutex").WriteTo(&w, 1) 529 prof := w.String() 530 531 if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") { 532 t.Errorf("Bad profile header:\n%v", prof) 533 } 534 prof = strings.Trim(prof, "\n") 535 lines := strings.Split(prof, "\n") 536 if len(lines) != 6 { 537 t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof) 538 } 539 if len(lines) < 6 { 540 return 541 } 542 // checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931" 543 r2 := `^\d+ 1 @(?: 0x[[:xdigit:]]+)+` 544 //r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$" 545 if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok { 546 t.Errorf("%q didn't match %q", lines[3], r2) 547 } 548 r3 := "^#.*runtime/pprof.blockMutex.*$" 549 if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok { 550 t.Errorf("%q didn't match %q", lines[5], r3) 551 } 552 } 553 554 func func1(c chan int) { <-c } 555 func func2(c chan int) { <-c } 556 func func3(c chan int) { <-c } 557 func func4(c chan int) { <-c } 558 559 func TestGoroutineCounts(t *testing.T) { 560 if runtime.GOOS == "openbsd" { 561 testenv.SkipFlaky(t, 15156) 562 } 563 c := make(chan int) 564 for i := 0; i < 100; i++ { 565 if i%10 == 0 { 566 go func1(c) 567 continue 568 } 569 if i%2 == 0 { 570 go func2(c) 571 continue 572 } 573 go func3(c) 574 } 575 time.Sleep(10 * time.Millisecond) // let goroutines block on channel 576 577 var w bytes.Buffer 578 goroutineProf := Lookup("goroutine") 579 580 // Check debug profile 581 goroutineProf.WriteTo(&w, 1) 582 prof := w.String() 583 584 if !containsInOrder(prof, "\n50 @ ", "\n40 @", "\n10 @", "\n1 @") { 585 t.Errorf("expected sorted goroutine counts:\n%s", prof) 586 } 587 588 // Check proto profile 589 w.Reset() 590 goroutineProf.WriteTo(&w, 0) 591 p, err := profile.Parse(&w) 592 if err != nil { 593 t.Errorf("error parsing protobuf profile: %v", err) 594 } 595 if err := p.CheckValid(); err != nil { 596 t.Errorf("protobuf profile is invalid: %v", err) 597 } 598 if !containsCounts(p, []int64{50, 40, 10, 1}) { 599 t.Errorf("expected count profile to contain goroutines with counts %v, got %v", 600 []int64{50, 40, 10, 1}, p) 601 } 602 603 close(c) 604 605 time.Sleep(10 * time.Millisecond) // let goroutines exit 606 } 607 608 func containsInOrder(s string, all ...string) bool { 609 for _, t := range all { 610 i := strings.Index(s, t) 611 if i < 0 { 612 return false 613 } 614 s = s[i+len(t):] 615 } 616 return true 617 } 618 619 func containsCounts(prof *profile.Profile, counts []int64) bool { 620 m := make(map[int64]int) 621 for _, c := range counts { 622 m[c]++ 623 } 624 for _, s := range prof.Sample { 625 // The count is the single value in the sample 626 if len(s.Value) != 1 { 627 return false 628 } 629 m[s.Value[0]]-- 630 } 631 for _, n := range m { 632 if n > 0 { 633 return false 634 } 635 } 636 return true 637 } 638 639 // Issue 18836. 640 func TestEmptyCallStack(t *testing.T) { 641 t.Parallel() 642 var buf bytes.Buffer 643 p := NewProfile("test18836") 644 p.Add("foo", 47674) 645 p.WriteTo(&buf, 1) 646 p.Remove("foo") 647 got := buf.String() 648 prefix := "test18836 profile: total 1\n" 649 if !strings.HasPrefix(got, prefix) { 650 t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix) 651 } 652 lostevent := "lostProfileEvent" 653 if !strings.Contains(got, lostevent) { 654 t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent) 655 } 656 }