github.com/zxy12/go_duplicate_112_new@v0.0.0-20200807091221-747231827200/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 !aix,!nacl,!js 6 7 package pprof 8 9 import ( 10 "bytes" 11 "context" 12 "fmt" 13 "internal/testenv" 14 "io" 15 "io/ioutil" 16 "math/big" 17 "os" 18 "os/exec" 19 "regexp" 20 "runtime" 21 "runtime/pprof/internal/profile" 22 "strings" 23 "sync" 24 "sync/atomic" 25 "testing" 26 "time" 27 ) 28 29 func cpuHogger(f func(x int) int, y *int, dur time.Duration) { 30 // We only need to get one 100 Hz clock tick, so we've got 31 // a large safety buffer. 32 // But do at least 500 iterations (which should take about 100ms), 33 // otherwise TestCPUProfileMultithreaded can fail if only one 34 // thread is scheduled during the testing period. 35 t0 := time.Now() 36 accum := *y 37 for i := 0; i < 500 || time.Since(t0) < dur; i++ { 38 accum = f(accum) 39 } 40 *y = accum 41 } 42 43 var ( 44 salt1 = 0 45 salt2 = 0 46 ) 47 48 // The actual CPU hogging function. 49 // Must not call other functions nor access heap/globals in the loop, 50 // otherwise under race detector the samples will be in the race runtime. 51 func cpuHog1(x int) int { 52 foo := x 53 for i := 0; i < 1e5; i++ { 54 if foo > 0 { 55 foo *= foo 56 } else { 57 foo *= foo + 1 58 } 59 } 60 return foo 61 } 62 63 func cpuHog2(x int) int { 64 foo := x 65 for i := 0; i < 1e5; i++ { 66 if foo > 0 { 67 foo *= foo 68 } else { 69 foo *= foo + 2 70 } 71 } 72 return foo 73 } 74 75 // Return a list of functions that we don't want to ever appear in CPU 76 // profiles. For gccgo, that list includes the sigprof handler itself. 77 func avoidFunctions() []string { 78 if runtime.Compiler == "gccgo" { 79 return []string{"runtime.sigprof"} 80 } 81 return nil 82 } 83 84 func TestCPUProfile(t *testing.T) { 85 testCPUProfile(t, stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions(), func(dur time.Duration) { 86 cpuHogger(cpuHog1, &salt1, dur) 87 }) 88 } 89 90 func TestCPUProfileMultithreaded(t *testing.T) { 91 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2)) 92 testCPUProfile(t, stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions(), func(dur time.Duration) { 93 c := make(chan int) 94 go func() { 95 cpuHogger(cpuHog1, &salt1, dur) 96 c <- 1 97 }() 98 cpuHogger(cpuHog2, &salt2, dur) 99 <-c 100 }) 101 } 102 103 func TestCPUProfileInlining(t *testing.T) { 104 testCPUProfile(t, stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions(), func(dur time.Duration) { 105 cpuHogger(inlinedCaller, &salt1, dur) 106 }) 107 } 108 109 func inlinedCaller(x int) int { 110 x = inlinedCallee(x) 111 return x 112 } 113 114 func inlinedCallee(x int) int { 115 // We could just use cpuHog1, but for loops prevent inlining 116 // right now. :( 117 foo := x 118 i := 0 119 loop: 120 if foo > 0 { 121 foo *= foo 122 } else { 123 foo *= foo + 1 124 } 125 if i++; i < 1e5 { 126 goto loop 127 } 128 return foo 129 } 130 131 func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) { 132 p, err := profile.Parse(bytes.NewReader(valBytes)) 133 if err != nil { 134 t.Fatal(err) 135 } 136 for _, sample := range p.Sample { 137 count := uintptr(sample.Value[0]) 138 f(count, sample.Location, sample.Label) 139 } 140 } 141 142 // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need, 143 // as interpreted by matches. 144 func testCPUProfile(t *testing.T, matches matchFunc, need []string, avoid []string, f func(dur time.Duration)) { 145 switch runtime.GOOS { 146 case "darwin": 147 switch runtime.GOARCH { 148 case "arm", "arm64": 149 // nothing 150 default: 151 out, err := exec.Command("uname", "-a").CombinedOutput() 152 if err != nil { 153 t.Fatal(err) 154 } 155 vers := string(out) 156 t.Logf("uname -a: %v", vers) 157 } 158 case "plan9": 159 t.Skip("skipping on plan9") 160 } 161 162 const maxDuration = 5 * time.Second 163 // If we're running a long test, start with a long duration 164 // for tests that try to make sure something *doesn't* happen. 165 duration := 5 * time.Second 166 if testing.Short() { 167 duration = 200 * time.Millisecond 168 } 169 170 // Profiling tests are inherently flaky, especially on a 171 // loaded system, such as when this test is running with 172 // several others under go test std. If a test fails in a way 173 // that could mean it just didn't run long enough, try with a 174 // longer duration. 175 for duration <= maxDuration { 176 var prof bytes.Buffer 177 if err := StartCPUProfile(&prof); err != nil { 178 t.Fatal(err) 179 } 180 f(duration) 181 StopCPUProfile() 182 183 if profileOk(t, matches, need, avoid, prof, duration) { 184 return 185 } 186 187 duration *= 2 188 if duration <= maxDuration { 189 t.Logf("retrying with %s duration", duration) 190 } 191 } 192 193 switch runtime.GOOS { 194 case "darwin", "dragonfly", "netbsd", "solaris": 195 t.Skipf("ignoring failure on %s; see golang.org/issue/13841", runtime.GOOS) 196 case "openbsd": 197 if runtime.GOARCH == "arm" { 198 t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH) 199 } 200 } 201 // Ignore the failure if the tests are running in a QEMU-based emulator, 202 // QEMU is not perfect at emulating everything. 203 // IN_QEMU environmental variable is set by some of the Go builders. 204 // IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605. 205 if os.Getenv("IN_QEMU") == "1" { 206 t.Skip("ignore the failure in QEMU; see golang.org/issue/9605") 207 } 208 t.FailNow() 209 } 210 211 func contains(slice []string, s string) bool { 212 for i := range slice { 213 if slice[i] == s { 214 return true 215 } 216 } 217 return false 218 } 219 220 // stackContains matches if a function named spec appears anywhere in the stack trace. 221 func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 222 for _, loc := range stk { 223 for _, line := range loc.Line { 224 if strings.Contains(line.Function.Name, spec) { 225 return true 226 } 227 } 228 } 229 return false 230 } 231 232 type matchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool 233 234 func profileOk(t *testing.T, matches matchFunc, need []string, avoid []string, prof bytes.Buffer, duration time.Duration) (ok bool) { 235 ok = true 236 237 // Check that profile is well formed, contains 'need', and does not contain 238 // anything from 'avoid'. 239 have := make([]uintptr, len(need)) 240 avoidSamples := make([]uintptr, len(avoid)) 241 var samples uintptr 242 var buf bytes.Buffer 243 parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) { 244 fmt.Fprintf(&buf, "%d:", count) 245 fprintStack(&buf, stk) 246 samples += count 247 for i, spec := range need { 248 if matches(spec, count, stk, labels) { 249 have[i] += count 250 } 251 } 252 for i, name := range avoid { 253 for _, loc := range stk { 254 for _, line := range loc.Line { 255 if strings.Contains(line.Function.Name, name) { 256 avoidSamples[i] += count 257 } 258 } 259 } 260 } 261 fmt.Fprintf(&buf, "\n") 262 }) 263 t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String()) 264 265 if samples < 10 && runtime.GOOS == "windows" { 266 // On some windows machines we end up with 267 // not enough samples due to coarse timer 268 // resolution. Let it go. 269 t.Log("too few samples on Windows (golang.org/issue/10842)") 270 return false 271 } 272 273 // Check that we got a reasonable number of samples. 274 // We used to always require at least ideal/4 samples, 275 // but that is too hard to guarantee on a loaded system. 276 // Now we accept 10 or more samples, which we take to be 277 // enough to show that at least some profiling is occurring. 278 if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) { 279 t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal) 280 ok = false 281 } 282 283 for i, name := range avoid { 284 bad := avoidSamples[i] 285 if bad != 0 { 286 t.Logf("found %d samples in avoid-function %s\n", bad, name) 287 ok = false 288 } 289 } 290 291 if len(need) == 0 { 292 return ok 293 } 294 295 var total uintptr 296 for i, name := range need { 297 total += have[i] 298 t.Logf("%s: %d\n", name, have[i]) 299 } 300 if total == 0 { 301 t.Logf("no samples in expected functions") 302 ok = false 303 } 304 // We'd like to check a reasonable minimum, like 305 // total / len(have) / smallconstant, but this test is 306 // pretty flaky (see bug 7095). So we'll just test to 307 // make sure we got at least one sample. 308 min := uintptr(1) 309 for i, name := range need { 310 if have[i] < min { 311 t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have))) 312 ok = false 313 } 314 } 315 return ok 316 } 317 318 // Fork can hang if preempted with signals frequently enough (see issue 5517). 319 // Ensure that we do not do this. 320 func TestCPUProfileWithFork(t *testing.T) { 321 testenv.MustHaveExec(t) 322 323 heap := 1 << 30 324 if runtime.GOOS == "android" { 325 // Use smaller size for Android to avoid crash. 326 heap = 100 << 20 327 } 328 if runtime.GOOS == "windows" && runtime.GOARCH == "arm" { 329 // Use smaller heap for Windows/ARM to avoid crash. 330 heap = 100 << 20 331 } 332 if testing.Short() { 333 heap = 100 << 20 334 } 335 // This makes fork slower. 336 garbage := make([]byte, heap) 337 // Need to touch the slice, otherwise it won't be paged in. 338 done := make(chan bool) 339 go func() { 340 for i := range garbage { 341 garbage[i] = 42 342 } 343 done <- true 344 }() 345 <-done 346 347 var prof bytes.Buffer 348 if err := StartCPUProfile(&prof); err != nil { 349 t.Fatal(err) 350 } 351 defer StopCPUProfile() 352 353 for i := 0; i < 10; i++ { 354 exec.Command(os.Args[0], "-h").CombinedOutput() 355 } 356 } 357 358 // Test that profiler does not observe runtime.gogo as "user" goroutine execution. 359 // If it did, it would see inconsistent state and would either record an incorrect stack 360 // or crash because the stack was malformed. 361 func TestGoroutineSwitch(t *testing.T) { 362 if runtime.Compiler == "gccgo" { 363 t.Skip("not applicable for gccgo") 364 } 365 // How much to try. These defaults take about 1 seconds 366 // on a 2012 MacBook Pro. The ones in short mode take 367 // about 0.1 seconds. 368 tries := 10 369 count := 1000000 370 if testing.Short() { 371 tries = 1 372 } 373 for try := 0; try < tries; try++ { 374 var prof bytes.Buffer 375 if err := StartCPUProfile(&prof); err != nil { 376 t.Fatal(err) 377 } 378 for i := 0; i < count; i++ { 379 runtime.Gosched() 380 } 381 StopCPUProfile() 382 383 // Read profile to look for entries for runtime.gogo with an attempt at a traceback. 384 // The special entry 385 parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) { 386 // An entry with two frames with 'System' in its top frame 387 // exists to record a PC without a traceback. Those are okay. 388 if len(stk) == 2 { 389 name := stk[1].Line[0].Function.Name 390 if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" { 391 return 392 } 393 } 394 395 // Otherwise, should not see runtime.gogo. 396 // The place we'd see it would be the inner most frame. 397 name := stk[0].Line[0].Function.Name 398 if name == "runtime.gogo" { 399 var buf bytes.Buffer 400 fprintStack(&buf, stk) 401 t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String()) 402 } 403 }) 404 } 405 } 406 407 func fprintStack(w io.Writer, stk []*profile.Location) { 408 for _, loc := range stk { 409 fmt.Fprintf(w, " %#x", loc.Address) 410 fmt.Fprintf(w, " (") 411 for i, line := range loc.Line { 412 if i > 0 { 413 fmt.Fprintf(w, " ") 414 } 415 fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line) 416 } 417 fmt.Fprintf(w, ")") 418 } 419 fmt.Fprintf(w, "\n") 420 } 421 422 // Test that profiling of division operations is okay, especially on ARM. See issue 6681. 423 func TestMathBigDivide(t *testing.T) { 424 testCPUProfile(t, nil, nil, nil, func(duration time.Duration) { 425 t := time.After(duration) 426 pi := new(big.Int) 427 for { 428 for i := 0; i < 100; i++ { 429 n := big.NewInt(2646693125139304345) 430 d := big.NewInt(842468587426513207) 431 pi.Div(n, d) 432 } 433 select { 434 case <-t: 435 return 436 default: 437 } 438 } 439 }) 440 } 441 442 // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace. 443 func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 444 for _, f := range strings.Split(spec, ",") { 445 if !stackContains(f, count, stk, labels) { 446 return false 447 } 448 } 449 return true 450 } 451 452 func TestMorestack(t *testing.T) { 453 testCPUProfile(t, stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions(), func(duration time.Duration) { 454 t := time.After(duration) 455 c := make(chan bool) 456 for { 457 go func() { 458 growstack1() 459 c <- true 460 }() 461 select { 462 case <-t: 463 return 464 case <-c: 465 } 466 } 467 }) 468 } 469 470 //go:noinline 471 func growstack1() { 472 growstack() 473 } 474 475 //go:noinline 476 func growstack() { 477 var buf [8 << 10]byte 478 use(buf) 479 } 480 481 //go:noinline 482 func use(x [8 << 10]byte) {} 483 484 func TestBlockProfile(t *testing.T) { 485 type TestCase struct { 486 name string 487 f func() 488 stk []string 489 re string 490 } 491 tests := [...]TestCase{ 492 { 493 name: "chan recv", 494 f: blockChanRecv, 495 stk: []string{ 496 "runtime.chanrecv1", 497 "runtime/pprof.blockChanRecv", 498 "runtime/pprof.TestBlockProfile", 499 }, 500 re: ` 501 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 502 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 503 # 0x[0-9a-f]+ runtime/pprof\.blockChanRecv\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 504 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 505 `}, 506 { 507 name: "chan send", 508 f: blockChanSend, 509 stk: []string{ 510 "runtime.chansend1", 511 "runtime/pprof.blockChanSend", 512 "runtime/pprof.TestBlockProfile", 513 }, 514 re: ` 515 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 516 # 0x[0-9a-f]+ runtime\.chansend1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 517 # 0x[0-9a-f]+ runtime/pprof\.blockChanSend\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 518 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 519 `}, 520 { 521 name: "chan close", 522 f: blockChanClose, 523 stk: []string{ 524 "runtime.chanrecv1", 525 "runtime/pprof.blockChanClose", 526 "runtime/pprof.TestBlockProfile", 527 }, 528 re: ` 529 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 530 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 531 # 0x[0-9a-f]+ runtime/pprof\.blockChanClose\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 532 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 533 `}, 534 { 535 name: "select recv async", 536 f: blockSelectRecvAsync, 537 stk: []string{ 538 "runtime.selectgo", 539 "runtime/pprof.blockSelectRecvAsync", 540 "runtime/pprof.TestBlockProfile", 541 }, 542 re: ` 543 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 544 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*/src/runtime/select.go:[0-9]+ 545 # 0x[0-9a-f]+ runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 546 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 547 `}, 548 { 549 name: "select send sync", 550 f: blockSelectSendSync, 551 stk: []string{ 552 "runtime.selectgo", 553 "runtime/pprof.blockSelectSendSync", 554 "runtime/pprof.TestBlockProfile", 555 }, 556 re: ` 557 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 558 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*/src/runtime/select.go:[0-9]+ 559 # 0x[0-9a-f]+ runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 560 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 561 `}, 562 { 563 name: "mutex", 564 f: blockMutex, 565 stk: []string{ 566 "sync.(*Mutex).Lock", 567 "runtime/pprof.blockMutex", 568 "runtime/pprof.TestBlockProfile", 569 }, 570 re: ` 571 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 572 # 0x[0-9a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+ .*/src/sync/mutex\.go:[0-9]+ 573 # 0x[0-9a-f]+ runtime/pprof\.blockMutex\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 574 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 575 `}, 576 { 577 name: "cond", 578 f: blockCond, 579 stk: []string{ 580 "sync.(*Cond).Wait", 581 "runtime/pprof.blockCond", 582 "runtime/pprof.TestBlockProfile", 583 }, 584 re: ` 585 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 586 # 0x[0-9a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+ .*/src/sync/cond\.go:[0-9]+ 587 # 0x[0-9a-f]+ runtime/pprof\.blockCond\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 588 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 589 `}, 590 } 591 592 // Generate block profile 593 runtime.SetBlockProfileRate(1) 594 defer runtime.SetBlockProfileRate(0) 595 for _, test := range tests { 596 test.f() 597 } 598 599 t.Run("debug=1", func(t *testing.T) { 600 var w bytes.Buffer 601 Lookup("block").WriteTo(&w, 1) 602 prof := w.String() 603 604 if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") { 605 t.Fatalf("Bad profile header:\n%v", prof) 606 } 607 608 if strings.HasSuffix(prof, "#\t0x0\n\n") { 609 t.Errorf("Useless 0 suffix:\n%v", prof) 610 } 611 612 for _, test := range tests { 613 if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) { 614 t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof) 615 } 616 } 617 }) 618 619 t.Run("proto", func(t *testing.T) { 620 // proto format 621 var w bytes.Buffer 622 Lookup("block").WriteTo(&w, 0) 623 p, err := profile.Parse(&w) 624 if err != nil { 625 t.Fatalf("failed to parse profile: %v", err) 626 } 627 t.Logf("parsed proto: %s", p) 628 if err := p.CheckValid(); err != nil { 629 t.Fatalf("invalid profile: %v", err) 630 } 631 632 stks := stacks(p) 633 for _, test := range tests { 634 if !containsStack(stks, test.stk) { 635 t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk) 636 } 637 } 638 }) 639 640 } 641 642 func stacks(p *profile.Profile) (res [][]string) { 643 for _, s := range p.Sample { 644 var stk []string 645 for _, l := range s.Location { 646 for _, line := range l.Line { 647 stk = append(stk, line.Function.Name) 648 } 649 } 650 res = append(res, stk) 651 } 652 return res 653 } 654 655 func containsStack(got [][]string, want []string) bool { 656 for _, stk := range got { 657 if len(stk) < len(want) { 658 continue 659 } 660 for i, f := range want { 661 if f != stk[i] { 662 break 663 } 664 if i == len(want)-1 { 665 return true 666 } 667 } 668 } 669 return false 670 } 671 672 const blockDelay = 10 * time.Millisecond 673 674 func blockChanRecv() { 675 c := make(chan bool) 676 go func() { 677 time.Sleep(blockDelay) 678 c <- true 679 }() 680 <-c 681 } 682 683 func blockChanSend() { 684 c := make(chan bool) 685 go func() { 686 time.Sleep(blockDelay) 687 <-c 688 }() 689 c <- true 690 } 691 692 func blockChanClose() { 693 c := make(chan bool) 694 go func() { 695 time.Sleep(blockDelay) 696 close(c) 697 }() 698 <-c 699 } 700 701 func blockSelectRecvAsync() { 702 const numTries = 3 703 c := make(chan bool, 1) 704 c2 := make(chan bool, 1) 705 go func() { 706 for i := 0; i < numTries; i++ { 707 time.Sleep(blockDelay) 708 c <- true 709 } 710 }() 711 for i := 0; i < numTries; i++ { 712 select { 713 case <-c: 714 case <-c2: 715 } 716 } 717 } 718 719 func blockSelectSendSync() { 720 c := make(chan bool) 721 c2 := make(chan bool) 722 go func() { 723 time.Sleep(blockDelay) 724 <-c 725 }() 726 select { 727 case c <- true: 728 case c2 <- true: 729 } 730 } 731 732 func blockMutex() { 733 var mu sync.Mutex 734 mu.Lock() 735 go func() { 736 time.Sleep(blockDelay) 737 mu.Unlock() 738 }() 739 // Note: Unlock releases mu before recording the mutex event, 740 // so it's theoretically possible for this to proceed and 741 // capture the profile before the event is recorded. As long 742 // as this is blocked before the unlock happens, it's okay. 743 mu.Lock() 744 } 745 746 func blockCond() { 747 var mu sync.Mutex 748 c := sync.NewCond(&mu) 749 mu.Lock() 750 go func() { 751 time.Sleep(blockDelay) 752 mu.Lock() 753 c.Signal() 754 mu.Unlock() 755 }() 756 c.Wait() 757 mu.Unlock() 758 } 759 760 func TestMutexProfile(t *testing.T) { 761 // Generate mutex profile 762 763 old := runtime.SetMutexProfileFraction(1) 764 defer runtime.SetMutexProfileFraction(old) 765 if old != 0 { 766 t.Fatalf("need MutexProfileRate 0, got %d", old) 767 } 768 769 blockMutex() 770 771 t.Run("debug=1", func(t *testing.T) { 772 var w bytes.Buffer 773 Lookup("mutex").WriteTo(&w, 1) 774 prof := w.String() 775 t.Logf("received profile: %v", prof) 776 777 if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") { 778 t.Errorf("Bad profile header:\n%v", prof) 779 } 780 prof = strings.Trim(prof, "\n") 781 lines := strings.Split(prof, "\n") 782 if len(lines) != 6 { 783 t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof) 784 } 785 if len(lines) < 6 { 786 return 787 } 788 // checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931" 789 r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+` 790 //r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$" 791 if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok { 792 t.Errorf("%q didn't match %q", lines[3], r2) 793 } 794 r3 := "^#.*runtime/pprof.blockMutex.*$" 795 if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok { 796 t.Errorf("%q didn't match %q", lines[5], r3) 797 } 798 t.Logf(prof) 799 }) 800 t.Run("proto", func(t *testing.T) { 801 // proto format 802 var w bytes.Buffer 803 Lookup("mutex").WriteTo(&w, 0) 804 p, err := profile.Parse(&w) 805 if err != nil { 806 t.Fatalf("failed to parse profile: %v", err) 807 } 808 t.Logf("parsed proto: %s", p) 809 if err := p.CheckValid(); err != nil { 810 t.Fatalf("invalid profile: %v", err) 811 } 812 813 stks := stacks(p) 814 for _, want := range [][]string{ 815 {"sync.(*Mutex).Unlock", "runtime/pprof.blockMutex.func1"}, 816 } { 817 if !containsStack(stks, want) { 818 t.Errorf("No matching stack entry for %+v", want) 819 } 820 } 821 }) 822 } 823 824 func func1(c chan int) { <-c } 825 func func2(c chan int) { <-c } 826 func func3(c chan int) { <-c } 827 func func4(c chan int) { <-c } 828 829 func TestGoroutineCounts(t *testing.T) { 830 // Setting GOMAXPROCS to 1 ensures we can force all goroutines to the 831 // desired blocking point. 832 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1)) 833 834 c := make(chan int) 835 for i := 0; i < 100; i++ { 836 switch { 837 case i%10 == 0: 838 go func1(c) 839 case i%2 == 0: 840 go func2(c) 841 default: 842 go func3(c) 843 } 844 // Let goroutines block on channel 845 for j := 0; j < 5; j++ { 846 runtime.Gosched() 847 } 848 } 849 850 var w bytes.Buffer 851 goroutineProf := Lookup("goroutine") 852 853 // Check debug profile 854 goroutineProf.WriteTo(&w, 1) 855 prof := w.String() 856 857 if !containsInOrder(prof, "\n50 @ ", "\n40 @", "\n10 @", "\n1 @") { 858 t.Errorf("expected sorted goroutine counts:\n%s", prof) 859 } 860 861 // Check proto profile 862 w.Reset() 863 goroutineProf.WriteTo(&w, 0) 864 p, err := profile.Parse(&w) 865 if err != nil { 866 t.Errorf("error parsing protobuf profile: %v", err) 867 } 868 if err := p.CheckValid(); err != nil { 869 t.Errorf("protobuf profile is invalid: %v", err) 870 } 871 if !containsCounts(p, []int64{50, 40, 10, 1}) { 872 t.Errorf("expected count profile to contain goroutines with counts %v, got %v", 873 []int64{50, 40, 10, 1}, p) 874 } 875 876 close(c) 877 878 time.Sleep(10 * time.Millisecond) // let goroutines exit 879 } 880 881 func containsInOrder(s string, all ...string) bool { 882 for _, t := range all { 883 i := strings.Index(s, t) 884 if i < 0 { 885 return false 886 } 887 s = s[i+len(t):] 888 } 889 return true 890 } 891 892 func containsCounts(prof *profile.Profile, counts []int64) bool { 893 m := make(map[int64]int) 894 for _, c := range counts { 895 m[c]++ 896 } 897 for _, s := range prof.Sample { 898 // The count is the single value in the sample 899 if len(s.Value) != 1 { 900 return false 901 } 902 m[s.Value[0]]-- 903 } 904 for _, n := range m { 905 if n > 0 { 906 return false 907 } 908 } 909 return true 910 } 911 912 var emptyCallStackTestRun int64 913 914 // Issue 18836. 915 func TestEmptyCallStack(t *testing.T) { 916 name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun) 917 emptyCallStackTestRun++ 918 919 t.Parallel() 920 var buf bytes.Buffer 921 p := NewProfile(name) 922 923 p.Add("foo", 47674) 924 p.WriteTo(&buf, 1) 925 p.Remove("foo") 926 got := buf.String() 927 prefix := name + " profile: total 1\n" 928 if !strings.HasPrefix(got, prefix) { 929 t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix) 930 } 931 lostevent := "lostProfileEvent" 932 if !strings.Contains(got, lostevent) { 933 t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent) 934 } 935 } 936 937 // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key 938 // and value and has funcname somewhere in the stack. 939 func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 940 semi := strings.Index(spec, ";") 941 if semi == -1 { 942 panic("no semicolon in key/value spec") 943 } 944 kv := strings.SplitN(spec[semi+1:], "=", 2) 945 if len(kv) != 2 { 946 panic("missing = in key/value spec") 947 } 948 if !contains(labels[kv[0]], kv[1]) { 949 return false 950 } 951 return stackContains(spec[:semi], count, stk, labels) 952 } 953 954 func TestCPUProfileLabel(t *testing.T) { 955 testCPUProfile(t, stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions(), func(dur time.Duration) { 956 Do(context.Background(), Labels("key", "value"), func(context.Context) { 957 cpuHogger(cpuHog1, &salt1, dur) 958 }) 959 }) 960 } 961 962 func TestLabelRace(t *testing.T) { 963 // Test the race detector annotations for synchronization 964 // between settings labels and consuming them from the 965 // profile. 966 testCPUProfile(t, stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil, func(dur time.Duration) { 967 start := time.Now() 968 var wg sync.WaitGroup 969 for time.Since(start) < dur { 970 var salts [10]int 971 for i := 0; i < 10; i++ { 972 wg.Add(1) 973 go func(j int) { 974 Do(context.Background(), Labels("key", "value"), func(context.Context) { 975 cpuHogger(cpuHog1, &salts[j], time.Millisecond) 976 }) 977 wg.Done() 978 }(i) 979 } 980 wg.Wait() 981 } 982 }) 983 } 984 985 // Check that there is no deadlock when the program receives SIGPROF while in 986 // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146. 987 func TestAtomicLoadStore64(t *testing.T) { 988 f, err := ioutil.TempFile("", "profatomic") 989 if err != nil { 990 t.Fatalf("TempFile: %v", err) 991 } 992 defer os.Remove(f.Name()) 993 defer f.Close() 994 995 if err := StartCPUProfile(f); err != nil { 996 t.Fatal(err) 997 } 998 defer StopCPUProfile() 999 1000 var flag uint64 1001 done := make(chan bool, 1) 1002 1003 go func() { 1004 for atomic.LoadUint64(&flag) == 0 { 1005 runtime.Gosched() 1006 } 1007 done <- true 1008 }() 1009 time.Sleep(50 * time.Millisecond) 1010 atomic.StoreUint64(&flag, 1) 1011 <-done 1012 } 1013 1014 func TestTracebackAll(t *testing.T) { 1015 // With gccgo, if a profiling signal arrives at the wrong time 1016 // during traceback, it may crash or hang. See issue #29448. 1017 f, err := ioutil.TempFile("", "proftraceback") 1018 if err != nil { 1019 t.Fatalf("TempFile: %v", err) 1020 } 1021 defer os.Remove(f.Name()) 1022 defer f.Close() 1023 1024 if err := StartCPUProfile(f); err != nil { 1025 t.Fatal(err) 1026 } 1027 defer StopCPUProfile() 1028 1029 ch := make(chan int) 1030 defer close(ch) 1031 1032 count := 10 1033 for i := 0; i < count; i++ { 1034 go func() { 1035 <-ch // block 1036 }() 1037 } 1038 1039 N := 10000 1040 if testing.Short() { 1041 N = 500 1042 } 1043 buf := make([]byte, 10*1024) 1044 for i := 0; i < N; i++ { 1045 runtime.Stack(buf, true) 1046 } 1047 }