summaryrefslogtreecommitdiffstats
path: root/src/runtime/pprof/pprof_test.go
diff options
context:
space:
mode:
authorDaniel Baumann <daniel.baumann@progress-linux.org>2024-04-16 19:25:22 +0000
committerDaniel Baumann <daniel.baumann@progress-linux.org>2024-04-16 19:25:22 +0000
commitf6ad4dcef54c5ce997a4bad5a6d86de229015700 (patch)
tree7cfa4e31ace5c2bd95c72b154d15af494b2bcbef /src/runtime/pprof/pprof_test.go
parentInitial commit. (diff)
downloadgolang-1.22-f6ad4dcef54c5ce997a4bad5a6d86de229015700.tar.xz
golang-1.22-f6ad4dcef54c5ce997a4bad5a6d86de229015700.zip
Adding upstream version 1.22.1.upstream/1.22.1
Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>
Diffstat (limited to '')
-rw-r--r--src/runtime/pprof/pprof_test.go2429
1 files changed, 2429 insertions, 0 deletions
diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go
new file mode 100644
index 0000000..6b299e5
--- /dev/null
+++ b/src/runtime/pprof/pprof_test.go
@@ -0,0 +1,2429 @@
+// Copyright 2011 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+//go:build !js
+
+package pprof
+
+import (
+ "bytes"
+ "context"
+ "fmt"
+ "internal/abi"
+ "internal/profile"
+ "internal/syscall/unix"
+ "internal/testenv"
+ "io"
+ "math"
+ "math/big"
+ "os"
+ "regexp"
+ "runtime"
+ "runtime/debug"
+ "strings"
+ "sync"
+ "sync/atomic"
+ "testing"
+ "time"
+ _ "unsafe"
+)
+
+func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
+ // We only need to get one 100 Hz clock tick, so we've got
+ // a large safety buffer.
+ // But do at least 500 iterations (which should take about 100ms),
+ // otherwise TestCPUProfileMultithreaded can fail if only one
+ // thread is scheduled during the testing period.
+ t0 := time.Now()
+ accum := *y
+ for i := 0; i < 500 || time.Since(t0) < dur; i++ {
+ accum = f(accum)
+ }
+ *y = accum
+}
+
+var (
+ salt1 = 0
+ salt2 = 0
+)
+
+// The actual CPU hogging function.
+// Must not call other functions nor access heap/globals in the loop,
+// otherwise under race detector the samples will be in the race runtime.
+func cpuHog1(x int) int {
+ return cpuHog0(x, 1e5)
+}
+
+func cpuHog0(x, n int) int {
+ foo := x
+ for i := 0; i < n; i++ {
+ if foo > 0 {
+ foo *= foo
+ } else {
+ foo *= foo + 1
+ }
+ }
+ return foo
+}
+
+func cpuHog2(x int) int {
+ foo := x
+ for i := 0; i < 1e5; i++ {
+ if foo > 0 {
+ foo *= foo
+ } else {
+ foo *= foo + 2
+ }
+ }
+ return foo
+}
+
+// Return a list of functions that we don't want to ever appear in CPU
+// profiles. For gccgo, that list includes the sigprof handler itself.
+func avoidFunctions() []string {
+ if runtime.Compiler == "gccgo" {
+ return []string{"runtime.sigprof"}
+ }
+ return nil
+}
+
+func TestCPUProfile(t *testing.T) {
+ matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
+ testCPUProfile(t, matches, func(dur time.Duration) {
+ cpuHogger(cpuHog1, &salt1, dur)
+ })
+}
+
+func TestCPUProfileMultithreaded(t *testing.T) {
+ defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
+ matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions())
+ testCPUProfile(t, matches, func(dur time.Duration) {
+ c := make(chan int)
+ go func() {
+ cpuHogger(cpuHog1, &salt1, dur)
+ c <- 1
+ }()
+ cpuHogger(cpuHog2, &salt2, dur)
+ <-c
+ })
+}
+
+func TestCPUProfileMultithreadMagnitude(t *testing.T) {
+ if runtime.GOOS != "linux" {
+ t.Skip("issue 35057 is only confirmed on Linux")
+ }
+
+ // Linux [5.9,5.16) has a kernel bug that can break CPU timers on newly
+ // created threads, breaking our CPU accounting.
+ major, minor := unix.KernelVersion()
+ t.Logf("Running on Linux %d.%d", major, minor)
+ defer func() {
+ if t.Failed() {
+ 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.")
+ }
+ }()
+
+ // Disable on affected builders to avoid flakiness, but otherwise keep
+ // it enabled to potentially warn users that they are on a broken
+ // kernel.
+ if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") {
+ have59 := major > 5 || (major == 5 && minor >= 9)
+ have516 := major > 5 || (major == 5 && minor >= 16)
+ if have59 && !have516 {
+ testenv.SkipFlaky(t, 49065)
+ }
+ }
+
+ // Run a workload in a single goroutine, then run copies of the same
+ // workload in several goroutines. For both the serial and parallel cases,
+ // the CPU time the process measures with its own profiler should match the
+ // total CPU usage that the OS reports.
+ //
+ // We could also check that increases in parallelism (GOMAXPROCS) lead to a
+ // linear increase in the CPU usage reported by both the OS and the
+ // profiler, but without a guarantee of exclusive access to CPU resources
+ // that is likely to be a flaky test.
+
+ // Require the smaller value to be within 10%, or 40% in short mode.
+ maxDiff := 0.10
+ if testing.Short() {
+ maxDiff = 0.40
+ }
+
+ compare := func(a, b time.Duration, maxDiff float64) error {
+ if a <= 0 || b <= 0 {
+ return fmt.Errorf("Expected both time reports to be positive")
+ }
+
+ if a < b {
+ a, b = b, a
+ }
+
+ diff := float64(a-b) / float64(a)
+ if diff > maxDiff {
+ return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100)
+ }
+
+ return nil
+ }
+
+ for _, tc := range []struct {
+ name string
+ workers int
+ }{
+ {
+ name: "serial",
+ workers: 1,
+ },
+ {
+ name: "parallel",
+ workers: runtime.GOMAXPROCS(0),
+ },
+ } {
+ // check that the OS's perspective matches what the Go runtime measures.
+ t.Run(tc.name, func(t *testing.T) {
+ t.Logf("Running with %d workers", tc.workers)
+
+ var userTime, systemTime time.Duration
+ matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
+ acceptProfile := func(t *testing.T, p *profile.Profile) bool {
+ if !matches(t, p) {
+ return false
+ }
+
+ ok := true
+ for i, unit := range []string{"count", "nanoseconds"} {
+ if have, want := p.SampleType[i].Unit, unit; have != want {
+ t.Logf("pN SampleType[%d]; %q != %q", i, have, want)
+ ok = false
+ }
+ }
+
+ // cpuHog1 called below is the primary source of CPU
+ // load, but there may be some background work by the
+ // runtime. Since the OS rusage measurement will
+ // include all work done by the process, also compare
+ // against all samples in our profile.
+ var value time.Duration
+ for _, sample := range p.Sample {
+ value += time.Duration(sample.Value[1]) * time.Nanosecond
+ }
+
+ totalTime := userTime + systemTime
+ t.Logf("compare %s user + %s system = %s vs %s", userTime, systemTime, totalTime, value)
+ if err := compare(totalTime, value, maxDiff); err != nil {
+ t.Logf("compare got %v want nil", err)
+ ok = false
+ }
+
+ return ok
+ }
+
+ testCPUProfile(t, acceptProfile, func(dur time.Duration) {
+ userTime, systemTime = diffCPUTime(t, func() {
+ var wg sync.WaitGroup
+ var once sync.Once
+ for i := 0; i < tc.workers; i++ {
+ wg.Add(1)
+ go func() {
+ defer wg.Done()
+ var salt = 0
+ cpuHogger(cpuHog1, &salt, dur)
+ once.Do(func() { salt1 = salt })
+ }()
+ }
+ wg.Wait()
+ })
+ })
+ })
+ }
+}
+
+// containsInlinedCall reports whether the function body for the function f is
+// known to contain an inlined function call within the first maxBytes bytes.
+func containsInlinedCall(f any, maxBytes int) bool {
+ _, found := findInlinedCall(f, maxBytes)
+ return found
+}
+
+// findInlinedCall returns the PC of an inlined function call within
+// the function body for the function f if any.
+func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) {
+ fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f)))
+ if fFunc == nil || fFunc.Entry() == 0 {
+ panic("failed to locate function entry")
+ }
+
+ for offset := 0; offset < maxBytes; offset++ {
+ innerPC := fFunc.Entry() + uintptr(offset)
+ inner := runtime.FuncForPC(innerPC)
+ if inner == nil {
+ // No function known for this PC value.
+ // It might simply be misaligned, so keep searching.
+ continue
+ }
+ if inner.Entry() != fFunc.Entry() {
+ // Scanned past f and didn't find any inlined functions.
+ break
+ }
+ if inner.Name() != fFunc.Name() {
+ // This PC has f as its entry-point, but is not f. Therefore, it must be a
+ // function inlined into f.
+ return uint64(innerPC), true
+ }
+ }
+
+ return 0, false
+}
+
+func TestCPUProfileInlining(t *testing.T) {
+ if !containsInlinedCall(inlinedCaller, 4<<10) {
+ t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.")
+ }
+
+ matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions())
+ p := testCPUProfile(t, matches, func(dur time.Duration) {
+ cpuHogger(inlinedCaller, &salt1, dur)
+ })
+
+ // Check if inlined function locations are encoded correctly. The inlinedCalee and inlinedCaller should be in one location.
+ for _, loc := range p.Location {
+ hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false
+ for _, line := range loc.Line {
+ if line.Function.Name == "runtime/pprof.inlinedCallee" {
+ hasInlinedCallee = true
+ }
+ if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" {
+ hasInlinedCallerAfterInlinedCallee = true
+ }
+ }
+ if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee {
+ t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p)
+ }
+ }
+}
+
+func inlinedCaller(x int) int {
+ x = inlinedCallee(x, 1e5)
+ return x
+}
+
+func inlinedCallee(x, n int) int {
+ return cpuHog0(x, n)
+}
+
+//go:noinline
+func dumpCallers(pcs []uintptr) {
+ if pcs == nil {
+ return
+ }
+
+ skip := 2 // Callers and dumpCallers
+ runtime.Callers(skip, pcs)
+}
+
+//go:noinline
+func inlinedCallerDump(pcs []uintptr) {
+ inlinedCalleeDump(pcs)
+}
+
+func inlinedCalleeDump(pcs []uintptr) {
+ dumpCallers(pcs)
+}
+
+type inlineWrapperInterface interface {
+ dump(stack []uintptr)
+}
+
+type inlineWrapper struct {
+}
+
+func (h inlineWrapper) dump(pcs []uintptr) {
+ dumpCallers(pcs)
+}
+
+func inlinedWrapperCallerDump(pcs []uintptr) {
+ var h inlineWrapperInterface
+ h = &inlineWrapper{}
+ h.dump(pcs)
+}
+
+func TestCPUProfileRecursion(t *testing.T) {
+ matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions())
+ p := testCPUProfile(t, matches, func(dur time.Duration) {
+ cpuHogger(recursionCaller, &salt1, dur)
+ })
+
+ // check the Location encoding was not confused by recursive calls.
+ for i, loc := range p.Location {
+ recursionFunc := 0
+ for _, line := range loc.Line {
+ if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" {
+ recursionFunc++
+ }
+ }
+ if recursionFunc > 1 {
+ t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p)
+ }
+ }
+}
+
+func recursionCaller(x int) int {
+ y := recursionCallee(3, x)
+ return y
+}
+
+func recursionCallee(n, x int) int {
+ if n == 0 {
+ return 1
+ }
+ y := inlinedCallee(x, 1e4)
+ return y * recursionCallee(n-1, x)
+}
+
+func recursionChainTop(x int, pcs []uintptr) {
+ if x < 0 {
+ return
+ }
+ recursionChainMiddle(x, pcs)
+}
+
+func recursionChainMiddle(x int, pcs []uintptr) {
+ recursionChainBottom(x, pcs)
+}
+
+func recursionChainBottom(x int, pcs []uintptr) {
+ // This will be called each time, we only care about the last. We
+ // can't make this conditional or this function won't be inlined.
+ dumpCallers(pcs)
+
+ recursionChainTop(x-1, pcs)
+}
+
+func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile {
+ p, err := profile.Parse(bytes.NewReader(valBytes))
+ if err != nil {
+ t.Fatal(err)
+ }
+ for _, sample := range p.Sample {
+ count := uintptr(sample.Value[0])
+ f(count, sample.Location, sample.Label)
+ }
+ return p
+}
+
+func cpuProfilingBroken() bool {
+ switch runtime.GOOS {
+ case "plan9":
+ // Profiling unimplemented.
+ return true
+ case "aix":
+ // See https://golang.org/issue/45170.
+ return true
+ case "ios", "dragonfly", "netbsd", "illumos", "solaris":
+ // See https://golang.org/issue/13841.
+ return true
+ case "openbsd":
+ if runtime.GOARCH == "arm" || runtime.GOARCH == "arm64" {
+ // See https://golang.org/issue/13841.
+ return true
+ }
+ }
+
+ return false
+}
+
+// testCPUProfile runs f under the CPU profiler, checking for some conditions specified by need,
+// as interpreted by matches, and returns the parsed profile.
+func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile {
+ switch runtime.GOOS {
+ case "darwin":
+ out, err := testenv.Command(t, "uname", "-a").CombinedOutput()
+ if err != nil {
+ t.Fatal(err)
+ }
+ vers := string(out)
+ t.Logf("uname -a: %v", vers)
+ case "plan9":
+ t.Skip("skipping on plan9")
+ case "wasip1":
+ t.Skip("skipping on wasip1")
+ }
+
+ broken := cpuProfilingBroken()
+
+ deadline, ok := t.Deadline()
+ if broken || !ok {
+ if broken && testing.Short() {
+ // If it's expected to be broken, no point waiting around.
+ deadline = time.Now().Add(1 * time.Second)
+ } else {
+ deadline = time.Now().Add(10 * time.Second)
+ }
+ }
+
+ // If we're running a long test, start with a long duration
+ // for tests that try to make sure something *doesn't* happen.
+ duration := 5 * time.Second
+ if testing.Short() {
+ duration = 100 * time.Millisecond
+ }
+
+ // Profiling tests are inherently flaky, especially on a
+ // loaded system, such as when this test is running with
+ // several others under go test std. If a test fails in a way
+ // that could mean it just didn't run long enough, try with a
+ // longer duration.
+ for {
+ var prof bytes.Buffer
+ if err := StartCPUProfile(&prof); err != nil {
+ t.Fatal(err)
+ }
+ f(duration)
+ StopCPUProfile()
+
+ if p, ok := profileOk(t, matches, prof, duration); ok {
+ return p
+ }
+
+ duration *= 2
+ if time.Until(deadline) < duration {
+ break
+ }
+ t.Logf("retrying with %s duration", duration)
+ }
+
+ if broken {
+ t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH)
+ }
+
+ // Ignore the failure if the tests are running in a QEMU-based emulator,
+ // QEMU is not perfect at emulating everything.
+ // IN_QEMU environmental variable is set by some of the Go builders.
+ // IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
+ if os.Getenv("IN_QEMU") == "1" {
+ t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
+ }
+ t.FailNow()
+ return nil
+}
+
+var diffCPUTimeImpl func(f func()) (user, system time.Duration)
+
+func diffCPUTime(t *testing.T, f func()) (user, system time.Duration) {
+ if fn := diffCPUTimeImpl; fn != nil {
+ return fn(f)
+ }
+ t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH)
+ return 0, 0
+}
+
+func contains(slice []string, s string) bool {
+ for i := range slice {
+ if slice[i] == s {
+ return true
+ }
+ }
+ return false
+}
+
+// stackContains matches if a function named spec appears anywhere in the stack trace.
+func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
+ for _, loc := range stk {
+ for _, line := range loc.Line {
+ if strings.Contains(line.Function.Name, spec) {
+ return true
+ }
+ }
+ }
+ return false
+}
+
+type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool
+
+func profileOk(t *testing.T, matches profileMatchFunc, prof bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) {
+ ok = true
+
+ var samples uintptr
+ var buf strings.Builder
+ p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) {
+ fmt.Fprintf(&buf, "%d:", count)
+ fprintStack(&buf, stk)
+ fmt.Fprintf(&buf, " labels: %v\n", labels)
+ samples += count
+ fmt.Fprintf(&buf, "\n")
+ })
+ t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String())
+
+ if samples < 10 && runtime.GOOS == "windows" {
+ // On some windows machines we end up with
+ // not enough samples due to coarse timer
+ // resolution. Let it go.
+ t.Log("too few samples on Windows (golang.org/issue/10842)")
+ return p, false
+ }
+
+ // Check that we got a reasonable number of samples.
+ // We used to always require at least ideal/4 samples,
+ // but that is too hard to guarantee on a loaded system.
+ // Now we accept 10 or more samples, which we take to be
+ // enough to show that at least some profiling is occurring.
+ if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) {
+ t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
+ ok = false
+ }
+
+ if matches != nil && !matches(t, p) {
+ ok = false
+ }
+
+ return p, ok
+}
+
+type profileMatchFunc func(*testing.T, *profile.Profile) bool
+
+func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc {
+ return func(t *testing.T, p *profile.Profile) (ok bool) {
+ ok = true
+
+ // Check that profile is well formed, contains 'need', and does not contain
+ // anything from 'avoid'.
+ have := make([]uintptr, len(need))
+ avoidSamples := make([]uintptr, len(avoid))
+
+ for _, sample := range p.Sample {
+ count := uintptr(sample.Value[0])
+ for i, spec := range need {
+ if matches(spec, count, sample.Location, sample.Label) {
+ have[i] += count
+ }
+ }
+ for i, name := range avoid {
+ for _, loc := range sample.Location {
+ for _, line := range loc.Line {
+ if strings.Contains(line.Function.Name, name) {
+ avoidSamples[i] += count
+ }
+ }
+ }
+ }
+ }
+
+ for i, name := range avoid {
+ bad := avoidSamples[i]
+ if bad != 0 {
+ t.Logf("found %d samples in avoid-function %s\n", bad, name)
+ ok = false
+ }
+ }
+
+ if len(need) == 0 {
+ return
+ }
+
+ var total uintptr
+ for i, name := range need {
+ total += have[i]
+ t.Logf("found %d samples in expected function %s\n", have[i], name)
+ }
+ if total == 0 {
+ t.Logf("no samples in expected functions")
+ ok = false
+ }
+
+ // We'd like to check a reasonable minimum, like
+ // total / len(have) / smallconstant, but this test is
+ // pretty flaky (see bug 7095). So we'll just test to
+ // make sure we got at least one sample.
+ min := uintptr(1)
+ for i, name := range need {
+ if have[i] < min {
+ t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
+ ok = false
+ }
+ }
+ return
+ }
+}
+
+// Fork can hang if preempted with signals frequently enough (see issue 5517).
+// Ensure that we do not do this.
+func TestCPUProfileWithFork(t *testing.T) {
+ testenv.MustHaveExec(t)
+
+ exe, err := os.Executable()
+ if err != nil {
+ t.Fatal(err)
+ }
+
+ heap := 1 << 30
+ if runtime.GOOS == "android" {
+ // Use smaller size for Android to avoid crash.
+ heap = 100 << 20
+ }
+ if runtime.GOOS == "windows" && runtime.GOARCH == "arm" {
+ // Use smaller heap for Windows/ARM to avoid crash.
+ heap = 100 << 20
+ }
+ if testing.Short() {
+ heap = 100 << 20
+ }
+ // This makes fork slower.
+ garbage := make([]byte, heap)
+ // Need to touch the slice, otherwise it won't be paged in.
+ done := make(chan bool)
+ go func() {
+ for i := range garbage {
+ garbage[i] = 42
+ }
+ done <- true
+ }()
+ <-done
+
+ var prof bytes.Buffer
+ if err := StartCPUProfile(&prof); err != nil {
+ t.Fatal(err)
+ }
+ defer StopCPUProfile()
+
+ for i := 0; i < 10; i++ {
+ testenv.Command(t, exe, "-h").CombinedOutput()
+ }
+}
+
+// Test that profiler does not observe runtime.gogo as "user" goroutine execution.
+// If it did, it would see inconsistent state and would either record an incorrect stack
+// or crash because the stack was malformed.
+func TestGoroutineSwitch(t *testing.T) {
+ if runtime.Compiler == "gccgo" {
+ t.Skip("not applicable for gccgo")
+ }
+ // How much to try. These defaults take about 1 seconds
+ // on a 2012 MacBook Pro. The ones in short mode take
+ // about 0.1 seconds.
+ tries := 10
+ count := 1000000
+ if testing.Short() {
+ tries = 1
+ }
+ for try := 0; try < tries; try++ {
+ var prof bytes.Buffer
+ if err := StartCPUProfile(&prof); err != nil {
+ t.Fatal(err)
+ }
+ for i := 0; i < count; i++ {
+ runtime.Gosched()
+ }
+ StopCPUProfile()
+
+ // Read profile to look for entries for gogo with an attempt at a traceback.
+ // "runtime.gogo" is OK, because that's the part of the context switch
+ // before the actual switch begins. But we should not see "gogo",
+ // aka "gogo<>(SB)", which does the actual switch and is marked SPWRITE.
+ parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) {
+ // An entry with two frames with 'System' in its top frame
+ // exists to record a PC without a traceback. Those are okay.
+ if len(stk) == 2 {
+ name := stk[1].Line[0].Function.Name
+ if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" {
+ return
+ }
+ }
+
+ // An entry with just one frame is OK too:
+ // it knew to stop at gogo.
+ if len(stk) == 1 {
+ return
+ }
+
+ // Otherwise, should not see gogo.
+ // The place we'd see it would be the inner most frame.
+ name := stk[0].Line[0].Function.Name
+ if name == "gogo" {
+ var buf strings.Builder
+ fprintStack(&buf, stk)
+ t.Fatalf("found profile entry for gogo:\n%s", buf.String())
+ }
+ })
+ }
+}
+
+func fprintStack(w io.Writer, stk []*profile.Location) {
+ if len(stk) == 0 {
+ fmt.Fprintf(w, " (stack empty)")
+ }
+ for _, loc := range stk {
+ fmt.Fprintf(w, " %#x", loc.Address)
+ fmt.Fprintf(w, " (")
+ for i, line := range loc.Line {
+ if i > 0 {
+ fmt.Fprintf(w, " ")
+ }
+ fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line)
+ }
+ fmt.Fprintf(w, ")")
+ }
+}
+
+// Test that profiling of division operations is okay, especially on ARM. See issue 6681.
+func TestMathBigDivide(t *testing.T) {
+ testCPUProfile(t, nil, func(duration time.Duration) {
+ t := time.After(duration)
+ pi := new(big.Int)
+ for {
+ for i := 0; i < 100; i++ {
+ n := big.NewInt(2646693125139304345)
+ d := big.NewInt(842468587426513207)
+ pi.Div(n, d)
+ }
+ select {
+ case <-t:
+ return
+ default:
+ }
+ }
+ })
+}
+
+// stackContainsAll matches if all functions in spec (comma-separated) appear somewhere in the stack trace.
+func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
+ for _, f := range strings.Split(spec, ",") {
+ if !stackContains(f, count, stk, labels) {
+ return false
+ }
+ }
+ return true
+}
+
+func TestMorestack(t *testing.T) {
+ matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions())
+ testCPUProfile(t, matches, func(duration time.Duration) {
+ t := time.After(duration)
+ c := make(chan bool)
+ for {
+ go func() {
+ growstack1()
+ c <- true
+ }()
+ select {
+ case <-t:
+ return
+ case <-c:
+ }
+ }
+ })
+}
+
+//go:noinline
+func growstack1() {
+ growstack(10)
+}
+
+//go:noinline
+func growstack(n int) {
+ var buf [8 << 18]byte
+ use(buf)
+ if n > 0 {
+ growstack(n - 1)
+ }
+}
+
+//go:noinline
+func use(x [8 << 18]byte) {}
+
+func TestBlockProfile(t *testing.T) {
+ type TestCase struct {
+ name string
+ f func(*testing.T)
+ stk []string
+ re string
+ }
+ tests := [...]TestCase{
+ {
+ name: "chan recv",
+ f: blockChanRecv,
+ stk: []string{
+ "runtime.chanrecv1",
+ "runtime/pprof.blockChanRecv",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockChanRecv\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ {
+ name: "chan send",
+ f: blockChanSend,
+ stk: []string{
+ "runtime.chansend1",
+ "runtime/pprof.blockChanSend",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ runtime\.chansend1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockChanSend\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ {
+ name: "chan close",
+ f: blockChanClose,
+ stk: []string{
+ "runtime.chanrecv1",
+ "runtime/pprof.blockChanClose",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockChanClose\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ {
+ name: "select recv async",
+ f: blockSelectRecvAsync,
+ stk: []string{
+ "runtime.selectgo",
+ "runtime/pprof.blockSelectRecvAsync",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*runtime/select.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ {
+ name: "select send sync",
+ f: blockSelectSendSync,
+ stk: []string{
+ "runtime.selectgo",
+ "runtime/pprof.blockSelectSendSync",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*runtime/select.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ {
+ name: "mutex",
+ f: blockMutex,
+ stk: []string{
+ "sync.(*Mutex).Lock",
+ "runtime/pprof.blockMutex",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+ .*sync/mutex\.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockMutex\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ {
+ name: "cond",
+ f: blockCond,
+ stk: []string{
+ "sync.(*Cond).Wait",
+ "runtime/pprof.blockCond",
+ "runtime/pprof.TestBlockProfile",
+ },
+ re: `
+[0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
+# 0x[0-9a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+ .*sync/cond\.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.blockCond\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+# 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
+`},
+ }
+
+ // Generate block profile
+ runtime.SetBlockProfileRate(1)
+ defer runtime.SetBlockProfileRate(0)
+ for _, test := range tests {
+ test.f(t)
+ }
+
+ t.Run("debug=1", func(t *testing.T) {
+ var w strings.Builder
+ Lookup("block").WriteTo(&w, 1)
+ prof := w.String()
+
+ if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
+ t.Fatalf("Bad profile header:\n%v", prof)
+ }
+
+ if strings.HasSuffix(prof, "#\t0x0\n\n") {
+ t.Errorf("Useless 0 suffix:\n%v", prof)
+ }
+
+ for _, test := range tests {
+ if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) {
+ t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
+ }
+ }
+ })
+
+ t.Run("proto", func(t *testing.T) {
+ // proto format
+ var w bytes.Buffer
+ Lookup("block").WriteTo(&w, 0)
+ p, err := profile.Parse(&w)
+ if err != nil {
+ t.Fatalf("failed to parse profile: %v", err)
+ }
+ t.Logf("parsed proto: %s", p)
+ if err := p.CheckValid(); err != nil {
+ t.Fatalf("invalid profile: %v", err)
+ }
+
+ stks := stacks(p)
+ for _, test := range tests {
+ if !containsStack(stks, test.stk) {
+ t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk)
+ }
+ }
+ })
+
+}
+
+func stacks(p *profile.Profile) (res [][]string) {
+ for _, s := range p.Sample {
+ var stk []string
+ for _, l := range s.Location {
+ for _, line := range l.Line {
+ stk = append(stk, line.Function.Name)
+ }
+ }
+ res = append(res, stk)
+ }
+ return res
+}
+
+func containsStack(got [][]string, want []string) bool {
+ for _, stk := range got {
+ if len(stk) < len(want) {
+ continue
+ }
+ for i, f := range want {
+ if f != stk[i] {
+ break
+ }
+ if i == len(want)-1 {
+ return true
+ }
+ }
+ }
+ return false
+}
+
+// awaitBlockedGoroutine spins on runtime.Gosched until a runtime stack dump
+// shows a goroutine in the given state with a stack frame in
+// runtime/pprof.<fName>.
+func awaitBlockedGoroutine(t *testing.T, state, fName string, count int) {
+ re := fmt.Sprintf(`(?m)^goroutine \d+ \[%s\]:\n(?:.+\n\t.+\n)*runtime/pprof\.%s`, regexp.QuoteMeta(state), fName)
+ r := regexp.MustCompile(re)
+
+ if deadline, ok := t.Deadline(); ok {
+ if d := time.Until(deadline); d > 1*time.Second {
+ timer := time.AfterFunc(d-1*time.Second, func() {
+ debug.SetTraceback("all")
+ panic(fmt.Sprintf("timed out waiting for %#q", re))
+ })
+ defer timer.Stop()
+ }
+ }
+
+ buf := make([]byte, 64<<10)
+ for {
+ runtime.Gosched()
+ n := runtime.Stack(buf, true)
+ if n == len(buf) {
+ // Buffer wasn't large enough for a full goroutine dump.
+ // Resize it and try again.
+ buf = make([]byte, 2*len(buf))
+ continue
+ }
+ if len(r.FindAll(buf[:n], -1)) >= count {
+ return
+ }
+ }
+}
+
+func blockChanRecv(t *testing.T) {
+ c := make(chan bool)
+ go func() {
+ awaitBlockedGoroutine(t, "chan receive", "blockChanRecv", 1)
+ c <- true
+ }()
+ <-c
+}
+
+func blockChanSend(t *testing.T) {
+ c := make(chan bool)
+ go func() {
+ awaitBlockedGoroutine(t, "chan send", "blockChanSend", 1)
+ <-c
+ }()
+ c <- true
+}
+
+func blockChanClose(t *testing.T) {
+ c := make(chan bool)
+ go func() {
+ awaitBlockedGoroutine(t, "chan receive", "blockChanClose", 1)
+ close(c)
+ }()
+ <-c
+}
+
+func blockSelectRecvAsync(t *testing.T) {
+ const numTries = 3
+ c := make(chan bool, 1)
+ c2 := make(chan bool, 1)
+ go func() {
+ for i := 0; i < numTries; i++ {
+ awaitBlockedGoroutine(t, "select", "blockSelectRecvAsync", 1)
+ c <- true
+ }
+ }()
+ for i := 0; i < numTries; i++ {
+ select {
+ case <-c:
+ case <-c2:
+ }
+ }
+}
+
+func blockSelectSendSync(t *testing.T) {
+ c := make(chan bool)
+ c2 := make(chan bool)
+ go func() {
+ awaitBlockedGoroutine(t, "select", "blockSelectSendSync", 1)
+ <-c
+ }()
+ select {
+ case c <- true:
+ case c2 <- true:
+ }
+}
+
+func blockMutex(t *testing.T) {
+ var mu sync.Mutex
+ mu.Lock()
+ go func() {
+ awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex", 1)
+ mu.Unlock()
+ }()
+ // Note: Unlock releases mu before recording the mutex event,
+ // so it's theoretically possible for this to proceed and
+ // capture the profile before the event is recorded. As long
+ // as this is blocked before the unlock happens, it's okay.
+ mu.Lock()
+}
+
+func blockMutexN(t *testing.T, n int, d time.Duration) {
+ var wg sync.WaitGroup
+ var mu sync.Mutex
+ mu.Lock()
+ go func() {
+ awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex", n)
+ time.Sleep(d)
+ mu.Unlock()
+ }()
+ // Note: Unlock releases mu before recording the mutex event,
+ // so it's theoretically possible for this to proceed and
+ // capture the profile before the event is recorded. As long
+ // as this is blocked before the unlock happens, it's okay.
+ for i := 0; i < n; i++ {
+ wg.Add(1)
+ go func() {
+ defer wg.Done()
+ mu.Lock()
+ mu.Unlock()
+ }()
+ }
+ wg.Wait()
+}
+
+func blockCond(t *testing.T) {
+ var mu sync.Mutex
+ c := sync.NewCond(&mu)
+ mu.Lock()
+ go func() {
+ awaitBlockedGoroutine(t, "sync.Cond.Wait", "blockCond", 1)
+ mu.Lock()
+ c.Signal()
+ mu.Unlock()
+ }()
+ c.Wait()
+ mu.Unlock()
+}
+
+// See http://golang.org/cl/299991.
+func TestBlockProfileBias(t *testing.T) {
+ rate := int(1000) // arbitrary value
+ runtime.SetBlockProfileRate(rate)
+ defer runtime.SetBlockProfileRate(0)
+
+ // simulate blocking events
+ blockFrequentShort(rate)
+ blockInfrequentLong(rate)
+
+ var w bytes.Buffer
+ Lookup("block").WriteTo(&w, 0)
+ p, err := profile.Parse(&w)
+ if err != nil {
+ t.Fatalf("failed to parse profile: %v", err)
+ }
+ t.Logf("parsed proto: %s", p)
+
+ il := float64(-1) // blockInfrequentLong duration
+ fs := float64(-1) // blockFrequentShort duration
+ for _, s := range p.Sample {
+ for _, l := range s.Location {
+ for _, line := range l.Line {
+ if len(s.Value) < 2 {
+ t.Fatal("block profile has less than 2 sample types")
+ }
+
+ if line.Function.Name == "runtime/pprof.blockInfrequentLong" {
+ il = float64(s.Value[1])
+ } else if line.Function.Name == "runtime/pprof.blockFrequentShort" {
+ fs = float64(s.Value[1])
+ }
+ }
+ }
+ }
+ if il == -1 || fs == -1 {
+ t.Fatal("block profile is missing expected functions")
+ }
+
+ // stddev of bias from 100 runs on local machine multiplied by 10x
+ const threshold = 0.2
+ if bias := (il - fs) / il; math.Abs(bias) > threshold {
+ t.Fatalf("bias: abs(%f) > %f", bias, threshold)
+ } else {
+ t.Logf("bias: abs(%f) < %f", bias, threshold)
+ }
+}
+
+// blockFrequentShort produces 100000 block events with an average duration of
+// rate / 10.
+func blockFrequentShort(rate int) {
+ for i := 0; i < 100000; i++ {
+ blockevent(int64(rate/10), 1)
+ }
+}
+
+// blockFrequentShort produces 10000 block events with an average duration of
+// rate.
+func blockInfrequentLong(rate int) {
+ for i := 0; i < 10000; i++ {
+ blockevent(int64(rate), 1)
+ }
+}
+
+// Used by TestBlockProfileBias.
+//
+//go:linkname blockevent runtime.blockevent
+func blockevent(cycles int64, skip int)
+
+func TestMutexProfile(t *testing.T) {
+ // Generate mutex profile
+
+ old := runtime.SetMutexProfileFraction(1)
+ defer runtime.SetMutexProfileFraction(old)
+ if old != 0 {
+ t.Fatalf("need MutexProfileRate 0, got %d", old)
+ }
+
+ const (
+ N = 100
+ D = 100 * time.Millisecond
+ )
+ start := time.Now()
+ blockMutexN(t, N, D)
+ blockMutexNTime := time.Since(start)
+
+ t.Run("debug=1", func(t *testing.T) {
+ var w strings.Builder
+ Lookup("mutex").WriteTo(&w, 1)
+ prof := w.String()
+ t.Logf("received profile: %v", prof)
+
+ if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") {
+ t.Errorf("Bad profile header:\n%v", prof)
+ }
+ prof = strings.Trim(prof, "\n")
+ lines := strings.Split(prof, "\n")
+ if len(lines) < 6 {
+ t.Fatalf("expected >=6 lines, got %d %q\n%s", len(lines), prof, prof)
+ }
+ // checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931"
+ r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+`
+ if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok {
+ t.Errorf("%q didn't match %q", lines[3], r2)
+ }
+ r3 := "^#.*runtime/pprof.blockMutex.*$"
+ if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok {
+ t.Errorf("%q didn't match %q", lines[5], r3)
+ }
+ t.Logf(prof)
+ })
+ t.Run("proto", func(t *testing.T) {
+ // proto format
+ var w bytes.Buffer
+ Lookup("mutex").WriteTo(&w, 0)
+ p, err := profile.Parse(&w)
+ if err != nil {
+ t.Fatalf("failed to parse profile: %v", err)
+ }
+ t.Logf("parsed proto: %s", p)
+ if err := p.CheckValid(); err != nil {
+ t.Fatalf("invalid profile: %v", err)
+ }
+
+ stks := stacks(p)
+ for _, want := range [][]string{
+ {"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexN.func1"},
+ } {
+ if !containsStack(stks, want) {
+ t.Errorf("No matching stack entry for %+v", want)
+ }
+ }
+
+ i := 0
+ for ; i < len(p.SampleType); i++ {
+ if p.SampleType[i].Unit == "nanoseconds" {
+ break
+ }
+ }
+ if i >= len(p.SampleType) {
+ t.Fatalf("profile did not contain nanoseconds sample")
+ }
+ total := int64(0)
+ for _, s := range p.Sample {
+ total += s.Value[i]
+ }
+ // Want d to be at least N*D, but give some wiggle-room to avoid
+ // a test flaking. Set an upper-bound proportional to the total
+ // wall time spent in blockMutexN. Generally speaking, the total
+ // contention time could be arbitrarily high when considering
+ // OS scheduler delays, or any other delays from the environment:
+ // time keeps ticking during these delays. By making the upper
+ // bound proportional to the wall time in blockMutexN, in theory
+ // we're accounting for all these possible delays.
+ d := time.Duration(total)
+ lo := time.Duration(N * D * 9 / 10)
+ hi := time.Duration(N) * blockMutexNTime * 11 / 10
+ if d < lo || d > hi {
+ for _, s := range p.Sample {
+ t.Logf("sample: %s", time.Duration(s.Value[i]))
+ }
+ t.Fatalf("profile samples total %v, want within range [%v, %v] (target: %v)", d, lo, hi, N*D)
+ }
+ })
+}
+
+func TestMutexProfileRateAdjust(t *testing.T) {
+ old := runtime.SetMutexProfileFraction(1)
+ defer runtime.SetMutexProfileFraction(old)
+ if old != 0 {
+ t.Fatalf("need MutexProfileRate 0, got %d", old)
+ }
+
+ readProfile := func() (contentions int64, delay int64) {
+ var w bytes.Buffer
+ Lookup("mutex").WriteTo(&w, 0)
+ p, err := profile.Parse(&w)
+ if err != nil {
+ t.Fatalf("failed to parse profile: %v", err)
+ }
+ t.Logf("parsed proto: %s", p)
+ if err := p.CheckValid(); err != nil {
+ t.Fatalf("invalid profile: %v", err)
+ }
+
+ for _, s := range p.Sample {
+ for _, l := range s.Location {
+ for _, line := range l.Line {
+ if line.Function.Name == "runtime/pprof.blockMutex.func1" {
+ contentions += s.Value[0]
+ delay += s.Value[1]
+ }
+ }
+ }
+ }
+ return
+ }
+
+ blockMutex(t)
+ contentions, delay := readProfile()
+ if contentions == 0 || delay == 0 {
+ t.Fatal("did not see expected function in profile")
+ }
+ runtime.SetMutexProfileFraction(0)
+ newContentions, newDelay := readProfile()
+ if newContentions != contentions || newDelay != delay {
+ t.Fatalf("sample value changed: got [%d, %d], want [%d, %d]", newContentions, newDelay, contentions, delay)
+ }
+}
+
+func func1(c chan int) { <-c }
+func func2(c chan int) { <-c }
+func func3(c chan int) { <-c }
+func func4(c chan int) { <-c }
+
+func TestGoroutineCounts(t *testing.T) {
+ // Setting GOMAXPROCS to 1 ensures we can force all goroutines to the
+ // desired blocking point.
+ defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
+
+ c := make(chan int)
+ for i := 0; i < 100; i++ {
+ switch {
+ case i%10 == 0:
+ go func1(c)
+ case i%2 == 0:
+ go func2(c)
+ default:
+ go func3(c)
+ }
+ // Let goroutines block on channel
+ for j := 0; j < 5; j++ {
+ runtime.Gosched()
+ }
+ }
+ ctx := context.Background()
+
+ // ... and again, with labels this time (just with fewer iterations to keep
+ // sorting deterministic).
+ Do(ctx, Labels("label", "value"), func(context.Context) {
+ for i := 0; i < 89; i++ {
+ switch {
+ case i%10 == 0:
+ go func1(c)
+ case i%2 == 0:
+ go func2(c)
+ default:
+ go func3(c)
+ }
+ // Let goroutines block on channel
+ for j := 0; j < 5; j++ {
+ runtime.Gosched()
+ }
+ }
+ })
+
+ SetGoroutineLabels(WithLabels(context.Background(), Labels("self-label", "self-value")))
+ defer SetGoroutineLabels(context.Background())
+
+ garbage := new(*int)
+ fingReady := make(chan struct{})
+ runtime.SetFinalizer(garbage, func(v **int) {
+ Do(context.Background(), Labels("fing-label", "fing-value"), func(ctx context.Context) {
+ close(fingReady)
+ <-c
+ })
+ })
+ garbage = nil
+ for i := 0; i < 2; i++ {
+ runtime.GC()
+ }
+ <-fingReady
+
+ var w bytes.Buffer
+ goroutineProf := Lookup("goroutine")
+
+ // Check debug profile
+ goroutineProf.WriteTo(&w, 1)
+ prof := w.String()
+
+ labels := labelMap{"label": "value"}
+ labelStr := "\n# labels: " + labels.String()
+ selfLabel := labelMap{"self-label": "self-value"}
+ selfLabelStr := "\n# labels: " + selfLabel.String()
+ fingLabel := labelMap{"fing-label": "fing-value"}
+ fingLabelStr := "\n# labels: " + fingLabel.String()
+ orderedPrefix := []string{
+ "\n50 @ ",
+ "\n44 @", labelStr,
+ "\n40 @",
+ "\n36 @", labelStr,
+ "\n10 @",
+ "\n9 @", labelStr,
+ "\n1 @"}
+ if !containsInOrder(prof, append(orderedPrefix, selfLabelStr)...) {
+ t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
+ }
+ if !containsInOrder(prof, append(orderedPrefix, fingLabelStr)...) {
+ t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
+ }
+
+ // Check proto profile
+ w.Reset()
+ goroutineProf.WriteTo(&w, 0)
+ p, err := profile.Parse(&w)
+ if err != nil {
+ t.Errorf("error parsing protobuf profile: %v", err)
+ }
+ if err := p.CheckValid(); err != nil {
+ t.Errorf("protobuf profile is invalid: %v", err)
+ }
+ expectedLabels := map[int64]map[string]string{
+ 50: {},
+ 44: {"label": "value"},
+ 40: {},
+ 36: {"label": "value"},
+ 10: {},
+ 9: {"label": "value"},
+ 1: {"self-label": "self-value", "fing-label": "fing-value"},
+ }
+ if !containsCountsLabels(p, expectedLabels) {
+ t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v",
+ expectedLabels, p)
+ }
+
+ close(c)
+
+ time.Sleep(10 * time.Millisecond) // let goroutines exit
+}
+
+func containsInOrder(s string, all ...string) bool {
+ for _, t := range all {
+ var ok bool
+ if _, s, ok = strings.Cut(s, t); !ok {
+ return false
+ }
+ }
+ return true
+}
+
+func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool {
+ m := make(map[int64]int)
+ type nkey struct {
+ count int64
+ key, val string
+ }
+ n := make(map[nkey]int)
+ for c, kv := range countLabels {
+ m[c]++
+ for k, v := range kv {
+ n[nkey{
+ count: c,
+ key: k,
+ val: v,
+ }]++
+
+ }
+ }
+ for _, s := range prof.Sample {
+ // The count is the single value in the sample
+ if len(s.Value) != 1 {
+ return false
+ }
+ m[s.Value[0]]--
+ for k, vs := range s.Label {
+ for _, v := range vs {
+ n[nkey{
+ count: s.Value[0],
+ key: k,
+ val: v,
+ }]--
+ }
+ }
+ }
+ for _, n := range m {
+ if n > 0 {
+ return false
+ }
+ }
+ for _, ncnt := range n {
+ if ncnt != 0 {
+ return false
+ }
+ }
+ return true
+}
+
+func TestGoroutineProfileConcurrency(t *testing.T) {
+ testenv.MustHaveParallelism(t)
+
+ goroutineProf := Lookup("goroutine")
+
+ profilerCalls := func(s string) int {
+ return strings.Count(s, "\truntime/pprof.runtime_goroutineProfileWithLabels+")
+ }
+
+ includesFinalizer := func(s string) bool {
+ return strings.Contains(s, "runtime.runfinq")
+ }
+
+ // Concurrent calls to the goroutine profiler should not trigger data races
+ // or corruption.
+ t.Run("overlapping profile requests", func(t *testing.T) {
+ ctx := context.Background()
+ ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
+ defer cancel()
+
+ var wg sync.WaitGroup
+ for i := 0; i < 2; i++ {
+ wg.Add(1)
+ Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
+ go func() {
+ defer wg.Done()
+ for ctx.Err() == nil {
+ var w strings.Builder
+ goroutineProf.WriteTo(&w, 1)
+ prof := w.String()
+ count := profilerCalls(prof)
+ if count >= 2 {
+ t.Logf("prof %d\n%s", count, prof)
+ cancel()
+ }
+ }
+ }()
+ })
+ }
+ wg.Wait()
+ })
+
+ // The finalizer goroutine should not show up in most profiles, since it's
+ // marked as a system goroutine when idle.
+ t.Run("finalizer not present", func(t *testing.T) {
+ var w strings.Builder
+ goroutineProf.WriteTo(&w, 1)
+ prof := w.String()
+ if includesFinalizer(prof) {
+ t.Errorf("profile includes finalizer (but finalizer should be marked as system):\n%s", prof)
+ }
+ })
+
+ // The finalizer goroutine should show up when it's running user code.
+ t.Run("finalizer present", func(t *testing.T) {
+ obj := new(byte)
+ ch1, ch2 := make(chan int), make(chan int)
+ defer close(ch2)
+ runtime.SetFinalizer(obj, func(_ interface{}) {
+ close(ch1)
+ <-ch2
+ })
+ obj = nil
+ for i := 10; i >= 0; i-- {
+ select {
+ case <-ch1:
+ default:
+ if i == 0 {
+ t.Fatalf("finalizer did not run")
+ }
+ runtime.GC()
+ }
+ }
+ var w strings.Builder
+ goroutineProf.WriteTo(&w, 1)
+ prof := w.String()
+ if !includesFinalizer(prof) {
+ t.Errorf("profile does not include finalizer (and it should be marked as user):\n%s", prof)
+ }
+ })
+
+ // Check that new goroutines only show up in order.
+ testLaunches := func(t *testing.T) {
+ var done sync.WaitGroup
+ defer done.Wait()
+
+ ctx := context.Background()
+ ctx, cancel := context.WithCancel(ctx)
+ defer cancel()
+
+ ch := make(chan int)
+ defer close(ch)
+
+ var ready sync.WaitGroup
+
+ // These goroutines all survive until the end of the subtest, so we can
+ // check that a (numbered) goroutine appearing in the profile implies
+ // that all older goroutines also appear in the profile.
+ ready.Add(1)
+ done.Add(1)
+ go func() {
+ defer done.Done()
+ for i := 0; ctx.Err() == nil; i++ {
+ // Use SetGoroutineLabels rather than Do we can always expect an
+ // extra goroutine (this one) with most recent label.
+ SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-loop-i", fmt.Sprint(i))))
+ done.Add(1)
+ go func() {
+ <-ch
+ done.Done()
+ }()
+ for j := 0; j < i; j++ {
+ // Spin for longer and longer as the test goes on. This
+ // goroutine will do O(N^2) work with the number of
+ // goroutines it launches. This should be slow relative to
+ // the work involved in collecting a goroutine profile,
+ // which is O(N) with the high-water mark of the number of
+ // goroutines in this process (in the allgs slice).
+ runtime.Gosched()
+ }
+ if i == 0 {
+ ready.Done()
+ }
+ }
+ }()
+
+ // Short-lived goroutines exercise different code paths (goroutines with
+ // status _Gdead, for instance). This churn doesn't have behavior that
+ // we can test directly, but does help to shake out data races.
+ ready.Add(1)
+ var churn func(i int)
+ churn = func(i int) {
+ SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-churn-i", fmt.Sprint(i))))
+ if i == 0 {
+ ready.Done()
+ } else if i%16 == 0 {
+ // Yield on occasion so this sequence of goroutine launches
+ // doesn't monopolize a P. See issue #52934.
+ runtime.Gosched()
+ }
+ if ctx.Err() == nil {
+ go churn(i + 1)
+ }
+ }
+ go func() {
+ churn(0)
+ }()
+
+ ready.Wait()
+
+ var w [3]bytes.Buffer
+ for i := range w {
+ goroutineProf.WriteTo(&w[i], 0)
+ }
+ for i := range w {
+ p, err := profile.Parse(bytes.NewReader(w[i].Bytes()))
+ if err != nil {
+ t.Errorf("error parsing protobuf profile: %v", err)
+ }
+
+ // High-numbered loop-i goroutines imply that every lower-numbered
+ // loop-i goroutine should be present in the profile too.
+ counts := make(map[string]int)
+ for _, s := range p.Sample {
+ label := s.Label[t.Name()+"-loop-i"]
+ if len(label) > 0 {
+ counts[label[0]]++
+ }
+ }
+ for j, max := 0, len(counts)-1; j <= max; j++ {
+ n := counts[fmt.Sprint(j)]
+ if n == 1 || (n == 2 && j == max) {
+ continue
+ }
+ t.Errorf("profile #%d's goroutines with label loop-i:%d; %d != 1 (or 2 for the last entry, %d)",
+ i+1, j, n, max)
+ t.Logf("counts %v", counts)
+ break
+ }
+ }
+ }
+
+ runs := 100
+ if testing.Short() {
+ runs = 5
+ }
+ for i := 0; i < runs; i++ {
+ // Run multiple times to shake out data races
+ t.Run("goroutine launches", testLaunches)
+ }
+}
+
+func BenchmarkGoroutine(b *testing.B) {
+ withIdle := func(n int, fn func(b *testing.B)) func(b *testing.B) {
+ return func(b *testing.B) {
+ c := make(chan int)
+ var ready, done sync.WaitGroup
+ defer func() {
+ close(c)
+ done.Wait()
+ }()
+
+ for i := 0; i < n; i++ {
+ ready.Add(1)
+ done.Add(1)
+ go func() {
+ ready.Done()
+ <-c
+ done.Done()
+ }()
+ }
+ // Let goroutines block on channel
+ ready.Wait()
+ for i := 0; i < 5; i++ {
+ runtime.Gosched()
+ }
+
+ fn(b)
+ }
+ }
+
+ withChurn := func(fn func(b *testing.B)) func(b *testing.B) {
+ return func(b *testing.B) {
+ ctx := context.Background()
+ ctx, cancel := context.WithCancel(ctx)
+ defer cancel()
+
+ var ready sync.WaitGroup
+ ready.Add(1)
+ var count int64
+ var churn func(i int)
+ churn = func(i int) {
+ SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
+ atomic.AddInt64(&count, 1)
+ if i == 0 {
+ ready.Done()
+ }
+ if ctx.Err() == nil {
+ go churn(i + 1)
+ }
+ }
+ go func() {
+ churn(0)
+ }()
+ ready.Wait()
+
+ fn(b)
+ b.ReportMetric(float64(atomic.LoadInt64(&count))/float64(b.N), "concurrent_launches/op")
+ }
+ }
+
+ benchWriteTo := func(b *testing.B) {
+ goroutineProf := Lookup("goroutine")
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ goroutineProf.WriteTo(io.Discard, 0)
+ }
+ b.StopTimer()
+ }
+
+ benchGoroutineProfile := func(b *testing.B) {
+ p := make([]runtime.StackRecord, 10000)
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ runtime.GoroutineProfile(p)
+ }
+ b.StopTimer()
+ }
+
+ // Note that some costs of collecting a goroutine profile depend on the
+ // length of the runtime.allgs slice, which never shrinks. Stay within race
+ // detector's 8k-goroutine limit
+ for _, n := range []int{50, 500, 5000} {
+ b.Run(fmt.Sprintf("Profile.WriteTo idle %d", n), withIdle(n, benchWriteTo))
+ b.Run(fmt.Sprintf("Profile.WriteTo churn %d", n), withIdle(n, withChurn(benchWriteTo)))
+ b.Run(fmt.Sprintf("runtime.GoroutineProfile churn %d", n), withIdle(n, withChurn(benchGoroutineProfile)))
+ }
+}
+
+var emptyCallStackTestRun int64
+
+// Issue 18836.
+func TestEmptyCallStack(t *testing.T) {
+ name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun)
+ emptyCallStackTestRun++
+
+ t.Parallel()
+ var buf strings.Builder
+ p := NewProfile(name)
+
+ p.Add("foo", 47674)
+ p.WriteTo(&buf, 1)
+ p.Remove("foo")
+ got := buf.String()
+ prefix := name + " profile: total 1\n"
+ if !strings.HasPrefix(got, prefix) {
+ t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix)
+ }
+ lostevent := "lostProfileEvent"
+ if !strings.Contains(got, lostevent) {
+ t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent)
+ }
+}
+
+// stackContainsLabeled takes a spec like funcname;key=value and matches if the stack has that key
+// and value and has funcname somewhere in the stack.
+func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
+ base, kv, ok := strings.Cut(spec, ";")
+ if !ok {
+ panic("no semicolon in key/value spec")
+ }
+ k, v, ok := strings.Cut(kv, "=")
+ if !ok {
+ panic("missing = in key/value spec")
+ }
+ if !contains(labels[k], v) {
+ return false
+ }
+ return stackContains(base, count, stk, labels)
+}
+
+func TestCPUProfileLabel(t *testing.T) {
+ matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions())
+ testCPUProfile(t, matches, func(dur time.Duration) {
+ Do(context.Background(), Labels("key", "value"), func(context.Context) {
+ cpuHogger(cpuHog1, &salt1, dur)
+ })
+ })
+}
+
+func TestLabelRace(t *testing.T) {
+ testenv.MustHaveParallelism(t)
+ // Test the race detector annotations for synchronization
+ // between setting labels and consuming them from the
+ // profile.
+ matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil)
+ testCPUProfile(t, matches, func(dur time.Duration) {
+ start := time.Now()
+ var wg sync.WaitGroup
+ for time.Since(start) < dur {
+ var salts [10]int
+ for i := 0; i < 10; i++ {
+ wg.Add(1)
+ go func(j int) {
+ Do(context.Background(), Labels("key", "value"), func(context.Context) {
+ cpuHogger(cpuHog1, &salts[j], time.Millisecond)
+ })
+ wg.Done()
+ }(i)
+ }
+ wg.Wait()
+ }
+ })
+}
+
+func TestGoroutineProfileLabelRace(t *testing.T) {
+ testenv.MustHaveParallelism(t)
+ // Test the race detector annotations for synchronization
+ // between setting labels and consuming them from the
+ // goroutine profile. See issue #50292.
+
+ t.Run("reset", func(t *testing.T) {
+ ctx := context.Background()
+ ctx, cancel := context.WithCancel(ctx)
+ defer cancel()
+
+ go func() {
+ goroutineProf := Lookup("goroutine")
+ for ctx.Err() == nil {
+ var w strings.Builder
+ goroutineProf.WriteTo(&w, 1)
+ prof := w.String()
+ if strings.Contains(prof, "loop-i") {
+ cancel()
+ }
+ }
+ }()
+
+ for i := 0; ctx.Err() == nil; i++ {
+ Do(ctx, Labels("loop-i", fmt.Sprint(i)), func(ctx context.Context) {
+ })
+ }
+ })
+
+ t.Run("churn", func(t *testing.T) {
+ ctx := context.Background()
+ ctx, cancel := context.WithCancel(ctx)
+ defer cancel()
+
+ var ready sync.WaitGroup
+ ready.Add(1)
+ var churn func(i int)
+ churn = func(i int) {
+ SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
+ if i == 0 {
+ ready.Done()
+ }
+ if ctx.Err() == nil {
+ go churn(i + 1)
+ }
+ }
+ go func() {
+ churn(0)
+ }()
+ ready.Wait()
+
+ goroutineProf := Lookup("goroutine")
+ for i := 0; i < 10; i++ {
+ goroutineProf.WriteTo(io.Discard, 1)
+ }
+ })
+}
+
+// TestLabelSystemstack makes sure CPU profiler samples of goroutines running
+// on systemstack include the correct pprof labels. See issue #48577
+func TestLabelSystemstack(t *testing.T) {
+ // Grab and re-set the initial value before continuing to ensure
+ // GOGC doesn't actually change following the test.
+ gogc := debug.SetGCPercent(100)
+ debug.SetGCPercent(gogc)
+
+ matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions())
+ p := testCPUProfile(t, matches, func(dur time.Duration) {
+ Do(context.Background(), Labels("key", "value"), func(ctx context.Context) {
+ parallelLabelHog(ctx, dur, gogc)
+ })
+ })
+
+ // Two conditions to check:
+ // * labelHog should always be labeled.
+ // * The label should _only_ appear on labelHog and the Do call above.
+ for _, s := range p.Sample {
+ isLabeled := s.Label != nil && contains(s.Label["key"], "value")
+ var (
+ mayBeLabeled bool
+ mustBeLabeled string
+ mustNotBeLabeled string
+ )
+ for _, loc := range s.Location {
+ for _, l := range loc.Line {
+ switch l.Function.Name {
+ case "runtime/pprof.labelHog", "runtime/pprof.parallelLabelHog", "runtime/pprof.parallelLabelHog.func1":
+ mustBeLabeled = l.Function.Name
+ case "runtime/pprof.Do":
+ // Do sets the labels, so samples may
+ // or may not be labeled depending on
+ // which part of the function they are
+ // at.
+ mayBeLabeled = true
+ case "runtime.bgsweep", "runtime.bgscavenge", "runtime.forcegchelper", "runtime.gcBgMarkWorker", "runtime.runfinq", "runtime.sysmon":
+ // Runtime system goroutines or threads
+ // (such as those identified by
+ // runtime.isSystemGoroutine). These
+ // should never be labeled.
+ mustNotBeLabeled = l.Function.Name
+ case "gogo", "gosave_systemstack_switch", "racecall":
+ // These are context switch/race
+ // critical that we can't do a full
+ // traceback from. Typically this would
+ // be covered by the runtime check
+ // below, but these symbols don't have
+ // the package name.
+ mayBeLabeled = true
+ }
+
+ if strings.HasPrefix(l.Function.Name, "runtime.") {
+ // There are many places in the runtime
+ // where we can't do a full traceback.
+ // Ideally we'd list them all, but
+ // barring that allow anything in the
+ // runtime, unless explicitly excluded
+ // above.
+ mayBeLabeled = true
+ }
+ }
+ }
+ errorStack := func(f string, args ...any) {
+ var buf strings.Builder
+ fprintStack(&buf, s.Location)
+ t.Errorf("%s: %s", fmt.Sprintf(f, args...), buf.String())
+ }
+ if mustBeLabeled != "" && mustNotBeLabeled != "" {
+ errorStack("sample contains both %s, which must be labeled, and %s, which must not be labeled", mustBeLabeled, mustNotBeLabeled)
+ continue
+ }
+ if mustBeLabeled != "" || mustNotBeLabeled != "" {
+ // We found a definitive frame, so mayBeLabeled hints are not relevant.
+ mayBeLabeled = false
+ }
+ if mayBeLabeled {
+ // This sample may or may not be labeled, so there's nothing we can check.
+ continue
+ }
+ if mustBeLabeled != "" && !isLabeled {
+ errorStack("sample must be labeled because of %s, but is not", mustBeLabeled)
+ }
+ if mustNotBeLabeled != "" && isLabeled {
+ errorStack("sample must not be labeled because of %s, but is", mustNotBeLabeled)
+ }
+ }
+}
+
+// labelHog is designed to burn CPU time in a way that a high number of CPU
+// samples end up running on systemstack.
+func labelHog(stop chan struct{}, gogc int) {
+ // Regression test for issue 50032. We must give GC an opportunity to
+ // be initially triggered by a labelled goroutine.
+ runtime.GC()
+
+ for i := 0; ; i++ {
+ select {
+ case <-stop:
+ return
+ default:
+ debug.SetGCPercent(gogc)
+ }
+ }
+}
+
+// parallelLabelHog runs GOMAXPROCS goroutines running labelHog.
+func parallelLabelHog(ctx context.Context, dur time.Duration, gogc int) {
+ var wg sync.WaitGroup
+ stop := make(chan struct{})
+ for i := 0; i < runtime.GOMAXPROCS(0); i++ {
+ wg.Add(1)
+ go func() {
+ defer wg.Done()
+ labelHog(stop, gogc)
+ }()
+ }
+
+ time.Sleep(dur)
+ close(stop)
+ wg.Wait()
+}
+
+// Check that there is no deadlock when the program receives SIGPROF while in
+// 64bit atomics' critical section. Used to happen on mips{,le}. See #20146.
+func TestAtomicLoadStore64(t *testing.T) {
+ f, err := os.CreateTemp("", "profatomic")
+ if err != nil {
+ t.Fatalf("TempFile: %v", err)
+ }
+ defer os.Remove(f.Name())
+ defer f.Close()
+
+ if err := StartCPUProfile(f); err != nil {
+ t.Fatal(err)
+ }
+ defer StopCPUProfile()
+
+ var flag uint64
+ done := make(chan bool, 1)
+
+ go func() {
+ for atomic.LoadUint64(&flag) == 0 {
+ runtime.Gosched()
+ }
+ done <- true
+ }()
+ time.Sleep(50 * time.Millisecond)
+ atomic.StoreUint64(&flag, 1)
+ <-done
+}
+
+func TestTracebackAll(t *testing.T) {
+ // With gccgo, if a profiling signal arrives at the wrong time
+ // during traceback, it may crash or hang. See issue #29448.
+ f, err := os.CreateTemp("", "proftraceback")
+ if err != nil {
+ t.Fatalf("TempFile: %v", err)
+ }
+ defer os.Remove(f.Name())
+ defer f.Close()
+
+ if err := StartCPUProfile(f); err != nil {
+ t.Fatal(err)
+ }
+ defer StopCPUProfile()
+
+ ch := make(chan int)
+ defer close(ch)
+
+ count := 10
+ for i := 0; i < count; i++ {
+ go func() {
+ <-ch // block
+ }()
+ }
+
+ N := 10000
+ if testing.Short() {
+ N = 500
+ }
+ buf := make([]byte, 10*1024)
+ for i := 0; i < N; i++ {
+ runtime.Stack(buf, true)
+ }
+}
+
+// TestTryAdd tests the cases that are hard to test with real program execution.
+//
+// For example, the current go compilers may not always inline functions
+// involved in recursion but that may not be true in the future compilers. This
+// tests such cases by using fake call sequences and forcing the profile build
+// utilizing translateCPUProfile defined in proto_test.go
+func TestTryAdd(t *testing.T) {
+ if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found {
+ t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.")
+ }
+
+ // inlinedCallerDump
+ // inlinedCalleeDump
+ pcs := make([]uintptr, 2)
+ inlinedCallerDump(pcs)
+ inlinedCallerStack := make([]uint64, 2)
+ for i := range pcs {
+ inlinedCallerStack[i] = uint64(pcs[i])
+ }
+ wrapperPCs := make([]uintptr, 1)
+ inlinedWrapperCallerDump(wrapperPCs)
+
+ if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found {
+ t.Skip("Can't determine whether anything was inlined into recursionChainBottom.")
+ }
+
+ // recursionChainTop
+ // recursionChainMiddle
+ // recursionChainBottom
+ // recursionChainTop
+ // recursionChainMiddle
+ // recursionChainBottom
+ pcs = make([]uintptr, 6)
+ recursionChainTop(1, pcs)
+ recursionStack := make([]uint64, len(pcs))
+ for i := range pcs {
+ recursionStack[i] = uint64(pcs[i])
+ }
+
+ period := int64(2000 * 1000) // 1/500*1e9 nanosec.
+
+ testCases := []struct {
+ name string
+ input []uint64 // following the input format assumed by profileBuilder.addCPUData.
+ count int // number of records in input.
+ wantLocs [][]string // ordered location entries with function names.
+ wantSamples []*profile.Sample // ordered samples, we care only about Value and the profile location IDs.
+ }{{
+ // Sanity test for a normal, complete stack trace.
+ name: "full_stack_trace",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
+ },
+ count: 2,
+ wantLocs: [][]string{
+ {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
+ },
+ wantSamples: []*profile.Sample{
+ {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }, {
+ name: "bug35538",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ // Fake frame: tryAdd will have inlinedCallerDump
+ // (stack[1]) on the deck when it encounters the next
+ // inline function. It should accept this.
+ 7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1],
+ 5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1],
+ },
+ count: 3,
+ wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}},
+ {Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }, {
+ name: "bug38096",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ // count (data[2]) == 0 && len(stk) == 1 is an overflow
+ // entry. The "stk" entry is actually the count.
+ 4, 0, 0, 4242,
+ },
+ count: 2,
+ wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }, {
+ // If a function is directly called recursively then it must
+ // not be inlined in the caller.
+ //
+ // N.B. We're generating an impossible profile here, with a
+ // recursive inlineCalleeDump call. This is simulating a non-Go
+ // function that looks like an inlined Go function other than
+ // its recursive property. See pcDeck.tryAdd.
+ name: "directly_recursive_func_is_not_inlined",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0],
+ 4, 0, 40, inlinedCallerStack[0],
+ },
+ count: 3,
+ // inlinedCallerDump shows up here because
+ // runtime_expandFinalInlineFrame adds it to the stack frame.
+ wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}},
+ {Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}},
+ },
+ }, {
+ name: "recursion_chain_inline",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5],
+ },
+ count: 2,
+ wantLocs: [][]string{
+ {"runtime/pprof.recursionChainBottom"},
+ {
+ "runtime/pprof.recursionChainMiddle",
+ "runtime/pprof.recursionChainTop",
+ "runtime/pprof.recursionChainBottom",
+ },
+ {
+ "runtime/pprof.recursionChainMiddle",
+ "runtime/pprof.recursionChainTop",
+ "runtime/pprof.TestTryAdd", // inlined into the test.
+ },
+ },
+ wantSamples: []*profile.Sample{
+ {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}},
+ },
+ }, {
+ name: "truncated_stack_trace_later",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
+ 4, 0, 60, inlinedCallerStack[0],
+ },
+ count: 3,
+ wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
+ {Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }, {
+ name: "truncated_stack_trace_first",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 4, 0, 70, inlinedCallerStack[0],
+ 5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1],
+ },
+ count: 3,
+ wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
+ {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }, {
+ // We can recover the inlined caller from a truncated stack.
+ name: "truncated_stack_trace_only",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 4, 0, 70, inlinedCallerStack[0],
+ },
+ count: 2,
+ wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }, {
+ // The same location is used for duplicated stacks.
+ name: "truncated_stack_trace_twice",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 4, 0, 70, inlinedCallerStack[0],
+ // Fake frame: add a fake call to
+ // inlinedCallerDump to prevent this sample
+ // from getting merged into above.
+ 5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0],
+ },
+ count: 3,
+ wantLocs: [][]string{
+ {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
+ {"runtime/pprof.inlinedCallerDump"},
+ },
+ wantSamples: []*profile.Sample{
+ {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
+ {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}},
+ },
+ }, {
+ name: "expand_wrapper_function",
+ input: []uint64{
+ 3, 0, 500, // hz = 500. Must match the period.
+ 4, 0, 50, uint64(wrapperPCs[0]),
+ },
+ count: 2,
+ wantLocs: [][]string{{"runtime/pprof.inlineWrapper.dump"}},
+ wantSamples: []*profile.Sample{
+ {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
+ },
+ }}
+
+ for _, tc := range testCases {
+ t.Run(tc.name, func(t *testing.T) {
+ p, err := translateCPUProfile(tc.input, tc.count)
+ if err != nil {
+ t.Fatalf("translating profile: %v", err)
+ }
+ t.Logf("Profile: %v\n", p)
+
+ // One location entry with all inlined functions.
+ var gotLoc [][]string
+ for _, loc := range p.Location {
+ var names []string
+ for _, line := range loc.Line {
+ names = append(names, line.Function.Name)
+ }
+ gotLoc = append(gotLoc, names)
+ }
+ if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want {
+ t.Errorf("Got Location = %+v\n\twant %+v", got, want)
+ }
+ // All samples should point to one location.
+ var gotSamples []*profile.Sample
+ for _, sample := range p.Sample {
+ var locs []*profile.Location
+ for _, loc := range sample.Location {
+ locs = append(locs, &profile.Location{ID: loc.ID})
+ }
+ gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs})
+ }
+ if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want {
+ t.Errorf("Got Samples = %+v\n\twant %+v", got, want)
+ }
+ })
+ }
+}
+
+func TestTimeVDSO(t *testing.T) {
+ // Test that time functions have the right stack trace. In particular,
+ // it shouldn't be recursive.
+
+ if runtime.GOOS == "android" {
+ // Flaky on Android, issue 48655. VDSO may not be enabled.
+ testenv.SkipFlaky(t, 48655)
+ }
+
+ matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions())
+ p := testCPUProfile(t, matches, func(dur time.Duration) {
+ t0 := time.Now()
+ for {
+ t := time.Now()
+ if t.Sub(t0) >= dur {
+ return
+ }
+ }
+ })
+
+ // Check for recursive time.now sample.
+ for _, sample := range p.Sample {
+ var seenNow bool
+ for _, loc := range sample.Location {
+ for _, line := range loc.Line {
+ if line.Function.Name == "time.now" {
+ if seenNow {
+ t.Fatalf("unexpected recursive time.now")
+ }
+ seenNow = true
+ }
+ }
+ }
+ }
+}