runtime/pprof: fix block profile bias

Block profiles were biased towards infrequent long events over frequent
short events. This fix corrects the bias by aggregating shorter events
as longer but less frequent in the profiles. As a result their
cumulative duration will be accurately represented in the profile
without skewing their sample mean (duration/count).

Credit to @dvyukov for suggesting to adjust the count in the
saveblockevent function.

Fixes #44192.

Change-Id: I71a99d7f6ebdb2d484d44890a2517863cceb4004
Reviewed-on: https://go-review.googlesource.com/c/go/+/299991
Trust: Michael Pratt <mpratt@google.com>
Trust: Ian Lance Taylor <iant@golang.org>
Run-TryBot: Michael Pratt <mpratt@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>

diff --git a/src/runtime/mprof.go b/src/runtime/mprof.go
index 1156329615287735347544f6fc1544b2a6ab5216..5235b898e4f56cdcf4613ee91803e8377c39192d 100644 (file)
--- a/src/runtime/mprof.go
+++ b/src/runtime/mprof.go
@@ -133,7 +133,7 @@ func (a *memRecordCycle) add(b *memRecordCycle) {
 // A blockRecord is the bucket data for a bucket of type blockProfile,
 // which is used in blocking and mutex profiles.
 type blockRecord struct {
-       count  int64
+       count  float64
        cycles int64
 }
 
@@ -398,20 +398,23 @@ func blockevent(cycles int64, skip int) {
        if cycles <= 0 {
                cycles = 1
        }
-       if blocksampled(cycles) {
-               saveblockevent(cycles, skip+1, blockProfile)
+
+       rate := int64(atomic.Load64(&blockprofilerate))
+       if blocksampled(cycles, rate) {
+               saveblockevent(cycles, rate, skip+1, blockProfile)
        }
 }
 
-func blocksampled(cycles int64) bool {
-       rate := int64(atomic.Load64(&blockprofilerate))
+// blocksampled returns true for all events where cycles >= rate. Shorter
+// events have a cycles/rate random chance of returning true.
+func blocksampled(cycles, rate int64) bool {
        if rate <= 0 || (rate > cycles && int64(fastrand())%rate > cycles) {
                return false
        }
        return true
 }
 
-func saveblockevent(cycles int64, skip int, which bucketType) {
+func saveblockevent(cycles, rate int64, skip int, which bucketType) {
        gp := getg()
        var nstk int
        var stk [maxStack]uintptr
@@ -422,8 +425,15 @@ func saveblockevent(cycles int64, skip int, which bucketType) {
        }
        lock(&proflock)
        b := stkbucket(which, 0, stk[:nstk], true)
-       b.bp().count++
-       b.bp().cycles += cycles
+
+       if which == blockProfile && cycles < rate {
+               // Remove sampling bias, see discussion on http://golang.org/cl/299991.
+               b.bp().count += float64(rate) / float64(cycles)
+               b.bp().cycles += rate
+       } else {
+               b.bp().count++
+               b.bp().cycles += cycles
+       }
        unlock(&proflock)
 }
 
@@ -454,7 +464,7 @@ func mutexevent(cycles int64, skip int) {
        // TODO(pjw): measure impact of always calling fastrand vs using something
        // like malloc.go:nextSample()
        if rate > 0 && int64(fastrand())%rate == 0 {
-               saveblockevent(cycles, skip+1, mutexProfile)
+               saveblockevent(cycles, rate, skip+1, mutexProfile)
        }
 }
 
@@ -656,7 +666,12 @@ func BlockProfile(p []BlockProfileRecord) (n int, ok bool) {
                for b := bbuckets; b != nil; b = b.allnext {
                        bp := b.bp()
                        r := &p[0]
-                       r.Count = bp.count
+                       r.Count = int64(bp.count)
+                       // Prevent callers from having to worry about division by zero errors.
+                       // See discussion on http://golang.org/cl/299991.
+                       if r.Count == 0 {
+                               r.Count = 1
+                       }
                        r.Cycles = bp.cycles
                        if raceenabled {
                                racewriterangepc(unsafe.Pointer(&r.Stack0[0]), unsafe.Sizeof(r.Stack0), getcallerpc(), funcPC(BlockProfile))

diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go
index 3423f8dc3dcf70135add19a0bfd558a824708769..7cbb4fc7ae4e41ea7fdac596254ee206ee0807a6 100644 (file)
--- a/src/runtime/pprof/pprof_test.go
+++ b/src/runtime/pprof/pprof_test.go
@@ -14,6 +14,7 @@ import (
        "internal/profile"
        "internal/testenv"
        "io"
+       "math"
        "math/big"
        "os"
        "os/exec"
@@ -24,6 +25,7 @@ import (
        "sync/atomic"
        "testing"
        "time"
+       _ "unsafe"
 )
 
 func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
@@ -895,6 +897,74 @@ func blockCond() {
        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