github.com/m10x/go/src@v0.0.0-20220112094212-ba61592315da/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 //go:build !js 6 7 package pprof 8 9 import ( 10 "bytes" 11 "context" 12 "fmt" 13 "internal/abi" 14 "internal/profile" 15 "internal/testenv" 16 "io" 17 "math" 18 "math/big" 19 "os" 20 "os/exec" 21 "regexp" 22 "runtime" 23 "runtime/debug" 24 "strings" 25 "sync" 26 "sync/atomic" 27 "testing" 28 "time" 29 _ "unsafe" 30 ) 31 32 func cpuHogger(f func(x int) int, y *int, dur time.Duration) { 33 // We only need to get one 100 Hz clock tick, so we've got 34 // a large safety buffer. 35 // But do at least 500 iterations (which should take about 100ms), 36 // otherwise TestCPUProfileMultithreaded can fail if only one 37 // thread is scheduled during the testing period. 38 t0 := time.Now() 39 accum := *y 40 for i := 0; i < 500 || time.Since(t0) < dur; i++ { 41 accum = f(accum) 42 } 43 *y = accum 44 } 45 46 var ( 47 salt1 = 0 48 salt2 = 0 49 ) 50 51 // The actual CPU hogging function. 52 // Must not call other functions nor access heap/globals in the loop, 53 // otherwise under race detector the samples will be in the race runtime. 54 func cpuHog1(x int) int { 55 return cpuHog0(x, 1e5) 56 } 57 58 func cpuHog0(x, n int) int { 59 foo := x 60 for i := 0; i < n; i++ { 61 if foo > 0 { 62 foo *= foo 63 } else { 64 foo *= foo + 1 65 } 66 } 67 return foo 68 } 69 70 func cpuHog2(x int) int { 71 foo := x 72 for i := 0; i < 1e5; i++ { 73 if foo > 0 { 74 foo *= foo 75 } else { 76 foo *= foo + 2 77 } 78 } 79 return foo 80 } 81 82 // Return a list of functions that we don't want to ever appear in CPU 83 // profiles. For gccgo, that list includes the sigprof handler itself. 84 func avoidFunctions() []string { 85 if runtime.Compiler == "gccgo" { 86 return []string{"runtime.sigprof"} 87 } 88 return nil 89 } 90 91 func TestCPUProfile(t *testing.T) { 92 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions()) 93 testCPUProfile(t, matches, func(dur time.Duration) { 94 cpuHogger(cpuHog1, &salt1, dur) 95 }) 96 } 97 98 func TestCPUProfileMultithreaded(t *testing.T) { 99 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2)) 100 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions()) 101 testCPUProfile(t, matches, func(dur time.Duration) { 102 c := make(chan int) 103 go func() { 104 cpuHogger(cpuHog1, &salt1, dur) 105 c <- 1 106 }() 107 cpuHogger(cpuHog2, &salt2, dur) 108 <-c 109 }) 110 } 111 112 func TestCPUProfileMultithreadMagnitude(t *testing.T) { 113 if runtime.GOOS != "linux" { 114 t.Skip("issue 35057 is only confirmed on Linux") 115 } 116 117 // Linux [5.9,5.16) has a kernel bug that can break CPU timers on newly 118 // created threads, breaking our CPU accounting. 119 major, minor, patch, err := linuxKernelVersion() 120 if err != nil { 121 t.Errorf("Error determining kernel version: %v", err) 122 } 123 t.Logf("Running on Linux %d.%d.%d", major, minor, patch) 124 defer func() { 125 if t.Failed() { 126 t.Logf("Failure of this test may indicate that your system suffers from a known Linux kernel bug fixed on newer kernels. See https://golang.org/issue/49065.") 127 } 128 }() 129 130 // Disable on affected builders to avoid flakiness, but otherwise keep 131 // it enabled to potentially warn users that they are on a broken 132 // kernel. 133 if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") { 134 have59 := major > 5 || (major == 5 && minor >= 9) 135 have516 := major > 5 || (major == 5 && minor >= 16) 136 if have59 && !have516 { 137 testenv.SkipFlaky(t, 49065) 138 } 139 } 140 141 // Run a workload in a single goroutine, then run copies of the same 142 // workload in several goroutines. For both the serial and parallel cases, 143 // the CPU time the process measures with its own profiler should match the 144 // total CPU usage that the OS reports. 145 // 146 // We could also check that increases in parallelism (GOMAXPROCS) lead to a 147 // linear increase in the CPU usage reported by both the OS and the 148 // profiler, but without a guarantee of exclusive access to CPU resources 149 // that is likely to be a flaky test. 150 151 // Require the smaller value to be within 10%, or 40% in short mode. 152 maxDiff := 0.10 153 if testing.Short() { 154 maxDiff = 0.40 155 } 156 157 // This test compares the process's total CPU time against the CPU 158 // profiler's view of time spent in direct execution of user code. 159 // Background work, especially from the garbage collector, adds noise to 160 // that measurement. Disable automatic triggering of the GC, and then 161 // request a complete GC cycle (up through sweep termination). 162 defer debug.SetGCPercent(debug.SetGCPercent(-1)) 163 runtime.GC() 164 165 compare := func(a, b time.Duration, maxDiff float64) error { 166 if a <= 0 || b <= 0 { 167 return fmt.Errorf("Expected both time reports to be positive") 168 } 169 170 if a < b { 171 a, b = b, a 172 } 173 174 diff := float64(a-b) / float64(a) 175 if diff > maxDiff { 176 return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100) 177 } 178 179 return nil 180 } 181 182 for _, tc := range []struct { 183 name string 184 workers int 185 }{ 186 { 187 name: "serial", 188 workers: 1, 189 }, 190 { 191 name: "parallel", 192 workers: runtime.GOMAXPROCS(0), 193 }, 194 } { 195 // check that the OS's perspective matches what the Go runtime measures. 196 t.Run(tc.name, func(t *testing.T) { 197 t.Logf("Running with %d workers", tc.workers) 198 199 var cpuTime time.Duration 200 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions()) 201 p := testCPUProfile(t, matches, func(dur time.Duration) { 202 cpuTime = diffCPUTime(t, func() { 203 var wg sync.WaitGroup 204 var once sync.Once 205 for i := 0; i < tc.workers; i++ { 206 wg.Add(1) 207 go func() { 208 defer wg.Done() 209 var salt = 0 210 cpuHogger(cpuHog1, &salt, dur) 211 once.Do(func() { salt1 = salt }) 212 }() 213 } 214 wg.Wait() 215 }) 216 }) 217 218 for i, unit := range []string{"count", "nanoseconds"} { 219 if have, want := p.SampleType[i].Unit, unit; have != want { 220 t.Errorf("pN SampleType[%d]; %q != %q", i, have, want) 221 } 222 } 223 224 var value time.Duration 225 for _, sample := range p.Sample { 226 if stackContains("runtime/pprof.cpuHog1", uintptr(sample.Value[0]), sample.Location, sample.Label) { 227 value += time.Duration(sample.Value[1]) * time.Nanosecond 228 } 229 } 230 231 t.Logf("compare %s vs %s", cpuTime, value) 232 if err := compare(cpuTime, value, maxDiff); err != nil { 233 t.Errorf("compare got %v want nil", err) 234 } 235 }) 236 } 237 } 238 239 // containsInlinedCall reports whether the function body for the function f is 240 // known to contain an inlined function call within the first maxBytes bytes. 241 func containsInlinedCall(f any, maxBytes int) bool { 242 _, found := findInlinedCall(f, maxBytes) 243 return found 244 } 245 246 // findInlinedCall returns the PC of an inlined function call within 247 // the function body for the function f if any. 248 func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) { 249 fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f))) 250 if fFunc == nil || fFunc.Entry() == 0 { 251 panic("failed to locate function entry") 252 } 253 254 for offset := 0; offset < maxBytes; offset++ { 255 innerPC := fFunc.Entry() + uintptr(offset) 256 inner := runtime.FuncForPC(innerPC) 257 if inner == nil { 258 // No function known for this PC value. 259 // It might simply be misaligned, so keep searching. 260 continue 261 } 262 if inner.Entry() != fFunc.Entry() { 263 // Scanned past f and didn't find any inlined functions. 264 break 265 } 266 if inner.Name() != fFunc.Name() { 267 // This PC has f as its entry-point, but is not f. Therefore, it must be a 268 // function inlined into f. 269 return uint64(innerPC), true 270 } 271 } 272 273 return 0, false 274 } 275 276 func TestCPUProfileInlining(t *testing.T) { 277 if !containsInlinedCall(inlinedCaller, 4<<10) { 278 t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.") 279 } 280 281 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions()) 282 p := testCPUProfile(t, matches, func(dur time.Duration) { 283 cpuHogger(inlinedCaller, &salt1, dur) 284 }) 285 286 // Check if inlined function locations are encoded correctly. The inlinedCalee and inlinedCaller should be in one location. 287 for _, loc := range p.Location { 288 hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false 289 for _, line := range loc.Line { 290 if line.Function.Name == "runtime/pprof.inlinedCallee" { 291 hasInlinedCallee = true 292 } 293 if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" { 294 hasInlinedCallerAfterInlinedCallee = true 295 } 296 } 297 if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee { 298 t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p) 299 } 300 } 301 } 302 303 func inlinedCaller(x int) int { 304 x = inlinedCallee(x, 1e5) 305 return x 306 } 307 308 func inlinedCallee(x, n int) int { 309 return cpuHog0(x, n) 310 } 311 312 //go:noinline 313 func dumpCallers(pcs []uintptr) { 314 if pcs == nil { 315 return 316 } 317 318 skip := 2 // Callers and dumpCallers 319 runtime.Callers(skip, pcs) 320 } 321 322 //go:noinline 323 func inlinedCallerDump(pcs []uintptr) { 324 inlinedCalleeDump(pcs) 325 } 326 327 func inlinedCalleeDump(pcs []uintptr) { 328 dumpCallers(pcs) 329 } 330 331 func TestCPUProfileRecursion(t *testing.T) { 332 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions()) 333 p := testCPUProfile(t, matches, func(dur time.Duration) { 334 cpuHogger(recursionCaller, &salt1, dur) 335 }) 336 337 // check the Location encoding was not confused by recursive calls. 338 for i, loc := range p.Location { 339 recursionFunc := 0 340 for _, line := range loc.Line { 341 if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" { 342 recursionFunc++ 343 } 344 } 345 if recursionFunc > 1 { 346 t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p) 347 } 348 } 349 } 350 351 func recursionCaller(x int) int { 352 y := recursionCallee(3, x) 353 return y 354 } 355 356 func recursionCallee(n, x int) int { 357 if n == 0 { 358 return 1 359 } 360 y := inlinedCallee(x, 1e4) 361 return y * recursionCallee(n-1, x) 362 } 363 364 func recursionChainTop(x int, pcs []uintptr) { 365 if x < 0 { 366 return 367 } 368 recursionChainMiddle(x, pcs) 369 } 370 371 func recursionChainMiddle(x int, pcs []uintptr) { 372 recursionChainBottom(x, pcs) 373 } 374 375 func recursionChainBottom(x int, pcs []uintptr) { 376 // This will be called each time, we only care about the last. We 377 // can't make this conditional or this function won't be inlined. 378 dumpCallers(pcs) 379 380 recursionChainTop(x-1, pcs) 381 } 382 383 func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile { 384 p, err := profile.Parse(bytes.NewReader(valBytes)) 385 if err != nil { 386 t.Fatal(err) 387 } 388 for _, sample := range p.Sample { 389 count := uintptr(sample.Value[0]) 390 f(count, sample.Location, sample.Label) 391 } 392 return p 393 } 394 395 func cpuProfilingBroken() bool { 396 switch runtime.GOOS { 397 case "plan9": 398 // Profiling unimplemented. 399 return true 400 case "aix": 401 // See https://golang.org/issue/45170. 402 return true 403 case "ios", "dragonfly", "netbsd", "illumos", "solaris": 404 // See https://golang.org/issue/13841. 405 return true 406 case "openbsd": 407 if runtime.GOARCH == "arm" || runtime.GOARCH == "arm64" { 408 // See https://golang.org/issue/13841. 409 return true 410 } 411 } 412 413 return false 414 } 415 416 // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need, 417 // as interpreted by matches, and returns the parsed profile. 418 func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile { 419 switch runtime.GOOS { 420 case "darwin": 421 out, err := exec.Command("uname", "-a").CombinedOutput() 422 if err != nil { 423 t.Fatal(err) 424 } 425 vers := string(out) 426 t.Logf("uname -a: %v", vers) 427 case "plan9": 428 t.Skip("skipping on plan9") 429 } 430 431 broken := cpuProfilingBroken() 432 433 maxDuration := 5 * time.Second 434 if testing.Short() && broken { 435 // If it's expected to be broken, no point waiting around. 436 maxDuration /= 10 437 } 438 439 // If we're running a long test, start with a long duration 440 // for tests that try to make sure something *doesn't* happen. 441 duration := 5 * time.Second 442 if testing.Short() { 443 duration = 100 * time.Millisecond 444 } 445 446 // Profiling tests are inherently flaky, especially on a 447 // loaded system, such as when this test is running with 448 // several others under go test std. If a test fails in a way 449 // that could mean it just didn't run long enough, try with a 450 // longer duration. 451 for duration <= maxDuration { 452 var prof bytes.Buffer 453 if err := StartCPUProfile(&prof); err != nil { 454 t.Fatal(err) 455 } 456 f(duration) 457 StopCPUProfile() 458 459 if p, ok := profileOk(t, matches, prof, duration); ok { 460 return p 461 } 462 463 duration *= 2 464 if duration <= maxDuration { 465 t.Logf("retrying with %s duration", duration) 466 } 467 } 468 469 if broken { 470 t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH) 471 } 472 473 // Ignore the failure if the tests are running in a QEMU-based emulator, 474 // QEMU is not perfect at emulating everything. 475 // IN_QEMU environmental variable is set by some of the Go builders. 476 // IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605. 477 if os.Getenv("IN_QEMU") == "1" { 478 t.Skip("ignore the failure in QEMU; see golang.org/issue/9605") 479 } 480 t.FailNow() 481 return nil 482 } 483 484 var diffCPUTimeImpl func(f func()) time.Duration 485 486 func diffCPUTime(t *testing.T, f func()) time.Duration { 487 if fn := diffCPUTimeImpl; fn != nil { 488 return fn(f) 489 } 490 t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH) 491 return 0 492 } 493 494 func contains(slice []string, s string) bool { 495 for i := range slice { 496 if slice[i] == s { 497 return true 498 } 499 } 500 return false 501 } 502 503 // stackContains matches if a function named spec appears anywhere in the stack trace. 504 func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 505 for _, loc := range stk { 506 for _, line := range loc.Line { 507 if strings.Contains(line.Function.Name, spec) { 508 return true 509 } 510 } 511 } 512 return false 513 } 514 515 type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool 516 517 func profileOk(t *testing.T, matches profileMatchFunc, prof bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) { 518 ok = true 519 520 var samples uintptr 521 var buf bytes.Buffer 522 p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) { 523 fmt.Fprintf(&buf, "%d:", count) 524 fprintStack(&buf, stk) 525 fmt.Fprintf(&buf, " labels: %v\n", labels) 526 samples += count 527 fmt.Fprintf(&buf, "\n") 528 }) 529 t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String()) 530 531 if samples < 10 && runtime.GOOS == "windows" { 532 // On some windows machines we end up with 533 // not enough samples due to coarse timer 534 // resolution. Let it go. 535 t.Log("too few samples on Windows (golang.org/issue/10842)") 536 return p, false 537 } 538 539 // Check that we got a reasonable number of samples. 540 // We used to always require at least ideal/4 samples, 541 // but that is too hard to guarantee on a loaded system. 542 // Now we accept 10 or more samples, which we take to be 543 // enough to show that at least some profiling is occurring. 544 if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) { 545 t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal) 546 ok = false 547 } 548 549 if matches != nil && !matches(t, p) { 550 ok = false 551 } 552 553 return p, ok 554 } 555 556 type profileMatchFunc func(*testing.T, *profile.Profile) bool 557 558 func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc { 559 return func(t *testing.T, p *profile.Profile) (ok bool) { 560 ok = true 561 562 // Check that profile is well formed, contains 'need', and does not contain 563 // anything from 'avoid'. 564 have := make([]uintptr, len(need)) 565 avoidSamples := make([]uintptr, len(avoid)) 566 567 for _, sample := range p.Sample { 568 count := uintptr(sample.Value[0]) 569 for i, spec := range need { 570 if matches(spec, count, sample.Location, sample.Label) { 571 have[i] += count 572 } 573 } 574 for i, name := range avoid { 575 for _, loc := range sample.Location { 576 for _, line := range loc.Line { 577 if strings.Contains(line.Function.Name, name) { 578 avoidSamples[i] += count 579 } 580 } 581 } 582 } 583 } 584 585 for i, name := range avoid { 586 bad := avoidSamples[i] 587 if bad != 0 { 588 t.Logf("found %d samples in avoid-function %s\n", bad, name) 589 ok = false 590 } 591 } 592 593 if len(need) == 0 { 594 return 595 } 596 597 var total uintptr 598 for i, name := range need { 599 total += have[i] 600 t.Logf("%s: %d\n", name, have[i]) 601 } 602 if total == 0 { 603 t.Logf("no samples in expected functions") 604 ok = false 605 } 606 607 // We'd like to check a reasonable minimum, like 608 // total / len(have) / smallconstant, but this test is 609 // pretty flaky (see bug 7095). So we'll just test to 610 // make sure we got at least one sample. 611 min := uintptr(1) 612 for i, name := range need { 613 if have[i] < min { 614 t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have))) 615 ok = false 616 } 617 } 618 return 619 } 620 } 621 622 // Fork can hang if preempted with signals frequently enough (see issue 5517). 623 // Ensure that we do not do this. 624 func TestCPUProfileWithFork(t *testing.T) { 625 testenv.MustHaveExec(t) 626 627 heap := 1 << 30 628 if runtime.GOOS == "android" { 629 // Use smaller size for Android to avoid crash. 630 heap = 100 << 20 631 } 632 if runtime.GOOS == "windows" && runtime.GOARCH == "arm" { 633 // Use smaller heap for Windows/ARM to avoid crash. 634 heap = 100 << 20 635 } 636 if testing.Short() { 637 heap = 100 << 20 638 } 639 // This makes fork slower. 640 garbage := make([]byte, heap) 641 // Need to touch the slice, otherwise it won't be paged in. 642 done := make(chan bool) 643 go func() { 644 for i := range garbage { 645 garbage[i] = 42 646 } 647 done <- true 648 }() 649 <-done 650 651 var prof bytes.Buffer 652 if err := StartCPUProfile(&prof); err != nil { 653 t.Fatal(err) 654 } 655 defer StopCPUProfile() 656 657 for i := 0; i < 10; i++ { 658 exec.Command(os.Args[0], "-h").CombinedOutput() 659 } 660 } 661 662 // Test that profiler does not observe runtime.gogo as "user" goroutine execution. 663 // If it did, it would see inconsistent state and would either record an incorrect stack 664 // or crash because the stack was malformed. 665 func TestGoroutineSwitch(t *testing.T) { 666 if runtime.Compiler == "gccgo" { 667 t.Skip("not applicable for gccgo") 668 } 669 // How much to try. These defaults take about 1 seconds 670 // on a 2012 MacBook Pro. The ones in short mode take 671 // about 0.1 seconds. 672 tries := 10 673 count := 1000000 674 if testing.Short() { 675 tries = 1 676 } 677 for try := 0; try < tries; try++ { 678 var prof bytes.Buffer 679 if err := StartCPUProfile(&prof); err != nil { 680 t.Fatal(err) 681 } 682 for i := 0; i < count; i++ { 683 runtime.Gosched() 684 } 685 StopCPUProfile() 686 687 // Read profile to look for entries for gogo with an attempt at a traceback. 688 // "runtime.gogo" is OK, because that's the part of the context switch 689 // before the actual switch begins. But we should not see "gogo", 690 // aka "gogo<>(SB)", which does the actual switch and is marked SPWRITE. 691 parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) { 692 // An entry with two frames with 'System' in its top frame 693 // exists to record a PC without a traceback. Those are okay. 694 if len(stk) == 2 { 695 name := stk[1].Line[0].Function.Name 696 if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" { 697 return 698 } 699 } 700 701 // An entry with just one frame is OK too: 702 // it knew to stop at gogo. 703 if len(stk) == 1 { 704 return 705 } 706 707 // Otherwise, should not see gogo. 708 // The place we'd see it would be the inner most frame. 709 name := stk[0].Line[0].Function.Name 710 if name == "gogo" { 711 var buf bytes.Buffer 712 fprintStack(&buf, stk) 713 t.Fatalf("found profile entry for gogo:\n%s", buf.String()) 714 } 715 }) 716 } 717 } 718 719 func fprintStack(w io.Writer, stk []*profile.Location) { 720 for _, loc := range stk { 721 fmt.Fprintf(w, " %#x", loc.Address) 722 fmt.Fprintf(w, " (") 723 for i, line := range loc.Line { 724 if i > 0 { 725 fmt.Fprintf(w, " ") 726 } 727 fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line) 728 } 729 fmt.Fprintf(w, ")") 730 } 731 } 732 733 // Test that profiling of division operations is okay, especially on ARM. See issue 6681. 734 func TestMathBigDivide(t *testing.T) { 735 testCPUProfile(t, nil, func(duration time.Duration) { 736 t := time.After(duration) 737 pi := new(big.Int) 738 for { 739 for i := 0; i < 100; i++ { 740 n := big.NewInt(2646693125139304345) 741 d := big.NewInt(842468587426513207) 742 pi.Div(n, d) 743 } 744 select { 745 case <-t: 746 return 747 default: 748 } 749 } 750 }) 751 } 752 753 // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace. 754 func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 755 for _, f := range strings.Split(spec, ",") { 756 if !stackContains(f, count, stk, labels) { 757 return false 758 } 759 } 760 return true 761 } 762 763 func TestMorestack(t *testing.T) { 764 matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions()) 765 testCPUProfile(t, matches, func(duration time.Duration) { 766 t := time.After(duration) 767 c := make(chan bool) 768 for { 769 go func() { 770 growstack1() 771 c <- true 772 }() 773 select { 774 case <-t: 775 return 776 case <-c: 777 } 778 } 779 }) 780 } 781 782 //go:noinline 783 func growstack1() { 784 growstack(10) 785 } 786 787 //go:noinline 788 func growstack(n int) { 789 var buf [8 << 18]byte 790 use(buf) 791 if n > 0 { 792 growstack(n - 1) 793 } 794 } 795 796 //go:noinline 797 func use(x [8 << 18]byte) {} 798 799 func TestBlockProfile(t *testing.T) { 800 type TestCase struct { 801 name string 802 f func() 803 stk []string 804 re string 805 } 806 tests := [...]TestCase{ 807 { 808 name: "chan recv", 809 f: blockChanRecv, 810 stk: []string{ 811 "runtime.chanrecv1", 812 "runtime/pprof.blockChanRecv", 813 "runtime/pprof.TestBlockProfile", 814 }, 815 re: ` 816 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 817 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 818 # 0x[0-9a-f]+ runtime/pprof\.blockChanRecv\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 819 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 820 `}, 821 { 822 name: "chan send", 823 f: blockChanSend, 824 stk: []string{ 825 "runtime.chansend1", 826 "runtime/pprof.blockChanSend", 827 "runtime/pprof.TestBlockProfile", 828 }, 829 re: ` 830 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 831 # 0x[0-9a-f]+ runtime\.chansend1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 832 # 0x[0-9a-f]+ runtime/pprof\.blockChanSend\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 833 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 834 `}, 835 { 836 name: "chan close", 837 f: blockChanClose, 838 stk: []string{ 839 "runtime.chanrecv1", 840 "runtime/pprof.blockChanClose", 841 "runtime/pprof.TestBlockProfile", 842 }, 843 re: ` 844 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 845 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*/src/runtime/chan.go:[0-9]+ 846 # 0x[0-9a-f]+ runtime/pprof\.blockChanClose\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 847 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 848 `}, 849 { 850 name: "select recv async", 851 f: blockSelectRecvAsync, 852 stk: []string{ 853 "runtime.selectgo", 854 "runtime/pprof.blockSelectRecvAsync", 855 "runtime/pprof.TestBlockProfile", 856 }, 857 re: ` 858 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 859 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*/src/runtime/select.go:[0-9]+ 860 # 0x[0-9a-f]+ runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 861 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 862 `}, 863 { 864 name: "select send sync", 865 f: blockSelectSendSync, 866 stk: []string{ 867 "runtime.selectgo", 868 "runtime/pprof.blockSelectSendSync", 869 "runtime/pprof.TestBlockProfile", 870 }, 871 re: ` 872 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 873 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*/src/runtime/select.go:[0-9]+ 874 # 0x[0-9a-f]+ runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 875 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 876 `}, 877 { 878 name: "mutex", 879 f: blockMutex, 880 stk: []string{ 881 "sync.(*Mutex).Lock", 882 "runtime/pprof.blockMutex", 883 "runtime/pprof.TestBlockProfile", 884 }, 885 re: ` 886 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 887 # 0x[0-9a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+ .*/src/sync/mutex\.go:[0-9]+ 888 # 0x[0-9a-f]+ runtime/pprof\.blockMutex\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 889 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 890 `}, 891 { 892 name: "cond", 893 f: blockCond, 894 stk: []string{ 895 "sync.(*Cond).Wait", 896 "runtime/pprof.blockCond", 897 "runtime/pprof.TestBlockProfile", 898 }, 899 re: ` 900 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 901 # 0x[0-9a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+ .*/src/sync/cond\.go:[0-9]+ 902 # 0x[0-9a-f]+ runtime/pprof\.blockCond\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 903 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+ 904 `}, 905 } 906 907 // Generate block profile 908 runtime.SetBlockProfileRate(1) 909 defer runtime.SetBlockProfileRate(0) 910 for _, test := range tests { 911 test.f() 912 } 913 914 t.Run("debug=1", func(t *testing.T) { 915 var w bytes.Buffer 916 Lookup("block").WriteTo(&w, 1) 917 prof := w.String() 918 919 if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") { 920 t.Fatalf("Bad profile header:\n%v", prof) 921 } 922 923 if strings.HasSuffix(prof, "#\t0x0\n\n") { 924 t.Errorf("Useless 0 suffix:\n%v", prof) 925 } 926 927 for _, test := range tests { 928 if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) { 929 t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof) 930 } 931 } 932 }) 933 934 t.Run("proto", func(t *testing.T) { 935 // proto format 936 var w bytes.Buffer 937 Lookup("block").WriteTo(&w, 0) 938 p, err := profile.Parse(&w) 939 if err != nil { 940 t.Fatalf("failed to parse profile: %v", err) 941 } 942 t.Logf("parsed proto: %s", p) 943 if err := p.CheckValid(); err != nil { 944 t.Fatalf("invalid profile: %v", err) 945 } 946 947 stks := stacks(p) 948 for _, test := range tests { 949 if !containsStack(stks, test.stk) { 950 t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk) 951 } 952 } 953 }) 954 955 } 956 957 func stacks(p *profile.Profile) (res [][]string) { 958 for _, s := range p.Sample { 959 var stk []string 960 for _, l := range s.Location { 961 for _, line := range l.Line { 962 stk = append(stk, line.Function.Name) 963 } 964 } 965 res = append(res, stk) 966 } 967 return res 968 } 969 970 func containsStack(got [][]string, want []string) bool { 971 for _, stk := range got { 972 if len(stk) < len(want) { 973 continue 974 } 975 for i, f := range want { 976 if f != stk[i] { 977 break 978 } 979 if i == len(want)-1 { 980 return true 981 } 982 } 983 } 984 return false 985 } 986 987 const blockDelay = 10 * time.Millisecond 988 989 func blockChanRecv() { 990 c := make(chan bool) 991 go func() { 992 time.Sleep(blockDelay) 993 c <- true 994 }() 995 <-c 996 } 997 998 func blockChanSend() { 999 c := make(chan bool) 1000 go func() { 1001 time.Sleep(blockDelay) 1002 <-c 1003 }() 1004 c <- true 1005 } 1006 1007 func blockChanClose() { 1008 c := make(chan bool) 1009 go func() { 1010 time.Sleep(blockDelay) 1011 close(c) 1012 }() 1013 <-c 1014 } 1015 1016 func blockSelectRecvAsync() { 1017 const numTries = 3 1018 c := make(chan bool, 1) 1019 c2 := make(chan bool, 1) 1020 go func() { 1021 for i := 0; i < numTries; i++ { 1022 time.Sleep(blockDelay) 1023 c <- true 1024 } 1025 }() 1026 for i := 0; i < numTries; i++ { 1027 select { 1028 case <-c: 1029 case <-c2: 1030 } 1031 } 1032 } 1033 1034 func blockSelectSendSync() { 1035 c := make(chan bool) 1036 c2 := make(chan bool) 1037 go func() { 1038 time.Sleep(blockDelay) 1039 <-c 1040 }() 1041 select { 1042 case c <- true: 1043 case c2 <- true: 1044 } 1045 } 1046 1047 func blockMutex() { 1048 var mu sync.Mutex 1049 mu.Lock() 1050 go func() { 1051 time.Sleep(blockDelay) 1052 mu.Unlock() 1053 }() 1054 // Note: Unlock releases mu before recording the mutex event, 1055 // so it's theoretically possible for this to proceed and 1056 // capture the profile before the event is recorded. As long 1057 // as this is blocked before the unlock happens, it's okay. 1058 mu.Lock() 1059 } 1060 1061 func blockCond() { 1062 var mu sync.Mutex 1063 c := sync.NewCond(&mu) 1064 mu.Lock() 1065 go func() { 1066 time.Sleep(blockDelay) 1067 mu.Lock() 1068 c.Signal() 1069 mu.Unlock() 1070 }() 1071 c.Wait() 1072 mu.Unlock() 1073 } 1074 1075 // See http://golang.org/cl/299991. 1076 func TestBlockProfileBias(t *testing.T) { 1077 rate := int(1000) // arbitrary value 1078 runtime.SetBlockProfileRate(rate) 1079 defer runtime.SetBlockProfileRate(0) 1080 1081 // simulate blocking events 1082 blockFrequentShort(rate) 1083 blockInfrequentLong(rate) 1084 1085 var w bytes.Buffer 1086 Lookup("block").WriteTo(&w, 0) 1087 p, err := profile.Parse(&w) 1088 if err != nil { 1089 t.Fatalf("failed to parse profile: %v", err) 1090 } 1091 t.Logf("parsed proto: %s", p) 1092 1093 il := float64(-1) // blockInfrequentLong duration 1094 fs := float64(-1) // blockFrequentShort duration 1095 for _, s := range p.Sample { 1096 for _, l := range s.Location { 1097 for _, line := range l.Line { 1098 if len(s.Value) < 2 { 1099 t.Fatal("block profile has less than 2 sample types") 1100 } 1101 1102 if line.Function.Name == "runtime/pprof.blockInfrequentLong" { 1103 il = float64(s.Value[1]) 1104 } else if line.Function.Name == "runtime/pprof.blockFrequentShort" { 1105 fs = float64(s.Value[1]) 1106 } 1107 } 1108 } 1109 } 1110 if il == -1 || fs == -1 { 1111 t.Fatal("block profile is missing expected functions") 1112 } 1113 1114 // stddev of bias from 100 runs on local machine multiplied by 10x 1115 const threshold = 0.2 1116 if bias := (il - fs) / il; math.Abs(bias) > threshold { 1117 t.Fatalf("bias: abs(%f) > %f", bias, threshold) 1118 } else { 1119 t.Logf("bias: abs(%f) < %f", bias, threshold) 1120 } 1121 } 1122 1123 // blockFrequentShort produces 100000 block events with an average duration of 1124 // rate / 10. 1125 func blockFrequentShort(rate int) { 1126 for i := 0; i < 100000; i++ { 1127 blockevent(int64(rate/10), 1) 1128 } 1129 } 1130 1131 // blockFrequentShort produces 10000 block events with an average duration of 1132 // rate. 1133 func blockInfrequentLong(rate int) { 1134 for i := 0; i < 10000; i++ { 1135 blockevent(int64(rate), 1) 1136 } 1137 } 1138 1139 // Used by TestBlockProfileBias. 1140 //go:linkname blockevent runtime.blockevent 1141 func blockevent(cycles int64, skip int) 1142 1143 func TestMutexProfile(t *testing.T) { 1144 // Generate mutex profile 1145 1146 old := runtime.SetMutexProfileFraction(1) 1147 defer runtime.SetMutexProfileFraction(old) 1148 if old != 0 { 1149 t.Fatalf("need MutexProfileRate 0, got %d", old) 1150 } 1151 1152 blockMutex() 1153 1154 t.Run("debug=1", func(t *testing.T) { 1155 var w bytes.Buffer 1156 Lookup("mutex").WriteTo(&w, 1) 1157 prof := w.String() 1158 t.Logf("received profile: %v", prof) 1159 1160 if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") { 1161 t.Errorf("Bad profile header:\n%v", prof) 1162 } 1163 prof = strings.Trim(prof, "\n") 1164 lines := strings.Split(prof, "\n") 1165 if len(lines) != 6 { 1166 t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof) 1167 } 1168 if len(lines) < 6 { 1169 return 1170 } 1171 // checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931" 1172 r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+` 1173 //r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$" 1174 if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok { 1175 t.Errorf("%q didn't match %q", lines[3], r2) 1176 } 1177 r3 := "^#.*runtime/pprof.blockMutex.*$" 1178 if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok { 1179 t.Errorf("%q didn't match %q", lines[5], r3) 1180 } 1181 t.Logf(prof) 1182 }) 1183 t.Run("proto", func(t *testing.T) { 1184 // proto format 1185 var w bytes.Buffer 1186 Lookup("mutex").WriteTo(&w, 0) 1187 p, err := profile.Parse(&w) 1188 if err != nil { 1189 t.Fatalf("failed to parse profile: %v", err) 1190 } 1191 t.Logf("parsed proto: %s", p) 1192 if err := p.CheckValid(); err != nil { 1193 t.Fatalf("invalid profile: %v", err) 1194 } 1195 1196 stks := stacks(p) 1197 for _, want := range [][]string{ 1198 {"sync.(*Mutex).Unlock", "runtime/pprof.blockMutex.func1"}, 1199 } { 1200 if !containsStack(stks, want) { 1201 t.Errorf("No matching stack entry for %+v", want) 1202 } 1203 } 1204 }) 1205 } 1206 1207 func func1(c chan int) { <-c } 1208 func func2(c chan int) { <-c } 1209 func func3(c chan int) { <-c } 1210 func func4(c chan int) { <-c } 1211 1212 func TestGoroutineCounts(t *testing.T) { 1213 // Setting GOMAXPROCS to 1 ensures we can force all goroutines to the 1214 // desired blocking point. 1215 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1)) 1216 1217 c := make(chan int) 1218 for i := 0; i < 100; i++ { 1219 switch { 1220 case i%10 == 0: 1221 go func1(c) 1222 case i%2 == 0: 1223 go func2(c) 1224 default: 1225 go func3(c) 1226 } 1227 // Let goroutines block on channel 1228 for j := 0; j < 5; j++ { 1229 runtime.Gosched() 1230 } 1231 } 1232 ctx := context.Background() 1233 1234 // ... and again, with labels this time (just with fewer iterations to keep 1235 // sorting deterministic). 1236 Do(ctx, Labels("label", "value"), func(context.Context) { 1237 for i := 0; i < 89; i++ { 1238 switch { 1239 case i%10 == 0: 1240 go func1(c) 1241 case i%2 == 0: 1242 go func2(c) 1243 default: 1244 go func3(c) 1245 } 1246 // Let goroutines block on channel 1247 for j := 0; j < 5; j++ { 1248 runtime.Gosched() 1249 } 1250 } 1251 }) 1252 1253 var w bytes.Buffer 1254 goroutineProf := Lookup("goroutine") 1255 1256 // Check debug profile 1257 goroutineProf.WriteTo(&w, 1) 1258 prof := w.String() 1259 1260 labels := labelMap{"label": "value"} 1261 labelStr := "\n# labels: " + labels.String() 1262 if !containsInOrder(prof, "\n50 @ ", "\n44 @", labelStr, 1263 "\n40 @", "\n36 @", labelStr, "\n10 @", "\n9 @", labelStr, "\n1 @") { 1264 t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof) 1265 } 1266 1267 // Check proto profile 1268 w.Reset() 1269 goroutineProf.WriteTo(&w, 0) 1270 p, err := profile.Parse(&w) 1271 if err != nil { 1272 t.Errorf("error parsing protobuf profile: %v", err) 1273 } 1274 if err := p.CheckValid(); err != nil { 1275 t.Errorf("protobuf profile is invalid: %v", err) 1276 } 1277 expectedLabels := map[int64]map[string]string{ 1278 50: map[string]string{}, 1279 44: map[string]string{"label": "value"}, 1280 40: map[string]string{}, 1281 36: map[string]string{"label": "value"}, 1282 10: map[string]string{}, 1283 9: map[string]string{"label": "value"}, 1284 1: map[string]string{}, 1285 } 1286 if !containsCountsLabels(p, expectedLabels) { 1287 t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v", 1288 expectedLabels, p) 1289 } 1290 1291 close(c) 1292 1293 time.Sleep(10 * time.Millisecond) // let goroutines exit 1294 } 1295 1296 func containsInOrder(s string, all ...string) bool { 1297 for _, t := range all { 1298 var ok bool 1299 if _, s, ok = strings.Cut(s, t); !ok { 1300 return false 1301 } 1302 } 1303 return true 1304 } 1305 1306 func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool { 1307 m := make(map[int64]int) 1308 type nkey struct { 1309 count int64 1310 key, val string 1311 } 1312 n := make(map[nkey]int) 1313 for c, kv := range countLabels { 1314 m[c]++ 1315 for k, v := range kv { 1316 n[nkey{ 1317 count: c, 1318 key: k, 1319 val: v, 1320 }]++ 1321 1322 } 1323 } 1324 for _, s := range prof.Sample { 1325 // The count is the single value in the sample 1326 if len(s.Value) != 1 { 1327 return false 1328 } 1329 m[s.Value[0]]-- 1330 for k, vs := range s.Label { 1331 for _, v := range vs { 1332 n[nkey{ 1333 count: s.Value[0], 1334 key: k, 1335 val: v, 1336 }]-- 1337 } 1338 } 1339 } 1340 for _, n := range m { 1341 if n > 0 { 1342 return false 1343 } 1344 } 1345 for _, ncnt := range n { 1346 if ncnt != 0 { 1347 return false 1348 } 1349 } 1350 return true 1351 } 1352 1353 var emptyCallStackTestRun int64 1354 1355 // Issue 18836. 1356 func TestEmptyCallStack(t *testing.T) { 1357 name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun) 1358 emptyCallStackTestRun++ 1359 1360 t.Parallel() 1361 var buf bytes.Buffer 1362 p := NewProfile(name) 1363 1364 p.Add("foo", 47674) 1365 p.WriteTo(&buf, 1) 1366 p.Remove("foo") 1367 got := buf.String() 1368 prefix := name + " profile: total 1\n" 1369 if !strings.HasPrefix(got, prefix) { 1370 t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix) 1371 } 1372 lostevent := "lostProfileEvent" 1373 if !strings.Contains(got, lostevent) { 1374 t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent) 1375 } 1376 } 1377 1378 // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key 1379 // and value and has funcname somewhere in the stack. 1380 func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 1381 base, kv, ok := strings.Cut(spec, ";") 1382 if !ok { 1383 panic("no semicolon in key/value spec") 1384 } 1385 k, v, ok := strings.Cut(kv, "=") 1386 if !ok { 1387 panic("missing = in key/value spec") 1388 } 1389 if !contains(labels[k], v) { 1390 return false 1391 } 1392 return stackContains(base, count, stk, labels) 1393 } 1394 1395 func TestCPUProfileLabel(t *testing.T) { 1396 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions()) 1397 testCPUProfile(t, matches, func(dur time.Duration) { 1398 Do(context.Background(), Labels("key", "value"), func(context.Context) { 1399 cpuHogger(cpuHog1, &salt1, dur) 1400 }) 1401 }) 1402 } 1403 1404 func TestLabelRace(t *testing.T) { 1405 // Test the race detector annotations for synchronization 1406 // between settings labels and consuming them from the 1407 // profile. 1408 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil) 1409 testCPUProfile(t, matches, func(dur time.Duration) { 1410 start := time.Now() 1411 var wg sync.WaitGroup 1412 for time.Since(start) < dur { 1413 var salts [10]int 1414 for i := 0; i < 10; i++ { 1415 wg.Add(1) 1416 go func(j int) { 1417 Do(context.Background(), Labels("key", "value"), func(context.Context) { 1418 cpuHogger(cpuHog1, &salts[j], time.Millisecond) 1419 }) 1420 wg.Done() 1421 }(i) 1422 } 1423 wg.Wait() 1424 } 1425 }) 1426 } 1427 1428 // TestLabelSystemstack makes sure CPU profiler samples of goroutines running 1429 // on systemstack include the correct pprof labels. See issue #48577 1430 func TestLabelSystemstack(t *testing.T) { 1431 // Grab and re-set the initial value before continuing to ensure 1432 // GOGC doesn't actually change following the test. 1433 gogc := debug.SetGCPercent(100) 1434 debug.SetGCPercent(gogc) 1435 1436 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions()) 1437 p := testCPUProfile(t, matches, func(dur time.Duration) { 1438 Do(context.Background(), Labels("key", "value"), func(context.Context) { 1439 var wg sync.WaitGroup 1440 stop := make(chan struct{}) 1441 for i := 0; i < runtime.GOMAXPROCS(0); i++ { 1442 wg.Add(1) 1443 go func() { 1444 defer wg.Done() 1445 labelHog(stop, gogc) 1446 }() 1447 } 1448 1449 time.Sleep(dur) 1450 close(stop) 1451 wg.Wait() 1452 }) 1453 }) 1454 1455 // labelHog should always be labeled. 1456 for _, s := range p.Sample { 1457 for _, loc := range s.Location { 1458 for _, l := range loc.Line { 1459 if l.Function.Name != "runtime/pprof.labelHog" { 1460 continue 1461 } 1462 1463 if s.Label == nil { 1464 t.Errorf("labelHog sample labels got nil want key=value") 1465 continue 1466 } 1467 if !contains(s.Label["key"], "value") { 1468 t.Errorf("labelHog sample labels got %+v want contains key=value", s.Label) 1469 continue 1470 } 1471 } 1472 } 1473 } 1474 } 1475 1476 // labelHog is designed to burn CPU time in a way that a high number of CPU 1477 // samples end up running on systemstack. 1478 func labelHog(stop chan struct{}, gogc int) { 1479 for i := 0; ; i++ { 1480 select { 1481 case <-stop: 1482 return 1483 default: 1484 debug.SetGCPercent(gogc) 1485 } 1486 } 1487 } 1488 1489 // Check that there is no deadlock when the program receives SIGPROF while in 1490 // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146. 1491 func TestAtomicLoadStore64(t *testing.T) { 1492 f, err := os.CreateTemp("", "profatomic") 1493 if err != nil { 1494 t.Fatalf("TempFile: %v", err) 1495 } 1496 defer os.Remove(f.Name()) 1497 defer f.Close() 1498 1499 if err := StartCPUProfile(f); err != nil { 1500 t.Fatal(err) 1501 } 1502 defer StopCPUProfile() 1503 1504 var flag uint64 1505 done := make(chan bool, 1) 1506 1507 go func() { 1508 for atomic.LoadUint64(&flag) == 0 { 1509 runtime.Gosched() 1510 } 1511 done <- true 1512 }() 1513 time.Sleep(50 * time.Millisecond) 1514 atomic.StoreUint64(&flag, 1) 1515 <-done 1516 } 1517 1518 func TestTracebackAll(t *testing.T) { 1519 // With gccgo, if a profiling signal arrives at the wrong time 1520 // during traceback, it may crash or hang. See issue #29448. 1521 f, err := os.CreateTemp("", "proftraceback") 1522 if err != nil { 1523 t.Fatalf("TempFile: %v", err) 1524 } 1525 defer os.Remove(f.Name()) 1526 defer f.Close() 1527 1528 if err := StartCPUProfile(f); err != nil { 1529 t.Fatal(err) 1530 } 1531 defer StopCPUProfile() 1532 1533 ch := make(chan int) 1534 defer close(ch) 1535 1536 count := 10 1537 for i := 0; i < count; i++ { 1538 go func() { 1539 <-ch // block 1540 }() 1541 } 1542 1543 N := 10000 1544 if testing.Short() { 1545 N = 500 1546 } 1547 buf := make([]byte, 10*1024) 1548 for i := 0; i < N; i++ { 1549 runtime.Stack(buf, true) 1550 } 1551 } 1552 1553 // TestTryAdd tests the cases that are hard to test with real program execution. 1554 // 1555 // For example, the current go compilers may not always inline functions 1556 // involved in recursion but that may not be true in the future compilers. This 1557 // tests such cases by using fake call sequences and forcing the profile build 1558 // utilizing translateCPUProfile defined in proto_test.go 1559 func TestTryAdd(t *testing.T) { 1560 if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found { 1561 t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.") 1562 } 1563 1564 // inlinedCallerDump 1565 // inlinedCalleeDump 1566 pcs := make([]uintptr, 2) 1567 inlinedCallerDump(pcs) 1568 inlinedCallerStack := make([]uint64, 2) 1569 for i := range pcs { 1570 inlinedCallerStack[i] = uint64(pcs[i]) 1571 } 1572 1573 if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found { 1574 t.Skip("Can't determine whether anything was inlined into recursionChainBottom.") 1575 } 1576 1577 // recursionChainTop 1578 // recursionChainMiddle 1579 // recursionChainBottom 1580 // recursionChainTop 1581 // recursionChainMiddle 1582 // recursionChainBottom 1583 pcs = make([]uintptr, 6) 1584 recursionChainTop(1, pcs) 1585 recursionStack := make([]uint64, len(pcs)) 1586 for i := range pcs { 1587 recursionStack[i] = uint64(pcs[i]) 1588 } 1589 1590 period := int64(2000 * 1000) // 1/500*1e9 nanosec. 1591 1592 testCases := []struct { 1593 name string 1594 input []uint64 // following the input format assumed by profileBuilder.addCPUData. 1595 count int // number of records in input. 1596 wantLocs [][]string // ordered location entries with function names. 1597 wantSamples []*profile.Sample // ordered samples, we care only about Value and the profile location IDs. 1598 }{{ 1599 // Sanity test for a normal, complete stack trace. 1600 name: "full_stack_trace", 1601 input: []uint64{ 1602 3, 0, 500, // hz = 500. Must match the period. 1603 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1], 1604 }, 1605 count: 2, 1606 wantLocs: [][]string{ 1607 {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}, 1608 }, 1609 wantSamples: []*profile.Sample{ 1610 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}}, 1611 }, 1612 }, { 1613 name: "bug35538", 1614 input: []uint64{ 1615 3, 0, 500, // hz = 500. Must match the period. 1616 // Fake frame: tryAdd will have inlinedCallerDump 1617 // (stack[1]) on the deck when it encounters the next 1618 // inline function. It should accept this. 1619 7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1], 1620 5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1], 1621 }, 1622 count: 3, 1623 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 1624 wantSamples: []*profile.Sample{ 1625 {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}}, 1626 {Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}}, 1627 }, 1628 }, { 1629 name: "bug38096", 1630 input: []uint64{ 1631 3, 0, 500, // hz = 500. Must match the period. 1632 // count (data[2]) == 0 && len(stk) == 1 is an overflow 1633 // entry. The "stk" entry is actually the count. 1634 4, 0, 0, 4242, 1635 }, 1636 count: 2, 1637 wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}}, 1638 wantSamples: []*profile.Sample{ 1639 {Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}}, 1640 }, 1641 }, { 1642 // If a function is directly called recursively then it must 1643 // not be inlined in the caller. 1644 // 1645 // N.B. We're generating an impossible profile here, with a 1646 // recursive inlineCalleeDump call. This is simulating a non-Go 1647 // function that looks like an inlined Go function other than 1648 // its recursive property. See pcDeck.tryAdd. 1649 name: "directly_recursive_func_is_not_inlined", 1650 input: []uint64{ 1651 3, 0, 500, // hz = 500. Must match the period. 1652 5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0], 1653 4, 0, 40, inlinedCallerStack[0], 1654 }, 1655 count: 3, 1656 // inlinedCallerDump shows up here because 1657 // runtime_expandFinalInlineFrame adds it to the stack frame. 1658 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}}, 1659 wantSamples: []*profile.Sample{ 1660 {Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}}, 1661 {Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}}, 1662 }, 1663 }, { 1664 name: "recursion_chain_inline", 1665 input: []uint64{ 1666 3, 0, 500, // hz = 500. Must match the period. 1667 9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5], 1668 }, 1669 count: 2, 1670 wantLocs: [][]string{ 1671 {"runtime/pprof.recursionChainBottom"}, 1672 { 1673 "runtime/pprof.recursionChainMiddle", 1674 "runtime/pprof.recursionChainTop", 1675 "runtime/pprof.recursionChainBottom", 1676 }, 1677 { 1678 "runtime/pprof.recursionChainMiddle", 1679 "runtime/pprof.recursionChainTop", 1680 "runtime/pprof.TestTryAdd", // inlined into the test. 1681 }, 1682 }, 1683 wantSamples: []*profile.Sample{ 1684 {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}}, 1685 }, 1686 }, { 1687 name: "truncated_stack_trace_later", 1688 input: []uint64{ 1689 3, 0, 500, // hz = 500. Must match the period. 1690 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1], 1691 4, 0, 60, inlinedCallerStack[0], 1692 }, 1693 count: 3, 1694 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 1695 wantSamples: []*profile.Sample{ 1696 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}}, 1697 {Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}}, 1698 }, 1699 }, { 1700 name: "truncated_stack_trace_first", 1701 input: []uint64{ 1702 3, 0, 500, // hz = 500. Must match the period. 1703 4, 0, 70, inlinedCallerStack[0], 1704 5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1], 1705 }, 1706 count: 3, 1707 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 1708 wantSamples: []*profile.Sample{ 1709 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}}, 1710 {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}}, 1711 }, 1712 }, { 1713 // We can recover the inlined caller from a truncated stack. 1714 name: "truncated_stack_trace_only", 1715 input: []uint64{ 1716 3, 0, 500, // hz = 500. Must match the period. 1717 4, 0, 70, inlinedCallerStack[0], 1718 }, 1719 count: 2, 1720 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 1721 wantSamples: []*profile.Sample{ 1722 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}}, 1723 }, 1724 }, { 1725 // The same location is used for duplicated stacks. 1726 name: "truncated_stack_trace_twice", 1727 input: []uint64{ 1728 3, 0, 500, // hz = 500. Must match the period. 1729 4, 0, 70, inlinedCallerStack[0], 1730 // Fake frame: add a fake call to 1731 // inlinedCallerDump to prevent this sample 1732 // from getting merged into above. 1733 5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0], 1734 }, 1735 count: 3, 1736 wantLocs: [][]string{ 1737 {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}, 1738 {"runtime/pprof.inlinedCallerDump"}, 1739 }, 1740 wantSamples: []*profile.Sample{ 1741 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}}, 1742 {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}}, 1743 }, 1744 }} 1745 1746 for _, tc := range testCases { 1747 t.Run(tc.name, func(t *testing.T) { 1748 p, err := translateCPUProfile(tc.input, tc.count) 1749 if err != nil { 1750 t.Fatalf("translating profile: %v", err) 1751 } 1752 t.Logf("Profile: %v\n", p) 1753 1754 // One location entry with all inlined functions. 1755 var gotLoc [][]string 1756 for _, loc := range p.Location { 1757 var names []string 1758 for _, line := range loc.Line { 1759 names = append(names, line.Function.Name) 1760 } 1761 gotLoc = append(gotLoc, names) 1762 } 1763 if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want { 1764 t.Errorf("Got Location = %+v\n\twant %+v", got, want) 1765 } 1766 // All samples should point to one location. 1767 var gotSamples []*profile.Sample 1768 for _, sample := range p.Sample { 1769 var locs []*profile.Location 1770 for _, loc := range sample.Location { 1771 locs = append(locs, &profile.Location{ID: loc.ID}) 1772 } 1773 gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs}) 1774 } 1775 if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want { 1776 t.Errorf("Got Samples = %+v\n\twant %+v", got, want) 1777 } 1778 }) 1779 } 1780 } 1781 1782 func TestTimeVDSO(t *testing.T) { 1783 // Test that time functions have the right stack trace. In particular, 1784 // it shouldn't be recursive. 1785 1786 if runtime.GOOS == "android" { 1787 // Flaky on Android, issue 48655. VDSO may not be enabled. 1788 testenv.SkipFlaky(t, 48655) 1789 } 1790 1791 matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions()) 1792 p := testCPUProfile(t, matches, func(dur time.Duration) { 1793 t0 := time.Now() 1794 for { 1795 t := time.Now() 1796 if t.Sub(t0) >= dur { 1797 return 1798 } 1799 } 1800 }) 1801 1802 // Check for recursive time.now sample. 1803 for _, sample := range p.Sample { 1804 var seenNow bool 1805 for _, loc := range sample.Location { 1806 for _, line := range loc.Line { 1807 if line.Function.Name == "time.now" { 1808 if seenNow { 1809 t.Fatalf("unexpected recursive time.now") 1810 } 1811 seenNow = true 1812 } 1813 } 1814 } 1815 } 1816 }