[go] runtime/pprof: stress test goroutine profiler
40 views
Skip to first unread message
Rhys Hiltner (Gerrit)
Feb 22, 2022, 3:42:01 PM2/22/22
to goph...@pubsubhelper.golang.org, Rhys Hiltner, golang-co...@googlegroups.com
Rhys Hiltner has uploaded this change for review.
runtime/pprof: stress test goroutine profiler
For #33250
Change-Id: Ic7aa74b1bb5da9c4319718bac96316b236cb40b2
---
M src/runtime/pprof/pprof_test.go
1 file changed, 263 insertions(+), 0 deletions(-)
diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go
index 9548384..a203143 100644
--- a/src/runtime/pprof/pprof_test.go
+++ b/src/runtime/pprof/pprof_test.go
@@ -1376,6 +1376,258 @@
return true
}
+func TestGoroutineProfileConcurrency(t *testing.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 bytes.Buffer
+ 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 bytes.Buffer
+ 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 bytes.Buffer
+ 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) {
+ 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)
+ go func() {
+ 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))))
+ go func1(ch)
+ 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()
+ }
+ 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
+ }
+ }
+ }
+
+ for i := 0; i < 100; 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)
+ defer func() {
+ close(c)
+ time.Sleep(10 * time.Millisecond) // let goroutines exit
+ }()
+
+ for i := 0; i < n; i++ {
+ go func1(c)
+ }
+ // Let goroutines block on channel
+ 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.
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Rhys Hiltner (Gerrit)
Apr 5, 2022, 7:13:36 PM4/5/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui.
Rhys Hiltner uploaded patch set #4 to this change.
runtime/pprof: stress test goroutine profiler
For #33250
Change-Id: Ic7aa74b1bb5da9c4319718bac96316b236cb40b2
---
M src/runtime/pprof/pprof_test.go
M src/runtime/runtime_test.go
2 files changed, 360 insertions(+), 0 deletions(-)
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Rhys Hiltner (Gerrit)
Apr 29, 2022, 4:36:32 PM4/29/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, Michael Knyszek, Cherry Mui, Gopher Robot, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui, Michael Knyszek.
1 comment:
Patchset:
Hi Michael, could you take a look at this CL of tests for the goroutine profiler please? It's a dependency of CL 387415, and is the source of some of the benchmark results I shared in that change's commit message.
Once this is ready, the whole stack should be good to merge. (I abandoned the two leaf-most changes, CL 387416 and CL 401336. They were relevant to the discussion but should not be merged, do not need review.) Thank you!
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Michael Knyszek (Gerrit)
Apr 29, 2022, 8:32:38 PM4/29/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, Cherry Mui, Gopher Robot, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui, Rhys Hiltner.
3 comments:
Patchset:
thanks! LGTM overall, just some concerns about how long the test could take to run on the builders (especially the slow ones).
File src/runtime/pprof/pprof_test.go:
how long does this test take to run? we may want to skip on non-longtest builders, i.e.
```
if !testing.Short() {
t.Skip(...)
}
```Patch Set #4, Line 1558:
time.Sleep(10 * time.Millisecond) // let goroutines exitjust to help avoid having goroutines exist across benchmark runs, I have slight preference for a wg.Wait() here and adding each func1 goroutine to a wait group. is that feasible, or does func1 need to be at the bottom of the stack? maybe I'm missing something here.
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Rhys Hiltner (Gerrit)
May 3, 2022, 2:01:57 PM5/3/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui, Rhys Hiltner.
Rhys Hiltner uploaded patch set #5 to this change.
runtime/pprof: stress test goroutine profiler
For #33250
Change-Id: Ic7aa74b1bb5da9c4319718bac96316b236cb40b2
---
M src/runtime/pprof/pprof_test.go
M src/runtime/proc.go
M src/runtime/runtime_test.go
3 files changed, 382 insertions(+), 1 deletion(-)
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Rhys Hiltner (Gerrit)
May 3, 2022, 2:03:02 PM5/3/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, Michael Knyszek, Cherry Mui, Gopher Robot, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui, Michael Knyszek.
Patch set 5:Run-TryBot +1
2 comments:
File src/runtime/pprof/pprof_test.go:
how long does this test take to run? we may want to skip on non-longtest builders, i.e. […]
On my laptop, a call to testLaunches takes about 4ms. I reduced the loop count for short mode.
Patch Set #4, Line 1558:
time.Sleep(10 * time.Millisecond) // let goroutines exit
just to help avoid having goroutines exist across benchmark runs, I have slight preference for a wg. […]
Yes, wait groups are better. I've changed these new tests to be more explicit about when it's time to move forward. Thank you.
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Michael Knyszek (Gerrit)
May 3, 2022, 2:15:27 PM5/3/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, Cherry Mui, Gopher Robot, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui, Rhys Hiltner.
Patch set 5:Code-Review +2
David Chase (Gerrit)
May 3, 2022, 2:31:24 PM5/3/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, Gopher Robot, Cherry Mui, golang-co...@googlegroups.com
Attention is currently required from: Cherry Mui, Rhys Hiltner.
Patch set 5:Code-Review +1
Michael Knyszek (Gerrit)
May 3, 2022, 4:49:24 PM5/3/22
to Rhys Hiltner, goph...@pubsubhelper.golang.org, golang-...@googlegroups.com, David Chase, Gopher Robot, Cherry Mui, golang-co...@googlegroups.com
Michael Knyszek submitted this change.
Approvals:
Rhys Hiltner: Run TryBots
Gopher Robot: TryBots succeeded
David Chase: Looks good to me, but someone else must approve
Michael Knyszek: Looks good to me, approved
runtime/pprof: stress test goroutine profiler
For #33250
Change-Id: Ic7aa74b1bb5da9c4319718bac96316b236cb40b2
Reviewed-on: https://go-review.googlesource.com/c/go/+/387414
Run-TryBot: Rhys Hiltner <rh...@justin.tv>
TryBot-Result: Gopher Robot <go...@golang.org>
Reviewed-by: Michael Knyszek <mkny...@google.com>
Reviewed-by: David Chase <drc...@google.com>
---
M src/runtime/pprof/pprof_test.go
M src/runtime/proc.go
M src/runtime/runtime_test.go
3 files changed, 387 insertions(+), 1 deletion(-)
diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go
index 1cc69a3..eeb7b27 100644
--- a/src/runtime/pprof/pprof_test.go
+++ b/src/runtime/pprof/pprof_test.go
@@ -1389,6 +1389,279 @@
+ 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()
+ }()
+ 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()diff --git a/src/runtime/proc.go b/src/runtime/proc.go
index 34b09f2..2f2664f 100644
--- a/src/runtime/proc.go
+++ b/src/runtime/proc.go
@@ -5053,7 +5053,7 @@
}
}
- unlock(&sched.lock) // unlock so that GODEBUG=scheddetail=1 doesn't hang
+ unlock(&sched.lock) // unlock so that GODEBUG=scheddetail=1 doesn't hang
fatal("all goroutines are asleep - deadlock!")
}
diff --git a/src/runtime/runtime_test.go b/src/runtime/runtime_test.go
index 1dc04ac..0bdd01b 100644
--- a/src/runtime/runtime_test.go
+++ b/src/runtime/runtime_test.go
@@ -10,8 +10,11 @@
"io"
. "runtime"
"runtime/debug"
+ "sort"
"strings"
+ "sync"
"testing"
+ "time"
"unsafe"
)
@@ -357,6 +360,100 @@
}
}
+func BenchmarkGoroutineProfile(b *testing.B) {
+ run := func(fn func() bool) func(b *testing.B) {
+ runOne := func(b *testing.B) {
+ latencies := make([]time.Duration, 0, b.N)
+
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ start := time.Now()
+ ok := fn()
+ if !ok {
+ b.Fatal("goroutine profile failed")
+ }
+ latencies = append(latencies, time.Now().Sub(start))
+ }
+ b.StopTimer()
+
+ // Sort latencies then report percentiles.
+ sort.Slice(latencies, func(i, j int) bool {
+ return latencies[i] < latencies[j]
+ })
+ b.ReportMetric(float64(latencies[len(latencies)*50/100]), "p50-ns")
+ b.ReportMetric(float64(latencies[len(latencies)*90/100]), "p90-ns")
+ b.ReportMetric(float64(latencies[len(latencies)*99/100]), "p99-ns")
+ }
+ return func(b *testing.B) {
+ b.Run("idle", runOne)
+
+ b.Run("loaded", func(b *testing.B) {
+ stop := applyGCLoad(b)
+ runOne(b)
+ // Make sure to stop the timer before we wait! The load created above
+ // is very heavy-weight and not easy to stop, so we could end up
+ // confusing the benchmarking framework for small b.N.
+ b.StopTimer()
+ stop()
+ })
+ }
+ }
+
+ // Measure the cost of counting goroutines
+ b.Run("small-nil", run(func() bool {
+ GoroutineProfile(nil)
+ return true
+ }))
+
+ // Measure the cost with a small set of goroutines
+ n := NumGoroutine()
+ p := make([]StackRecord, 2*n+2*GOMAXPROCS(0))
+ b.Run("small", run(func() bool {
+ _, ok := GoroutineProfile(p)
+ return ok
+ }))
+
+ // Measure the cost with a large set of goroutines
+ ch := make(chan int)
+ var ready, done sync.WaitGroup
+ for i := 0; i < 5000; i++ {
+ ready.Add(1)
+ done.Add(1)
+ go func() { ready.Done(); <-ch; done.Done() }()
+ }
+ ready.Wait()
+
+ // Count goroutines with a large allgs list
+ b.Run("large-nil", run(func() bool {
+ GoroutineProfile(nil)
+ return true
+ }))
+
+ n = NumGoroutine()
+ p = make([]StackRecord, 2*n+2*GOMAXPROCS(0))
+ b.Run("large", run(func() bool {
+ _, ok := GoroutineProfile(p)
+ return ok
+ }))
+
+ close(ch)
+ done.Wait()
+
+ // Count goroutines with a large (but unused) allgs list
+ b.Run("sparse-nil", run(func() bool {
+ GoroutineProfile(nil)
+ return true
+ }))
+
+ // Measure the cost of a large (but unused) allgs list
+ n = NumGoroutine()
+ p = make([]StackRecord, 2*n+2*GOMAXPROCS(0))
+ b.Run("sparse", run(func() bool {
+ _, ok := GoroutineProfile(p)
+ return ok
+ }))
+}
+
func TestVersion(t *testing.T) {
// Test that version does not contain \r or \n.
vers := Version()
To view, visit change 387414. To unsubscribe, or for help writing mail filters, visit settings.
Reply all
Reply to author
Forward
0 new messages