github.com/twelsh-aw/go/src@v0.0.0-20230516233729-a56fe86a7c81/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/syscall/unix" 16 "internal/testenv" 17 "io" 18 "math" 19 "math/big" 20 "os" 21 "os/exec" 22 "regexp" 23 "runtime" 24 "runtime/debug" 25 "strings" 26 "sync" 27 "sync/atomic" 28 "testing" 29 "time" 30 _ "unsafe" 31 ) 32 33 func cpuHogger(f func(x int) int, y *int, dur time.Duration) { 34 // We only need to get one 100 Hz clock tick, so we've got 35 // a large safety buffer. 36 // But do at least 500 iterations (which should take about 100ms), 37 // otherwise TestCPUProfileMultithreaded can fail if only one 38 // thread is scheduled during the testing period. 39 t0 := time.Now() 40 accum := *y 41 for i := 0; i < 500 || time.Since(t0) < dur; i++ { 42 accum = f(accum) 43 } 44 *y = accum 45 } 46 47 var ( 48 salt1 = 0 49 salt2 = 0 50 ) 51 52 // The actual CPU hogging function. 53 // Must not call other functions nor access heap/globals in the loop, 54 // otherwise under race detector the samples will be in the race runtime. 55 func cpuHog1(x int) int { 56 return cpuHog0(x, 1e5) 57 } 58 59 func cpuHog0(x, n int) int { 60 foo := x 61 for i := 0; i < n; i++ { 62 if foo > 0 { 63 foo *= foo 64 } else { 65 foo *= foo + 1 66 } 67 } 68 return foo 69 } 70 71 func cpuHog2(x int) int { 72 foo := x 73 for i := 0; i < 1e5; i++ { 74 if foo > 0 { 75 foo *= foo 76 } else { 77 foo *= foo + 2 78 } 79 } 80 return foo 81 } 82 83 // Return a list of functions that we don't want to ever appear in CPU 84 // profiles. For gccgo, that list includes the sigprof handler itself. 85 func avoidFunctions() []string { 86 if runtime.Compiler == "gccgo" { 87 return []string{"runtime.sigprof"} 88 } 89 return nil 90 } 91 92 func TestCPUProfile(t *testing.T) { 93 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions()) 94 testCPUProfile(t, matches, func(dur time.Duration) { 95 cpuHogger(cpuHog1, &salt1, dur) 96 }) 97 } 98 99 func TestCPUProfileMultithreaded(t *testing.T) { 100 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2)) 101 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions()) 102 testCPUProfile(t, matches, func(dur time.Duration) { 103 c := make(chan int) 104 go func() { 105 cpuHogger(cpuHog1, &salt1, dur) 106 c <- 1 107 }() 108 cpuHogger(cpuHog2, &salt2, dur) 109 <-c 110 }) 111 } 112 113 func TestCPUProfileMultithreadMagnitude(t *testing.T) { 114 if runtime.GOOS != "linux" { 115 t.Skip("issue 35057 is only confirmed on Linux") 116 } 117 118 // Linux [5.9,5.16) has a kernel bug that can break CPU timers on newly 119 // created threads, breaking our CPU accounting. 120 major, minor := unix.KernelVersion() 121 t.Logf("Running on Linux %d.%d", major, minor) 122 defer func() { 123 if t.Failed() { 124 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.") 125 } 126 }() 127 128 // Disable on affected builders to avoid flakiness, but otherwise keep 129 // it enabled to potentially warn users that they are on a broken 130 // kernel. 131 if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") { 132 have59 := major > 5 || (major == 5 && minor >= 9) 133 have516 := major > 5 || (major == 5 && minor >= 16) 134 if have59 && !have516 { 135 testenv.SkipFlaky(t, 49065) 136 } 137 } 138 139 // Run a workload in a single goroutine, then run copies of the same 140 // workload in several goroutines. For both the serial and parallel cases, 141 // the CPU time the process measures with its own profiler should match the 142 // total CPU usage that the OS reports. 143 // 144 // We could also check that increases in parallelism (GOMAXPROCS) lead to a 145 // linear increase in the CPU usage reported by both the OS and the 146 // profiler, but without a guarantee of exclusive access to CPU resources 147 // that is likely to be a flaky test. 148 149 // Require the smaller value to be within 10%, or 40% in short mode. 150 maxDiff := 0.10 151 if testing.Short() { 152 maxDiff = 0.40 153 } 154 155 compare := func(a, b time.Duration, maxDiff float64) error { 156 if a <= 0 || b <= 0 { 157 return fmt.Errorf("Expected both time reports to be positive") 158 } 159 160 if a < b { 161 a, b = b, a 162 } 163 164 diff := float64(a-b) / float64(a) 165 if diff > maxDiff { 166 return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100) 167 } 168 169 return nil 170 } 171 172 for _, tc := range []struct { 173 name string 174 workers int 175 }{ 176 { 177 name: "serial", 178 workers: 1, 179 }, 180 { 181 name: "parallel", 182 workers: runtime.GOMAXPROCS(0), 183 }, 184 } { 185 // check that the OS's perspective matches what the Go runtime measures. 186 t.Run(tc.name, func(t *testing.T) { 187 t.Logf("Running with %d workers", tc.workers) 188 189 var userTime, systemTime time.Duration 190 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions()) 191 acceptProfile := func(t *testing.T, p *profile.Profile) bool { 192 if !matches(t, p) { 193 return false 194 } 195 196 ok := true 197 for i, unit := range []string{"count", "nanoseconds"} { 198 if have, want := p.SampleType[i].Unit, unit; have != want { 199 t.Logf("pN SampleType[%d]; %q != %q", i, have, want) 200 ok = false 201 } 202 } 203 204 // cpuHog1 called below is the primary source of CPU 205 // load, but there may be some background work by the 206 // runtime. Since the OS rusage measurement will 207 // include all work done by the process, also compare 208 // against all samples in our profile. 209 var value time.Duration 210 for _, sample := range p.Sample { 211 value += time.Duration(sample.Value[1]) * time.Nanosecond 212 } 213 214 totalTime := userTime + systemTime 215 t.Logf("compare %s user + %s system = %s vs %s", userTime, systemTime, totalTime, value) 216 if err := compare(totalTime, value, maxDiff); err != nil { 217 t.Logf("compare got %v want nil", err) 218 ok = false 219 } 220 221 return ok 222 } 223 224 testCPUProfile(t, acceptProfile, func(dur time.Duration) { 225 userTime, systemTime = diffCPUTime(t, func() { 226 var wg sync.WaitGroup 227 var once sync.Once 228 for i := 0; i < tc.workers; i++ { 229 wg.Add(1) 230 go func() { 231 defer wg.Done() 232 var salt = 0 233 cpuHogger(cpuHog1, &salt, dur) 234 once.Do(func() { salt1 = salt }) 235 }() 236 } 237 wg.Wait() 238 }) 239 }) 240 }) 241 } 242 } 243 244 // containsInlinedCall reports whether the function body for the function f is 245 // known to contain an inlined function call within the first maxBytes bytes. 246 func containsInlinedCall(f any, maxBytes int) bool { 247 _, found := findInlinedCall(f, maxBytes) 248 return found 249 } 250 251 // findInlinedCall returns the PC of an inlined function call within 252 // the function body for the function f if any. 253 func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) { 254 fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f))) 255 if fFunc == nil || fFunc.Entry() == 0 { 256 panic("failed to locate function entry") 257 } 258 259 for offset := 0; offset < maxBytes; offset++ { 260 innerPC := fFunc.Entry() + uintptr(offset) 261 inner := runtime.FuncForPC(innerPC) 262 if inner == nil { 263 // No function known for this PC value. 264 // It might simply be misaligned, so keep searching. 265 continue 266 } 267 if inner.Entry() != fFunc.Entry() { 268 // Scanned past f and didn't find any inlined functions. 269 break 270 } 271 if inner.Name() != fFunc.Name() { 272 // This PC has f as its entry-point, but is not f. Therefore, it must be a 273 // function inlined into f. 274 return uint64(innerPC), true 275 } 276 } 277 278 return 0, false 279 } 280 281 func TestCPUProfileInlining(t *testing.T) { 282 if !containsInlinedCall(inlinedCaller, 4<<10) { 283 t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.") 284 } 285 286 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions()) 287 p := testCPUProfile(t, matches, func(dur time.Duration) { 288 cpuHogger(inlinedCaller, &salt1, dur) 289 }) 290 291 // Check if inlined function locations are encoded correctly. The inlinedCalee and inlinedCaller should be in one location. 292 for _, loc := range p.Location { 293 hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false 294 for _, line := range loc.Line { 295 if line.Function.Name == "runtime/pprof.inlinedCallee" { 296 hasInlinedCallee = true 297 } 298 if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" { 299 hasInlinedCallerAfterInlinedCallee = true 300 } 301 } 302 if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee { 303 t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p) 304 } 305 } 306 } 307 308 func inlinedCaller(x int) int { 309 x = inlinedCallee(x, 1e5) 310 return x 311 } 312 313 func inlinedCallee(x, n int) int { 314 return cpuHog0(x, n) 315 } 316 317 //go:noinline 318 func dumpCallers(pcs []uintptr) { 319 if pcs == nil { 320 return 321 } 322 323 skip := 2 // Callers and dumpCallers 324 runtime.Callers(skip, pcs) 325 } 326 327 //go:noinline 328 func inlinedCallerDump(pcs []uintptr) { 329 inlinedCalleeDump(pcs) 330 } 331 332 func inlinedCalleeDump(pcs []uintptr) { 333 dumpCallers(pcs) 334 } 335 336 type inlineWrapperInterface interface { 337 dump(stack []uintptr) 338 } 339 340 type inlineWrapper struct { 341 } 342 343 func (h inlineWrapper) dump(pcs []uintptr) { 344 dumpCallers(pcs) 345 } 346 347 func inlinedWrapperCallerDump(pcs []uintptr) { 348 var h inlineWrapperInterface 349 h = &inlineWrapper{} 350 h.dump(pcs) 351 } 352 353 func TestCPUProfileRecursion(t *testing.T) { 354 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions()) 355 p := testCPUProfile(t, matches, func(dur time.Duration) { 356 cpuHogger(recursionCaller, &salt1, dur) 357 }) 358 359 // check the Location encoding was not confused by recursive calls. 360 for i, loc := range p.Location { 361 recursionFunc := 0 362 for _, line := range loc.Line { 363 if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" { 364 recursionFunc++ 365 } 366 } 367 if recursionFunc > 1 { 368 t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p) 369 } 370 } 371 } 372 373 func recursionCaller(x int) int { 374 y := recursionCallee(3, x) 375 return y 376 } 377 378 func recursionCallee(n, x int) int { 379 if n == 0 { 380 return 1 381 } 382 y := inlinedCallee(x, 1e4) 383 return y * recursionCallee(n-1, x) 384 } 385 386 func recursionChainTop(x int, pcs []uintptr) { 387 if x < 0 { 388 return 389 } 390 recursionChainMiddle(x, pcs) 391 } 392 393 func recursionChainMiddle(x int, pcs []uintptr) { 394 recursionChainBottom(x, pcs) 395 } 396 397 func recursionChainBottom(x int, pcs []uintptr) { 398 // This will be called each time, we only care about the last. We 399 // can't make this conditional or this function won't be inlined. 400 dumpCallers(pcs) 401 402 recursionChainTop(x-1, pcs) 403 } 404 405 func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile { 406 p, err := profile.Parse(bytes.NewReader(valBytes)) 407 if err != nil { 408 t.Fatal(err) 409 } 410 for _, sample := range p.Sample { 411 count := uintptr(sample.Value[0]) 412 f(count, sample.Location, sample.Label) 413 } 414 return p 415 } 416 417 func cpuProfilingBroken() bool { 418 switch runtime.GOOS { 419 case "plan9": 420 // Profiling unimplemented. 421 return true 422 case "aix": 423 // See https://golang.org/issue/45170. 424 return true 425 case "ios", "dragonfly", "netbsd", "illumos", "solaris": 426 // See https://golang.org/issue/13841. 427 return true 428 case "openbsd": 429 if runtime.GOARCH == "arm" || runtime.GOARCH == "arm64" { 430 // See https://golang.org/issue/13841. 431 return true 432 } 433 } 434 435 return false 436 } 437 438 // testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need, 439 // as interpreted by matches, and returns the parsed profile. 440 func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile { 441 switch runtime.GOOS { 442 case "darwin": 443 out, err := exec.Command("uname", "-a").CombinedOutput() 444 if err != nil { 445 t.Fatal(err) 446 } 447 vers := string(out) 448 t.Logf("uname -a: %v", vers) 449 case "plan9": 450 t.Skip("skipping on plan9") 451 case "wasip1": 452 t.Skip("skipping on wasip1") 453 } 454 455 broken := cpuProfilingBroken() 456 457 deadline, ok := t.Deadline() 458 if broken || !ok { 459 if broken && testing.Short() { 460 // If it's expected to be broken, no point waiting around. 461 deadline = time.Now().Add(1 * time.Second) 462 } else { 463 deadline = time.Now().Add(10 * time.Second) 464 } 465 } 466 467 // If we're running a long test, start with a long duration 468 // for tests that try to make sure something *doesn't* happen. 469 duration := 5 * time.Second 470 if testing.Short() { 471 duration = 100 * time.Millisecond 472 } 473 474 // Profiling tests are inherently flaky, especially on a 475 // loaded system, such as when this test is running with 476 // several others under go test std. If a test fails in a way 477 // that could mean it just didn't run long enough, try with a 478 // longer duration. 479 for { 480 var prof bytes.Buffer 481 if err := StartCPUProfile(&prof); err != nil { 482 t.Fatal(err) 483 } 484 f(duration) 485 StopCPUProfile() 486 487 if p, ok := profileOk(t, matches, prof, duration); ok { 488 return p 489 } 490 491 duration *= 2 492 if time.Until(deadline) < duration { 493 break 494 } 495 t.Logf("retrying with %s duration", duration) 496 } 497 498 if broken { 499 t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH) 500 } 501 502 // Ignore the failure if the tests are running in a QEMU-based emulator, 503 // QEMU is not perfect at emulating everything. 504 // IN_QEMU environmental variable is set by some of the Go builders. 505 // IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605. 506 if os.Getenv("IN_QEMU") == "1" { 507 t.Skip("ignore the failure in QEMU; see golang.org/issue/9605") 508 } 509 t.FailNow() 510 return nil 511 } 512 513 var diffCPUTimeImpl func(f func()) (user, system time.Duration) 514 515 func diffCPUTime(t *testing.T, f func()) (user, system time.Duration) { 516 if fn := diffCPUTimeImpl; fn != nil { 517 return fn(f) 518 } 519 t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH) 520 return 0, 0 521 } 522 523 func contains(slice []string, s string) bool { 524 for i := range slice { 525 if slice[i] == s { 526 return true 527 } 528 } 529 return false 530 } 531 532 // stackContains matches if a function named spec appears anywhere in the stack trace. 533 func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 534 for _, loc := range stk { 535 for _, line := range loc.Line { 536 if strings.Contains(line.Function.Name, spec) { 537 return true 538 } 539 } 540 } 541 return false 542 } 543 544 type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool 545 546 func profileOk(t *testing.T, matches profileMatchFunc, prof bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) { 547 ok = true 548 549 var samples uintptr 550 var buf strings.Builder 551 p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) { 552 fmt.Fprintf(&buf, "%d:", count) 553 fprintStack(&buf, stk) 554 fmt.Fprintf(&buf, " labels: %v\n", labels) 555 samples += count 556 fmt.Fprintf(&buf, "\n") 557 }) 558 t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String()) 559 560 if samples < 10 && runtime.GOOS == "windows" { 561 // On some windows machines we end up with 562 // not enough samples due to coarse timer 563 // resolution. Let it go. 564 t.Log("too few samples on Windows (golang.org/issue/10842)") 565 return p, false 566 } 567 568 // Check that we got a reasonable number of samples. 569 // We used to always require at least ideal/4 samples, 570 // but that is too hard to guarantee on a loaded system. 571 // Now we accept 10 or more samples, which we take to be 572 // enough to show that at least some profiling is occurring. 573 if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) { 574 t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal) 575 ok = false 576 } 577 578 if matches != nil && !matches(t, p) { 579 ok = false 580 } 581 582 return p, ok 583 } 584 585 type profileMatchFunc func(*testing.T, *profile.Profile) bool 586 587 func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc { 588 return func(t *testing.T, p *profile.Profile) (ok bool) { 589 ok = true 590 591 // Check that profile is well formed, contains 'need', and does not contain 592 // anything from 'avoid'. 593 have := make([]uintptr, len(need)) 594 avoidSamples := make([]uintptr, len(avoid)) 595 596 for _, sample := range p.Sample { 597 count := uintptr(sample.Value[0]) 598 for i, spec := range need { 599 if matches(spec, count, sample.Location, sample.Label) { 600 have[i] += count 601 } 602 } 603 for i, name := range avoid { 604 for _, loc := range sample.Location { 605 for _, line := range loc.Line { 606 if strings.Contains(line.Function.Name, name) { 607 avoidSamples[i] += count 608 } 609 } 610 } 611 } 612 } 613 614 for i, name := range avoid { 615 bad := avoidSamples[i] 616 if bad != 0 { 617 t.Logf("found %d samples in avoid-function %s\n", bad, name) 618 ok = false 619 } 620 } 621 622 if len(need) == 0 { 623 return 624 } 625 626 var total uintptr 627 for i, name := range need { 628 total += have[i] 629 t.Logf("found %d samples in expected function %s\n", have[i], name) 630 } 631 if total == 0 { 632 t.Logf("no samples in expected functions") 633 ok = false 634 } 635 636 // We'd like to check a reasonable minimum, like 637 // total / len(have) / smallconstant, but this test is 638 // pretty flaky (see bug 7095). So we'll just test to 639 // make sure we got at least one sample. 640 min := uintptr(1) 641 for i, name := range need { 642 if have[i] < min { 643 t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have))) 644 ok = false 645 } 646 } 647 return 648 } 649 } 650 651 // Fork can hang if preempted with signals frequently enough (see issue 5517). 652 // Ensure that we do not do this. 653 func TestCPUProfileWithFork(t *testing.T) { 654 testenv.MustHaveExec(t) 655 656 heap := 1 << 30 657 if runtime.GOOS == "android" { 658 // Use smaller size for Android to avoid crash. 659 heap = 100 << 20 660 } 661 if runtime.GOOS == "windows" && runtime.GOARCH == "arm" { 662 // Use smaller heap for Windows/ARM to avoid crash. 663 heap = 100 << 20 664 } 665 if testing.Short() { 666 heap = 100 << 20 667 } 668 // This makes fork slower. 669 garbage := make([]byte, heap) 670 // Need to touch the slice, otherwise it won't be paged in. 671 done := make(chan bool) 672 go func() { 673 for i := range garbage { 674 garbage[i] = 42 675 } 676 done <- true 677 }() 678 <-done 679 680 var prof bytes.Buffer 681 if err := StartCPUProfile(&prof); err != nil { 682 t.Fatal(err) 683 } 684 defer StopCPUProfile() 685 686 for i := 0; i < 10; i++ { 687 exec.Command(os.Args[0], "-h").CombinedOutput() 688 } 689 } 690 691 // Test that profiler does not observe runtime.gogo as "user" goroutine execution. 692 // If it did, it would see inconsistent state and would either record an incorrect stack 693 // or crash because the stack was malformed. 694 func TestGoroutineSwitch(t *testing.T) { 695 if runtime.Compiler == "gccgo" { 696 t.Skip("not applicable for gccgo") 697 } 698 // How much to try. These defaults take about 1 seconds 699 // on a 2012 MacBook Pro. The ones in short mode take 700 // about 0.1 seconds. 701 tries := 10 702 count := 1000000 703 if testing.Short() { 704 tries = 1 705 } 706 for try := 0; try < tries; try++ { 707 var prof bytes.Buffer 708 if err := StartCPUProfile(&prof); err != nil { 709 t.Fatal(err) 710 } 711 for i := 0; i < count; i++ { 712 runtime.Gosched() 713 } 714 StopCPUProfile() 715 716 // Read profile to look for entries for gogo with an attempt at a traceback. 717 // "runtime.gogo" is OK, because that's the part of the context switch 718 // before the actual switch begins. But we should not see "gogo", 719 // aka "gogo<>(SB)", which does the actual switch and is marked SPWRITE. 720 parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) { 721 // An entry with two frames with 'System' in its top frame 722 // exists to record a PC without a traceback. Those are okay. 723 if len(stk) == 2 { 724 name := stk[1].Line[0].Function.Name 725 if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" { 726 return 727 } 728 } 729 730 // An entry with just one frame is OK too: 731 // it knew to stop at gogo. 732 if len(stk) == 1 { 733 return 734 } 735 736 // Otherwise, should not see gogo. 737 // The place we'd see it would be the inner most frame. 738 name := stk[0].Line[0].Function.Name 739 if name == "gogo" { 740 var buf strings.Builder 741 fprintStack(&buf, stk) 742 t.Fatalf("found profile entry for gogo:\n%s", buf.String()) 743 } 744 }) 745 } 746 } 747 748 func fprintStack(w io.Writer, stk []*profile.Location) { 749 if len(stk) == 0 { 750 fmt.Fprintf(w, " (stack empty)") 751 } 752 for _, loc := range stk { 753 fmt.Fprintf(w, " %#x", loc.Address) 754 fmt.Fprintf(w, " (") 755 for i, line := range loc.Line { 756 if i > 0 { 757 fmt.Fprintf(w, " ") 758 } 759 fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line) 760 } 761 fmt.Fprintf(w, ")") 762 } 763 } 764 765 // Test that profiling of division operations is okay, especially on ARM. See issue 6681. 766 func TestMathBigDivide(t *testing.T) { 767 testCPUProfile(t, nil, func(duration time.Duration) { 768 t := time.After(duration) 769 pi := new(big.Int) 770 for { 771 for i := 0; i < 100; i++ { 772 n := big.NewInt(2646693125139304345) 773 d := big.NewInt(842468587426513207) 774 pi.Div(n, d) 775 } 776 select { 777 case <-t: 778 return 779 default: 780 } 781 } 782 }) 783 } 784 785 // stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace. 786 func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 787 for _, f := range strings.Split(spec, ",") { 788 if !stackContains(f, count, stk, labels) { 789 return false 790 } 791 } 792 return true 793 } 794 795 func TestMorestack(t *testing.T) { 796 matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions()) 797 testCPUProfile(t, matches, func(duration time.Duration) { 798 t := time.After(duration) 799 c := make(chan bool) 800 for { 801 go func() { 802 growstack1() 803 c <- true 804 }() 805 select { 806 case <-t: 807 return 808 case <-c: 809 } 810 } 811 }) 812 } 813 814 //go:noinline 815 func growstack1() { 816 growstack(10) 817 } 818 819 //go:noinline 820 func growstack(n int) { 821 var buf [8 << 18]byte 822 use(buf) 823 if n > 0 { 824 growstack(n - 1) 825 } 826 } 827 828 //go:noinline 829 func use(x [8 << 18]byte) {} 830 831 func TestBlockProfile(t *testing.T) { 832 type TestCase struct { 833 name string 834 f func(*testing.T) 835 stk []string 836 re string 837 } 838 tests := [...]TestCase{ 839 { 840 name: "chan recv", 841 f: blockChanRecv, 842 stk: []string{ 843 "runtime.chanrecv1", 844 "runtime/pprof.blockChanRecv", 845 "runtime/pprof.TestBlockProfile", 846 }, 847 re: ` 848 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 849 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+ 850 # 0x[0-9a-f]+ runtime/pprof\.blockChanRecv\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 851 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 852 `}, 853 { 854 name: "chan send", 855 f: blockChanSend, 856 stk: []string{ 857 "runtime.chansend1", 858 "runtime/pprof.blockChanSend", 859 "runtime/pprof.TestBlockProfile", 860 }, 861 re: ` 862 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 863 # 0x[0-9a-f]+ runtime\.chansend1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+ 864 # 0x[0-9a-f]+ runtime/pprof\.blockChanSend\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 865 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 866 `}, 867 { 868 name: "chan close", 869 f: blockChanClose, 870 stk: []string{ 871 "runtime.chanrecv1", 872 "runtime/pprof.blockChanClose", 873 "runtime/pprof.TestBlockProfile", 874 }, 875 re: ` 876 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 877 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+ 878 # 0x[0-9a-f]+ runtime/pprof\.blockChanClose\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 879 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 880 `}, 881 { 882 name: "select recv async", 883 f: blockSelectRecvAsync, 884 stk: []string{ 885 "runtime.selectgo", 886 "runtime/pprof.blockSelectRecvAsync", 887 "runtime/pprof.TestBlockProfile", 888 }, 889 re: ` 890 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 891 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*runtime/select.go:[0-9]+ 892 # 0x[0-9a-f]+ runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 893 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 894 `}, 895 { 896 name: "select send sync", 897 f: blockSelectSendSync, 898 stk: []string{ 899 "runtime.selectgo", 900 "runtime/pprof.blockSelectSendSync", 901 "runtime/pprof.TestBlockProfile", 902 }, 903 re: ` 904 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 905 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*runtime/select.go:[0-9]+ 906 # 0x[0-9a-f]+ runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 907 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 908 `}, 909 { 910 name: "mutex", 911 f: blockMutex, 912 stk: []string{ 913 "sync.(*Mutex).Lock", 914 "runtime/pprof.blockMutex", 915 "runtime/pprof.TestBlockProfile", 916 }, 917 re: ` 918 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 919 # 0x[0-9a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+ .*sync/mutex\.go:[0-9]+ 920 # 0x[0-9a-f]+ runtime/pprof\.blockMutex\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 921 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 922 `}, 923 { 924 name: "cond", 925 f: blockCond, 926 stk: []string{ 927 "sync.(*Cond).Wait", 928 "runtime/pprof.blockCond", 929 "runtime/pprof.TestBlockProfile", 930 }, 931 re: ` 932 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+ 933 # 0x[0-9a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+ .*sync/cond\.go:[0-9]+ 934 # 0x[0-9a-f]+ runtime/pprof\.blockCond\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 935 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+ 936 `}, 937 } 938 939 // Generate block profile 940 runtime.SetBlockProfileRate(1) 941 defer runtime.SetBlockProfileRate(0) 942 for _, test := range tests { 943 test.f(t) 944 } 945 946 t.Run("debug=1", func(t *testing.T) { 947 var w strings.Builder 948 Lookup("block").WriteTo(&w, 1) 949 prof := w.String() 950 951 if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") { 952 t.Fatalf("Bad profile header:\n%v", prof) 953 } 954 955 if strings.HasSuffix(prof, "#\t0x0\n\n") { 956 t.Errorf("Useless 0 suffix:\n%v", prof) 957 } 958 959 for _, test := range tests { 960 if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) { 961 t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof) 962 } 963 } 964 }) 965 966 t.Run("proto", func(t *testing.T) { 967 // proto format 968 var w bytes.Buffer 969 Lookup("block").WriteTo(&w, 0) 970 p, err := profile.Parse(&w) 971 if err != nil { 972 t.Fatalf("failed to parse profile: %v", err) 973 } 974 t.Logf("parsed proto: %s", p) 975 if err := p.CheckValid(); err != nil { 976 t.Fatalf("invalid profile: %v", err) 977 } 978 979 stks := stacks(p) 980 for _, test := range tests { 981 if !containsStack(stks, test.stk) { 982 t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk) 983 } 984 } 985 }) 986 987 } 988 989 func stacks(p *profile.Profile) (res [][]string) { 990 for _, s := range p.Sample { 991 var stk []string 992 for _, l := range s.Location { 993 for _, line := range l.Line { 994 stk = append(stk, line.Function.Name) 995 } 996 } 997 res = append(res, stk) 998 } 999 return res 1000 } 1001 1002 func containsStack(got [][]string, want []string) bool { 1003 for _, stk := range got { 1004 if len(stk) < len(want) { 1005 continue 1006 } 1007 for i, f := range want { 1008 if f != stk[i] { 1009 break 1010 } 1011 if i == len(want)-1 { 1012 return true 1013 } 1014 } 1015 } 1016 return false 1017 } 1018 1019 // awaitBlockedGoroutine spins on runtime.Gosched until a runtime stack dump 1020 // shows a goroutine in the given state with a stack frame in 1021 // runtime/pprof.<fName>. 1022 func awaitBlockedGoroutine(t *testing.T, state, fName string) { 1023 re := fmt.Sprintf(`(?m)^goroutine \d+ \[%s\]:\n(?:.+\n\t.+\n)*runtime/pprof\.%s`, regexp.QuoteMeta(state), fName) 1024 r := regexp.MustCompile(re) 1025 1026 if deadline, ok := t.Deadline(); ok { 1027 if d := time.Until(deadline); d > 1*time.Second { 1028 timer := time.AfterFunc(d-1*time.Second, func() { 1029 debug.SetTraceback("all") 1030 panic(fmt.Sprintf("timed out waiting for %#q", re)) 1031 }) 1032 defer timer.Stop() 1033 } 1034 } 1035 1036 buf := make([]byte, 64<<10) 1037 for { 1038 runtime.Gosched() 1039 n := runtime.Stack(buf, true) 1040 if n == len(buf) { 1041 // Buffer wasn't large enough for a full goroutine dump. 1042 // Resize it and try again. 1043 buf = make([]byte, 2*len(buf)) 1044 continue 1045 } 1046 if r.Match(buf[:n]) { 1047 return 1048 } 1049 } 1050 } 1051 1052 func blockChanRecv(t *testing.T) { 1053 c := make(chan bool) 1054 go func() { 1055 awaitBlockedGoroutine(t, "chan receive", "blockChanRecv") 1056 c <- true 1057 }() 1058 <-c 1059 } 1060 1061 func blockChanSend(t *testing.T) { 1062 c := make(chan bool) 1063 go func() { 1064 awaitBlockedGoroutine(t, "chan send", "blockChanSend") 1065 <-c 1066 }() 1067 c <- true 1068 } 1069 1070 func blockChanClose(t *testing.T) { 1071 c := make(chan bool) 1072 go func() { 1073 awaitBlockedGoroutine(t, "chan receive", "blockChanClose") 1074 close(c) 1075 }() 1076 <-c 1077 } 1078 1079 func blockSelectRecvAsync(t *testing.T) { 1080 const numTries = 3 1081 c := make(chan bool, 1) 1082 c2 := make(chan bool, 1) 1083 go func() { 1084 for i := 0; i < numTries; i++ { 1085 awaitBlockedGoroutine(t, "select", "blockSelectRecvAsync") 1086 c <- true 1087 } 1088 }() 1089 for i := 0; i < numTries; i++ { 1090 select { 1091 case <-c: 1092 case <-c2: 1093 } 1094 } 1095 } 1096 1097 func blockSelectSendSync(t *testing.T) { 1098 c := make(chan bool) 1099 c2 := make(chan bool) 1100 go func() { 1101 awaitBlockedGoroutine(t, "select", "blockSelectSendSync") 1102 <-c 1103 }() 1104 select { 1105 case c <- true: 1106 case c2 <- true: 1107 } 1108 } 1109 1110 func blockMutex(t *testing.T) { 1111 var mu sync.Mutex 1112 mu.Lock() 1113 go func() { 1114 awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex") 1115 mu.Unlock() 1116 }() 1117 // Note: Unlock releases mu before recording the mutex event, 1118 // so it's theoretically possible for this to proceed and 1119 // capture the profile before the event is recorded. As long 1120 // as this is blocked before the unlock happens, it's okay. 1121 mu.Lock() 1122 } 1123 1124 func blockCond(t *testing.T) { 1125 var mu sync.Mutex 1126 c := sync.NewCond(&mu) 1127 mu.Lock() 1128 go func() { 1129 awaitBlockedGoroutine(t, "sync.Cond.Wait", "blockCond") 1130 mu.Lock() 1131 c.Signal() 1132 mu.Unlock() 1133 }() 1134 c.Wait() 1135 mu.Unlock() 1136 } 1137 1138 // See http://golang.org/cl/299991. 1139 func TestBlockProfileBias(t *testing.T) { 1140 rate := int(1000) // arbitrary value 1141 runtime.SetBlockProfileRate(rate) 1142 defer runtime.SetBlockProfileRate(0) 1143 1144 // simulate blocking events 1145 blockFrequentShort(rate) 1146 blockInfrequentLong(rate) 1147 1148 var w bytes.Buffer 1149 Lookup("block").WriteTo(&w, 0) 1150 p, err := profile.Parse(&w) 1151 if err != nil { 1152 t.Fatalf("failed to parse profile: %v", err) 1153 } 1154 t.Logf("parsed proto: %s", p) 1155 1156 il := float64(-1) // blockInfrequentLong duration 1157 fs := float64(-1) // blockFrequentShort duration 1158 for _, s := range p.Sample { 1159 for _, l := range s.Location { 1160 for _, line := range l.Line { 1161 if len(s.Value) < 2 { 1162 t.Fatal("block profile has less than 2 sample types") 1163 } 1164 1165 if line.Function.Name == "runtime/pprof.blockInfrequentLong" { 1166 il = float64(s.Value[1]) 1167 } else if line.Function.Name == "runtime/pprof.blockFrequentShort" { 1168 fs = float64(s.Value[1]) 1169 } 1170 } 1171 } 1172 } 1173 if il == -1 || fs == -1 { 1174 t.Fatal("block profile is missing expected functions") 1175 } 1176 1177 // stddev of bias from 100 runs on local machine multiplied by 10x 1178 const threshold = 0.2 1179 if bias := (il - fs) / il; math.Abs(bias) > threshold { 1180 t.Fatalf("bias: abs(%f) > %f", bias, threshold) 1181 } else { 1182 t.Logf("bias: abs(%f) < %f", bias, threshold) 1183 } 1184 } 1185 1186 // blockFrequentShort produces 100000 block events with an average duration of 1187 // rate / 10. 1188 func blockFrequentShort(rate int) { 1189 for i := 0; i < 100000; i++ { 1190 blockevent(int64(rate/10), 1) 1191 } 1192 } 1193 1194 // blockFrequentShort produces 10000 block events with an average duration of 1195 // rate. 1196 func blockInfrequentLong(rate int) { 1197 for i := 0; i < 10000; i++ { 1198 blockevent(int64(rate), 1) 1199 } 1200 } 1201 1202 // Used by TestBlockProfileBias. 1203 // 1204 //go:linkname blockevent runtime.blockevent 1205 func blockevent(cycles int64, skip int) 1206 1207 func TestMutexProfile(t *testing.T) { 1208 // Generate mutex profile 1209 1210 old := runtime.SetMutexProfileFraction(1) 1211 defer runtime.SetMutexProfileFraction(old) 1212 if old != 0 { 1213 t.Fatalf("need MutexProfileRate 0, got %d", old) 1214 } 1215 1216 blockMutex(t) 1217 1218 t.Run("debug=1", func(t *testing.T) { 1219 var w strings.Builder 1220 Lookup("mutex").WriteTo(&w, 1) 1221 prof := w.String() 1222 t.Logf("received profile: %v", prof) 1223 1224 if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") { 1225 t.Errorf("Bad profile header:\n%v", prof) 1226 } 1227 prof = strings.Trim(prof, "\n") 1228 lines := strings.Split(prof, "\n") 1229 if len(lines) != 6 { 1230 t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof) 1231 } 1232 if len(lines) < 6 { 1233 return 1234 } 1235 // checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931" 1236 r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+` 1237 //r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$" 1238 if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok { 1239 t.Errorf("%q didn't match %q", lines[3], r2) 1240 } 1241 r3 := "^#.*runtime/pprof.blockMutex.*$" 1242 if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok { 1243 t.Errorf("%q didn't match %q", lines[5], r3) 1244 } 1245 t.Logf(prof) 1246 }) 1247 t.Run("proto", func(t *testing.T) { 1248 // proto format 1249 var w bytes.Buffer 1250 Lookup("mutex").WriteTo(&w, 0) 1251 p, err := profile.Parse(&w) 1252 if err != nil { 1253 t.Fatalf("failed to parse profile: %v", err) 1254 } 1255 t.Logf("parsed proto: %s", p) 1256 if err := p.CheckValid(); err != nil { 1257 t.Fatalf("invalid profile: %v", err) 1258 } 1259 1260 stks := stacks(p) 1261 for _, want := range [][]string{ 1262 {"sync.(*Mutex).Unlock", "runtime/pprof.blockMutex.func1"}, 1263 } { 1264 if !containsStack(stks, want) { 1265 t.Errorf("No matching stack entry for %+v", want) 1266 } 1267 } 1268 }) 1269 } 1270 1271 func TestMutexProfileRateAdjust(t *testing.T) { 1272 old := runtime.SetMutexProfileFraction(1) 1273 defer runtime.SetMutexProfileFraction(old) 1274 if old != 0 { 1275 t.Fatalf("need MutexProfileRate 0, got %d", old) 1276 } 1277 1278 readProfile := func() (contentions int64, delay int64) { 1279 var w bytes.Buffer 1280 Lookup("mutex").WriteTo(&w, 0) 1281 p, err := profile.Parse(&w) 1282 if err != nil { 1283 t.Fatalf("failed to parse profile: %v", err) 1284 } 1285 t.Logf("parsed proto: %s", p) 1286 if err := p.CheckValid(); err != nil { 1287 t.Fatalf("invalid profile: %v", err) 1288 } 1289 1290 for _, s := range p.Sample { 1291 for _, l := range s.Location { 1292 for _, line := range l.Line { 1293 if line.Function.Name == "runtime/pprof.blockMutex.func1" { 1294 contentions += s.Value[0] 1295 delay += s.Value[1] 1296 } 1297 } 1298 } 1299 } 1300 return 1301 } 1302 1303 blockMutex(t) 1304 contentions, delay := readProfile() 1305 if contentions == 0 || delay == 0 { 1306 t.Fatal("did not see expected function in profile") 1307 } 1308 runtime.SetMutexProfileFraction(0) 1309 newContentions, newDelay := readProfile() 1310 if newContentions != contentions || newDelay != delay { 1311 t.Fatalf("sample value changed: got [%d, %d], want [%d, %d]", newContentions, newDelay, contentions, delay) 1312 } 1313 } 1314 1315 func func1(c chan int) { <-c } 1316 func func2(c chan int) { <-c } 1317 func func3(c chan int) { <-c } 1318 func func4(c chan int) { <-c } 1319 1320 func TestGoroutineCounts(t *testing.T) { 1321 // Setting GOMAXPROCS to 1 ensures we can force all goroutines to the 1322 // desired blocking point. 1323 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1)) 1324 1325 c := make(chan int) 1326 for i := 0; i < 100; i++ { 1327 switch { 1328 case i%10 == 0: 1329 go func1(c) 1330 case i%2 == 0: 1331 go func2(c) 1332 default: 1333 go func3(c) 1334 } 1335 // Let goroutines block on channel 1336 for j := 0; j < 5; j++ { 1337 runtime.Gosched() 1338 } 1339 } 1340 ctx := context.Background() 1341 1342 // ... and again, with labels this time (just with fewer iterations to keep 1343 // sorting deterministic). 1344 Do(ctx, Labels("label", "value"), func(context.Context) { 1345 for i := 0; i < 89; i++ { 1346 switch { 1347 case i%10 == 0: 1348 go func1(c) 1349 case i%2 == 0: 1350 go func2(c) 1351 default: 1352 go func3(c) 1353 } 1354 // Let goroutines block on channel 1355 for j := 0; j < 5; j++ { 1356 runtime.Gosched() 1357 } 1358 } 1359 }) 1360 1361 var w bytes.Buffer 1362 goroutineProf := Lookup("goroutine") 1363 1364 // Check debug profile 1365 goroutineProf.WriteTo(&w, 1) 1366 prof := w.String() 1367 1368 labels := labelMap{"label": "value"} 1369 labelStr := "\n# labels: " + labels.String() 1370 if !containsInOrder(prof, "\n50 @ ", "\n44 @", labelStr, 1371 "\n40 @", "\n36 @", labelStr, "\n10 @", "\n9 @", labelStr, "\n1 @") { 1372 t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof) 1373 } 1374 1375 // Check proto profile 1376 w.Reset() 1377 goroutineProf.WriteTo(&w, 0) 1378 p, err := profile.Parse(&w) 1379 if err != nil { 1380 t.Errorf("error parsing protobuf profile: %v", err) 1381 } 1382 if err := p.CheckValid(); err != nil { 1383 t.Errorf("protobuf profile is invalid: %v", err) 1384 } 1385 expectedLabels := map[int64]map[string]string{ 1386 50: {}, 1387 44: {"label": "value"}, 1388 40: {}, 1389 36: {"label": "value"}, 1390 10: {}, 1391 9: {"label": "value"}, 1392 1: {}, 1393 } 1394 if !containsCountsLabels(p, expectedLabels) { 1395 t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v", 1396 expectedLabels, p) 1397 } 1398 1399 close(c) 1400 1401 time.Sleep(10 * time.Millisecond) // let goroutines exit 1402 } 1403 1404 func containsInOrder(s string, all ...string) bool { 1405 for _, t := range all { 1406 var ok bool 1407 if _, s, ok = strings.Cut(s, t); !ok { 1408 return false 1409 } 1410 } 1411 return true 1412 } 1413 1414 func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool { 1415 m := make(map[int64]int) 1416 type nkey struct { 1417 count int64 1418 key, val string 1419 } 1420 n := make(map[nkey]int) 1421 for c, kv := range countLabels { 1422 m[c]++ 1423 for k, v := range kv { 1424 n[nkey{ 1425 count: c, 1426 key: k, 1427 val: v, 1428 }]++ 1429 1430 } 1431 } 1432 for _, s := range prof.Sample { 1433 // The count is the single value in the sample 1434 if len(s.Value) != 1 { 1435 return false 1436 } 1437 m[s.Value[0]]-- 1438 for k, vs := range s.Label { 1439 for _, v := range vs { 1440 n[nkey{ 1441 count: s.Value[0], 1442 key: k, 1443 val: v, 1444 }]-- 1445 } 1446 } 1447 } 1448 for _, n := range m { 1449 if n > 0 { 1450 return false 1451 } 1452 } 1453 for _, ncnt := range n { 1454 if ncnt != 0 { 1455 return false 1456 } 1457 } 1458 return true 1459 } 1460 1461 func TestGoroutineProfileConcurrency(t *testing.T) { 1462 testenv.MustHaveParallelism(t) 1463 1464 goroutineProf := Lookup("goroutine") 1465 1466 profilerCalls := func(s string) int { 1467 return strings.Count(s, "\truntime/pprof.runtime_goroutineProfileWithLabels+") 1468 } 1469 1470 includesFinalizer := func(s string) bool { 1471 return strings.Contains(s, "runtime.runfinq") 1472 } 1473 1474 // Concurrent calls to the goroutine profiler should not trigger data races 1475 // or corruption. 1476 t.Run("overlapping profile requests", func(t *testing.T) { 1477 ctx := context.Background() 1478 ctx, cancel := context.WithTimeout(ctx, 10*time.Second) 1479 defer cancel() 1480 1481 var wg sync.WaitGroup 1482 for i := 0; i < 2; i++ { 1483 wg.Add(1) 1484 Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) { 1485 go func() { 1486 defer wg.Done() 1487 for ctx.Err() == nil { 1488 var w strings.Builder 1489 goroutineProf.WriteTo(&w, 1) 1490 prof := w.String() 1491 count := profilerCalls(prof) 1492 if count >= 2 { 1493 t.Logf("prof %d\n%s", count, prof) 1494 cancel() 1495 } 1496 } 1497 }() 1498 }) 1499 } 1500 wg.Wait() 1501 }) 1502 1503 // The finalizer goroutine should not show up in most profiles, since it's 1504 // marked as a system goroutine when idle. 1505 t.Run("finalizer not present", func(t *testing.T) { 1506 var w strings.Builder 1507 goroutineProf.WriteTo(&w, 1) 1508 prof := w.String() 1509 if includesFinalizer(prof) { 1510 t.Errorf("profile includes finalizer (but finalizer should be marked as system):\n%s", prof) 1511 } 1512 }) 1513 1514 // The finalizer goroutine should show up when it's running user code. 1515 t.Run("finalizer present", func(t *testing.T) { 1516 obj := new(byte) 1517 ch1, ch2 := make(chan int), make(chan int) 1518 defer close(ch2) 1519 runtime.SetFinalizer(obj, func(_ interface{}) { 1520 close(ch1) 1521 <-ch2 1522 }) 1523 obj = nil 1524 for i := 10; i >= 0; i-- { 1525 select { 1526 case <-ch1: 1527 default: 1528 if i == 0 { 1529 t.Fatalf("finalizer did not run") 1530 } 1531 runtime.GC() 1532 } 1533 } 1534 var w strings.Builder 1535 goroutineProf.WriteTo(&w, 1) 1536 prof := w.String() 1537 if !includesFinalizer(prof) { 1538 t.Errorf("profile does not include finalizer (and it should be marked as user):\n%s", prof) 1539 } 1540 }) 1541 1542 // Check that new goroutines only show up in order. 1543 testLaunches := func(t *testing.T) { 1544 var done sync.WaitGroup 1545 defer done.Wait() 1546 1547 ctx := context.Background() 1548 ctx, cancel := context.WithCancel(ctx) 1549 defer cancel() 1550 1551 ch := make(chan int) 1552 defer close(ch) 1553 1554 var ready sync.WaitGroup 1555 1556 // These goroutines all survive until the end of the subtest, so we can 1557 // check that a (numbered) goroutine appearing in the profile implies 1558 // that all older goroutines also appear in the profile. 1559 ready.Add(1) 1560 done.Add(1) 1561 go func() { 1562 defer done.Done() 1563 for i := 0; ctx.Err() == nil; i++ { 1564 // Use SetGoroutineLabels rather than Do we can always expect an 1565 // extra goroutine (this one) with most recent label. 1566 SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-loop-i", fmt.Sprint(i)))) 1567 done.Add(1) 1568 go func() { 1569 <-ch 1570 done.Done() 1571 }() 1572 for j := 0; j < i; j++ { 1573 // Spin for longer and longer as the test goes on. This 1574 // goroutine will do O(N^2) work with the number of 1575 // goroutines it launches. This should be slow relative to 1576 // the work involved in collecting a goroutine profile, 1577 // which is O(N) with the high-water mark of the number of 1578 // goroutines in this process (in the allgs slice). 1579 runtime.Gosched() 1580 } 1581 if i == 0 { 1582 ready.Done() 1583 } 1584 } 1585 }() 1586 1587 // Short-lived goroutines exercise different code paths (goroutines with 1588 // status _Gdead, for instance). This churn doesn't have behavior that 1589 // we can test directly, but does help to shake out data races. 1590 ready.Add(1) 1591 var churn func(i int) 1592 churn = func(i int) { 1593 SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-churn-i", fmt.Sprint(i)))) 1594 if i == 0 { 1595 ready.Done() 1596 } else if i%16 == 0 { 1597 // Yield on occasion so this sequence of goroutine launches 1598 // doesn't monopolize a P. See issue #52934. 1599 runtime.Gosched() 1600 } 1601 if ctx.Err() == nil { 1602 go churn(i + 1) 1603 } 1604 } 1605 go func() { 1606 churn(0) 1607 }() 1608 1609 ready.Wait() 1610 1611 var w [3]bytes.Buffer 1612 for i := range w { 1613 goroutineProf.WriteTo(&w[i], 0) 1614 } 1615 for i := range w { 1616 p, err := profile.Parse(bytes.NewReader(w[i].Bytes())) 1617 if err != nil { 1618 t.Errorf("error parsing protobuf profile: %v", err) 1619 } 1620 1621 // High-numbered loop-i goroutines imply that every lower-numbered 1622 // loop-i goroutine should be present in the profile too. 1623 counts := make(map[string]int) 1624 for _, s := range p.Sample { 1625 label := s.Label[t.Name()+"-loop-i"] 1626 if len(label) > 0 { 1627 counts[label[0]]++ 1628 } 1629 } 1630 for j, max := 0, len(counts)-1; j <= max; j++ { 1631 n := counts[fmt.Sprint(j)] 1632 if n == 1 || (n == 2 && j == max) { 1633 continue 1634 } 1635 t.Errorf("profile #%d's goroutines with label loop-i:%d; %d != 1 (or 2 for the last entry, %d)", 1636 i+1, j, n, max) 1637 t.Logf("counts %v", counts) 1638 break 1639 } 1640 } 1641 } 1642 1643 runs := 100 1644 if testing.Short() { 1645 runs = 5 1646 } 1647 for i := 0; i < runs; i++ { 1648 // Run multiple times to shake out data races 1649 t.Run("goroutine launches", testLaunches) 1650 } 1651 } 1652 1653 func BenchmarkGoroutine(b *testing.B) { 1654 withIdle := func(n int, fn func(b *testing.B)) func(b *testing.B) { 1655 return func(b *testing.B) { 1656 c := make(chan int) 1657 var ready, done sync.WaitGroup 1658 defer func() { 1659 close(c) 1660 done.Wait() 1661 }() 1662 1663 for i := 0; i < n; i++ { 1664 ready.Add(1) 1665 done.Add(1) 1666 go func() { 1667 ready.Done() 1668 <-c 1669 done.Done() 1670 }() 1671 } 1672 // Let goroutines block on channel 1673 ready.Wait() 1674 for i := 0; i < 5; i++ { 1675 runtime.Gosched() 1676 } 1677 1678 fn(b) 1679 } 1680 } 1681 1682 withChurn := func(fn func(b *testing.B)) func(b *testing.B) { 1683 return func(b *testing.B) { 1684 ctx := context.Background() 1685 ctx, cancel := context.WithCancel(ctx) 1686 defer cancel() 1687 1688 var ready sync.WaitGroup 1689 ready.Add(1) 1690 var count int64 1691 var churn func(i int) 1692 churn = func(i int) { 1693 SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i)))) 1694 atomic.AddInt64(&count, 1) 1695 if i == 0 { 1696 ready.Done() 1697 } 1698 if ctx.Err() == nil { 1699 go churn(i + 1) 1700 } 1701 } 1702 go func() { 1703 churn(0) 1704 }() 1705 ready.Wait() 1706 1707 fn(b) 1708 b.ReportMetric(float64(atomic.LoadInt64(&count))/float64(b.N), "concurrent_launches/op") 1709 } 1710 } 1711 1712 benchWriteTo := func(b *testing.B) { 1713 goroutineProf := Lookup("goroutine") 1714 b.ResetTimer() 1715 for i := 0; i < b.N; i++ { 1716 goroutineProf.WriteTo(io.Discard, 0) 1717 } 1718 b.StopTimer() 1719 } 1720 1721 benchGoroutineProfile := func(b *testing.B) { 1722 p := make([]runtime.StackRecord, 10000) 1723 b.ResetTimer() 1724 for i := 0; i < b.N; i++ { 1725 runtime.GoroutineProfile(p) 1726 } 1727 b.StopTimer() 1728 } 1729 1730 // Note that some costs of collecting a goroutine profile depend on the 1731 // length of the runtime.allgs slice, which never shrinks. Stay within race 1732 // detector's 8k-goroutine limit 1733 for _, n := range []int{50, 500, 5000} { 1734 b.Run(fmt.Sprintf("Profile.WriteTo idle %d", n), withIdle(n, benchWriteTo)) 1735 b.Run(fmt.Sprintf("Profile.WriteTo churn %d", n), withIdle(n, withChurn(benchWriteTo))) 1736 b.Run(fmt.Sprintf("runtime.GoroutineProfile churn %d", n), withIdle(n, withChurn(benchGoroutineProfile))) 1737 } 1738 } 1739 1740 var emptyCallStackTestRun int64 1741 1742 // Issue 18836. 1743 func TestEmptyCallStack(t *testing.T) { 1744 name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun) 1745 emptyCallStackTestRun++ 1746 1747 t.Parallel() 1748 var buf strings.Builder 1749 p := NewProfile(name) 1750 1751 p.Add("foo", 47674) 1752 p.WriteTo(&buf, 1) 1753 p.Remove("foo") 1754 got := buf.String() 1755 prefix := name + " profile: total 1\n" 1756 if !strings.HasPrefix(got, prefix) { 1757 t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix) 1758 } 1759 lostevent := "lostProfileEvent" 1760 if !strings.Contains(got, lostevent) { 1761 t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent) 1762 } 1763 } 1764 1765 // stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key 1766 // and value and has funcname somewhere in the stack. 1767 func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool { 1768 base, kv, ok := strings.Cut(spec, ";") 1769 if !ok { 1770 panic("no semicolon in key/value spec") 1771 } 1772 k, v, ok := strings.Cut(kv, "=") 1773 if !ok { 1774 panic("missing = in key/value spec") 1775 } 1776 if !contains(labels[k], v) { 1777 return false 1778 } 1779 return stackContains(base, count, stk, labels) 1780 } 1781 1782 func TestCPUProfileLabel(t *testing.T) { 1783 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions()) 1784 testCPUProfile(t, matches, func(dur time.Duration) { 1785 Do(context.Background(), Labels("key", "value"), func(context.Context) { 1786 cpuHogger(cpuHog1, &salt1, dur) 1787 }) 1788 }) 1789 } 1790 1791 func TestLabelRace(t *testing.T) { 1792 testenv.MustHaveParallelism(t) 1793 // Test the race detector annotations for synchronization 1794 // between setting labels and consuming them from the 1795 // profile. 1796 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil) 1797 testCPUProfile(t, matches, func(dur time.Duration) { 1798 start := time.Now() 1799 var wg sync.WaitGroup 1800 for time.Since(start) < dur { 1801 var salts [10]int 1802 for i := 0; i < 10; i++ { 1803 wg.Add(1) 1804 go func(j int) { 1805 Do(context.Background(), Labels("key", "value"), func(context.Context) { 1806 cpuHogger(cpuHog1, &salts[j], time.Millisecond) 1807 }) 1808 wg.Done() 1809 }(i) 1810 } 1811 wg.Wait() 1812 } 1813 }) 1814 } 1815 1816 func TestGoroutineProfileLabelRace(t *testing.T) { 1817 testenv.MustHaveParallelism(t) 1818 // Test the race detector annotations for synchronization 1819 // between setting labels and consuming them from the 1820 // goroutine profile. See issue #50292. 1821 1822 t.Run("reset", func(t *testing.T) { 1823 ctx := context.Background() 1824 ctx, cancel := context.WithCancel(ctx) 1825 defer cancel() 1826 1827 go func() { 1828 goroutineProf := Lookup("goroutine") 1829 for ctx.Err() == nil { 1830 var w strings.Builder 1831 goroutineProf.WriteTo(&w, 1) 1832 prof := w.String() 1833 if strings.Contains(prof, "loop-i") { 1834 cancel() 1835 } 1836 } 1837 }() 1838 1839 for i := 0; ctx.Err() == nil; i++ { 1840 Do(ctx, Labels("loop-i", fmt.Sprint(i)), func(ctx context.Context) { 1841 }) 1842 } 1843 }) 1844 1845 t.Run("churn", func(t *testing.T) { 1846 ctx := context.Background() 1847 ctx, cancel := context.WithCancel(ctx) 1848 defer cancel() 1849 1850 var ready sync.WaitGroup 1851 ready.Add(1) 1852 var churn func(i int) 1853 churn = func(i int) { 1854 SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i)))) 1855 if i == 0 { 1856 ready.Done() 1857 } 1858 if ctx.Err() == nil { 1859 go churn(i + 1) 1860 } 1861 } 1862 go func() { 1863 churn(0) 1864 }() 1865 ready.Wait() 1866 1867 goroutineProf := Lookup("goroutine") 1868 for i := 0; i < 10; i++ { 1869 goroutineProf.WriteTo(io.Discard, 1) 1870 } 1871 }) 1872 } 1873 1874 // TestLabelSystemstack makes sure CPU profiler samples of goroutines running 1875 // on systemstack include the correct pprof labels. See issue #48577 1876 func TestLabelSystemstack(t *testing.T) { 1877 // Grab and re-set the initial value before continuing to ensure 1878 // GOGC doesn't actually change following the test. 1879 gogc := debug.SetGCPercent(100) 1880 debug.SetGCPercent(gogc) 1881 1882 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions()) 1883 p := testCPUProfile(t, matches, func(dur time.Duration) { 1884 Do(context.Background(), Labels("key", "value"), func(ctx context.Context) { 1885 parallelLabelHog(ctx, dur, gogc) 1886 }) 1887 }) 1888 1889 // Two conditions to check: 1890 // * labelHog should always be labeled. 1891 // * The label should _only_ appear on labelHog and the Do call above. 1892 for _, s := range p.Sample { 1893 isLabeled := s.Label != nil && contains(s.Label["key"], "value") 1894 var ( 1895 mayBeLabeled bool 1896 mustBeLabeled string 1897 mustNotBeLabeled string 1898 ) 1899 for _, loc := range s.Location { 1900 for _, l := range loc.Line { 1901 switch l.Function.Name { 1902 case "runtime/pprof.labelHog", "runtime/pprof.parallelLabelHog", "runtime/pprof.parallelLabelHog.func1": 1903 mustBeLabeled = l.Function.Name 1904 case "runtime/pprof.Do": 1905 // Do sets the labels, so samples may 1906 // or may not be labeled depending on 1907 // which part of the function they are 1908 // at. 1909 mayBeLabeled = true 1910 case "runtime.bgsweep", "runtime.bgscavenge", "runtime.forcegchelper", "runtime.gcBgMarkWorker", "runtime.runfinq", "runtime.sysmon": 1911 // Runtime system goroutines or threads 1912 // (such as those identified by 1913 // runtime.isSystemGoroutine). These 1914 // should never be labeled. 1915 mustNotBeLabeled = l.Function.Name 1916 case "gogo", "gosave_systemstack_switch", "racecall": 1917 // These are context switch/race 1918 // critical that we can't do a full 1919 // traceback from. Typically this would 1920 // be covered by the runtime check 1921 // below, but these symbols don't have 1922 // the package name. 1923 mayBeLabeled = true 1924 } 1925 1926 if strings.HasPrefix(l.Function.Name, "runtime.") { 1927 // There are many places in the runtime 1928 // where we can't do a full traceback. 1929 // Ideally we'd list them all, but 1930 // barring that allow anything in the 1931 // runtime, unless explicitly excluded 1932 // above. 1933 mayBeLabeled = true 1934 } 1935 } 1936 } 1937 errorStack := func(f string, args ...any) { 1938 var buf strings.Builder 1939 fprintStack(&buf, s.Location) 1940 t.Errorf("%s: %s", fmt.Sprintf(f, args...), buf.String()) 1941 } 1942 if mustBeLabeled != "" && mustNotBeLabeled != "" { 1943 errorStack("sample contains both %s, which must be labeled, and %s, which must not be labeled", mustBeLabeled, mustNotBeLabeled) 1944 continue 1945 } 1946 if mustBeLabeled != "" || mustNotBeLabeled != "" { 1947 // We found a definitive frame, so mayBeLabeled hints are not relevant. 1948 mayBeLabeled = false 1949 } 1950 if mayBeLabeled { 1951 // This sample may or may not be labeled, so there's nothing we can check. 1952 continue 1953 } 1954 if mustBeLabeled != "" && !isLabeled { 1955 errorStack("sample must be labeled because of %s, but is not", mustBeLabeled) 1956 } 1957 if mustNotBeLabeled != "" && isLabeled { 1958 errorStack("sample must not be labeled because of %s, but is", mustNotBeLabeled) 1959 } 1960 } 1961 } 1962 1963 // labelHog is designed to burn CPU time in a way that a high number of CPU 1964 // samples end up running on systemstack. 1965 func labelHog(stop chan struct{}, gogc int) { 1966 // Regression test for issue 50032. We must give GC an opportunity to 1967 // be initially triggered by a labelled goroutine. 1968 runtime.GC() 1969 1970 for i := 0; ; i++ { 1971 select { 1972 case <-stop: 1973 return 1974 default: 1975 debug.SetGCPercent(gogc) 1976 } 1977 } 1978 } 1979 1980 // parallelLabelHog runs GOMAXPROCS goroutines running labelHog. 1981 func parallelLabelHog(ctx context.Context, dur time.Duration, gogc int) { 1982 var wg sync.WaitGroup 1983 stop := make(chan struct{}) 1984 for i := 0; i < runtime.GOMAXPROCS(0); i++ { 1985 wg.Add(1) 1986 go func() { 1987 defer wg.Done() 1988 labelHog(stop, gogc) 1989 }() 1990 } 1991 1992 time.Sleep(dur) 1993 close(stop) 1994 wg.Wait() 1995 } 1996 1997 // Check that there is no deadlock when the program receives SIGPROF while in 1998 // 64bit atomics' critical section. Used to happen on mips{,le}. See #20146. 1999 func TestAtomicLoadStore64(t *testing.T) { 2000 f, err := os.CreateTemp("", "profatomic") 2001 if err != nil { 2002 t.Fatalf("TempFile: %v", err) 2003 } 2004 defer os.Remove(f.Name()) 2005 defer f.Close() 2006 2007 if err := StartCPUProfile(f); err != nil { 2008 t.Fatal(err) 2009 } 2010 defer StopCPUProfile() 2011 2012 var flag uint64 2013 done := make(chan bool, 1) 2014 2015 go func() { 2016 for atomic.LoadUint64(&flag) == 0 { 2017 runtime.Gosched() 2018 } 2019 done <- true 2020 }() 2021 time.Sleep(50 * time.Millisecond) 2022 atomic.StoreUint64(&flag, 1) 2023 <-done 2024 } 2025 2026 func TestTracebackAll(t *testing.T) { 2027 // With gccgo, if a profiling signal arrives at the wrong time 2028 // during traceback, it may crash or hang. See issue #29448. 2029 f, err := os.CreateTemp("", "proftraceback") 2030 if err != nil { 2031 t.Fatalf("TempFile: %v", err) 2032 } 2033 defer os.Remove(f.Name()) 2034 defer f.Close() 2035 2036 if err := StartCPUProfile(f); err != nil { 2037 t.Fatal(err) 2038 } 2039 defer StopCPUProfile() 2040 2041 ch := make(chan int) 2042 defer close(ch) 2043 2044 count := 10 2045 for i := 0; i < count; i++ { 2046 go func() { 2047 <-ch // block 2048 }() 2049 } 2050 2051 N := 10000 2052 if testing.Short() { 2053 N = 500 2054 } 2055 buf := make([]byte, 10*1024) 2056 for i := 0; i < N; i++ { 2057 runtime.Stack(buf, true) 2058 } 2059 } 2060 2061 // TestTryAdd tests the cases that are hard to test with real program execution. 2062 // 2063 // For example, the current go compilers may not always inline functions 2064 // involved in recursion but that may not be true in the future compilers. This 2065 // tests such cases by using fake call sequences and forcing the profile build 2066 // utilizing translateCPUProfile defined in proto_test.go 2067 func TestTryAdd(t *testing.T) { 2068 if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found { 2069 t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.") 2070 } 2071 2072 // inlinedCallerDump 2073 // inlinedCalleeDump 2074 pcs := make([]uintptr, 2) 2075 inlinedCallerDump(pcs) 2076 inlinedCallerStack := make([]uint64, 2) 2077 for i := range pcs { 2078 inlinedCallerStack[i] = uint64(pcs[i]) 2079 } 2080 wrapperPCs := make([]uintptr, 1) 2081 inlinedWrapperCallerDump(wrapperPCs) 2082 2083 if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found { 2084 t.Skip("Can't determine whether anything was inlined into recursionChainBottom.") 2085 } 2086 2087 // recursionChainTop 2088 // recursionChainMiddle 2089 // recursionChainBottom 2090 // recursionChainTop 2091 // recursionChainMiddle 2092 // recursionChainBottom 2093 pcs = make([]uintptr, 6) 2094 recursionChainTop(1, pcs) 2095 recursionStack := make([]uint64, len(pcs)) 2096 for i := range pcs { 2097 recursionStack[i] = uint64(pcs[i]) 2098 } 2099 2100 period := int64(2000 * 1000) // 1/500*1e9 nanosec. 2101 2102 testCases := []struct { 2103 name string 2104 input []uint64 // following the input format assumed by profileBuilder.addCPUData. 2105 count int // number of records in input. 2106 wantLocs [][]string // ordered location entries with function names. 2107 wantSamples []*profile.Sample // ordered samples, we care only about Value and the profile location IDs. 2108 }{{ 2109 // Sanity test for a normal, complete stack trace. 2110 name: "full_stack_trace", 2111 input: []uint64{ 2112 3, 0, 500, // hz = 500. Must match the period. 2113 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1], 2114 }, 2115 count: 2, 2116 wantLocs: [][]string{ 2117 {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}, 2118 }, 2119 wantSamples: []*profile.Sample{ 2120 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}}, 2121 }, 2122 }, { 2123 name: "bug35538", 2124 input: []uint64{ 2125 3, 0, 500, // hz = 500. Must match the period. 2126 // Fake frame: tryAdd will have inlinedCallerDump 2127 // (stack[1]) on the deck when it encounters the next 2128 // inline function. It should accept this. 2129 7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1], 2130 5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1], 2131 }, 2132 count: 3, 2133 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 2134 wantSamples: []*profile.Sample{ 2135 {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}}, 2136 {Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}}, 2137 }, 2138 }, { 2139 name: "bug38096", 2140 input: []uint64{ 2141 3, 0, 500, // hz = 500. Must match the period. 2142 // count (data[2]) == 0 && len(stk) == 1 is an overflow 2143 // entry. The "stk" entry is actually the count. 2144 4, 0, 0, 4242, 2145 }, 2146 count: 2, 2147 wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}}, 2148 wantSamples: []*profile.Sample{ 2149 {Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}}, 2150 }, 2151 }, { 2152 // If a function is directly called recursively then it must 2153 // not be inlined in the caller. 2154 // 2155 // N.B. We're generating an impossible profile here, with a 2156 // recursive inlineCalleeDump call. This is simulating a non-Go 2157 // function that looks like an inlined Go function other than 2158 // its recursive property. See pcDeck.tryAdd. 2159 name: "directly_recursive_func_is_not_inlined", 2160 input: []uint64{ 2161 3, 0, 500, // hz = 500. Must match the period. 2162 5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0], 2163 4, 0, 40, inlinedCallerStack[0], 2164 }, 2165 count: 3, 2166 // inlinedCallerDump shows up here because 2167 // runtime_expandFinalInlineFrame adds it to the stack frame. 2168 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}}, 2169 wantSamples: []*profile.Sample{ 2170 {Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}}, 2171 {Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}}, 2172 }, 2173 }, { 2174 name: "recursion_chain_inline", 2175 input: []uint64{ 2176 3, 0, 500, // hz = 500. Must match the period. 2177 9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5], 2178 }, 2179 count: 2, 2180 wantLocs: [][]string{ 2181 {"runtime/pprof.recursionChainBottom"}, 2182 { 2183 "runtime/pprof.recursionChainMiddle", 2184 "runtime/pprof.recursionChainTop", 2185 "runtime/pprof.recursionChainBottom", 2186 }, 2187 { 2188 "runtime/pprof.recursionChainMiddle", 2189 "runtime/pprof.recursionChainTop", 2190 "runtime/pprof.TestTryAdd", // inlined into the test. 2191 }, 2192 }, 2193 wantSamples: []*profile.Sample{ 2194 {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}}, 2195 }, 2196 }, { 2197 name: "truncated_stack_trace_later", 2198 input: []uint64{ 2199 3, 0, 500, // hz = 500. Must match the period. 2200 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1], 2201 4, 0, 60, inlinedCallerStack[0], 2202 }, 2203 count: 3, 2204 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 2205 wantSamples: []*profile.Sample{ 2206 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}}, 2207 {Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}}, 2208 }, 2209 }, { 2210 name: "truncated_stack_trace_first", 2211 input: []uint64{ 2212 3, 0, 500, // hz = 500. Must match the period. 2213 4, 0, 70, inlinedCallerStack[0], 2214 5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1], 2215 }, 2216 count: 3, 2217 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 2218 wantSamples: []*profile.Sample{ 2219 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}}, 2220 {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}}, 2221 }, 2222 }, { 2223 // We can recover the inlined caller from a truncated stack. 2224 name: "truncated_stack_trace_only", 2225 input: []uint64{ 2226 3, 0, 500, // hz = 500. Must match the period. 2227 4, 0, 70, inlinedCallerStack[0], 2228 }, 2229 count: 2, 2230 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}}, 2231 wantSamples: []*profile.Sample{ 2232 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}}, 2233 }, 2234 }, { 2235 // The same location is used for duplicated stacks. 2236 name: "truncated_stack_trace_twice", 2237 input: []uint64{ 2238 3, 0, 500, // hz = 500. Must match the period. 2239 4, 0, 70, inlinedCallerStack[0], 2240 // Fake frame: add a fake call to 2241 // inlinedCallerDump to prevent this sample 2242 // from getting merged into above. 2243 5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0], 2244 }, 2245 count: 3, 2246 wantLocs: [][]string{ 2247 {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}, 2248 {"runtime/pprof.inlinedCallerDump"}, 2249 }, 2250 wantSamples: []*profile.Sample{ 2251 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}}, 2252 {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}}, 2253 }, 2254 }, { 2255 name: "expand_wrapper_function", 2256 input: []uint64{ 2257 3, 0, 500, // hz = 500. Must match the period. 2258 4, 0, 50, uint64(wrapperPCs[0]), 2259 }, 2260 count: 2, 2261 wantLocs: [][]string{{"runtime/pprof.inlineWrapper.dump"}}, 2262 wantSamples: []*profile.Sample{ 2263 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}}, 2264 }, 2265 }} 2266 2267 for _, tc := range testCases { 2268 t.Run(tc.name, func(t *testing.T) { 2269 p, err := translateCPUProfile(tc.input, tc.count) 2270 if err != nil { 2271 t.Fatalf("translating profile: %v", err) 2272 } 2273 t.Logf("Profile: %v\n", p) 2274 2275 // One location entry with all inlined functions. 2276 var gotLoc [][]string 2277 for _, loc := range p.Location { 2278 var names []string 2279 for _, line := range loc.Line { 2280 names = append(names, line.Function.Name) 2281 } 2282 gotLoc = append(gotLoc, names) 2283 } 2284 if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want { 2285 t.Errorf("Got Location = %+v\n\twant %+v", got, want) 2286 } 2287 // All samples should point to one location. 2288 var gotSamples []*profile.Sample 2289 for _, sample := range p.Sample { 2290 var locs []*profile.Location 2291 for _, loc := range sample.Location { 2292 locs = append(locs, &profile.Location{ID: loc.ID}) 2293 } 2294 gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs}) 2295 } 2296 if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want { 2297 t.Errorf("Got Samples = %+v\n\twant %+v", got, want) 2298 } 2299 }) 2300 } 2301 } 2302 2303 func TestTimeVDSO(t *testing.T) { 2304 // Test that time functions have the right stack trace. In particular, 2305 // it shouldn't be recursive. 2306 2307 if runtime.GOOS == "android" { 2308 // Flaky on Android, issue 48655. VDSO may not be enabled. 2309 testenv.SkipFlaky(t, 48655) 2310 } 2311 2312 matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions()) 2313 p := testCPUProfile(t, matches, func(dur time.Duration) { 2314 t0 := time.Now() 2315 for { 2316 t := time.Now() 2317 if t.Sub(t0) >= dur { 2318 return 2319 } 2320 } 2321 }) 2322 2323 // Check for recursive time.now sample. 2324 for _, sample := range p.Sample { 2325 var seenNow bool 2326 for _, loc := range sample.Location { 2327 for _, line := range loc.Line { 2328 if line.Function.Name == "time.now" { 2329 if seenNow { 2330 t.Fatalf("unexpected recursive time.now") 2331 } 2332 seenNow = true 2333 } 2334 } 2335 } 2336 } 2337 }