runtime/pprof: increase contention upper bound in TestMutexProfile

Currently TestMutexProfile expects contention to reported as somewhere
between 0.9x and 2.0x the expected amount introduced. While bounding
from below is fine (especially since the goroutine holding the mutex
doesn't even start to sleep until the required number of goroutines are
blocked on a mutex), bounding from above can easily lead to flakiness.
Delays and non-determinism can come from anywhere in the system,
and nevertheless clocks keep ticking. The result is that goroutines
could easily appear to be blocked on a mutex much longer than just the
sleep time.

However, the contention upper bound is still useful, especially for
identifying wildly incorrect values. Set the contention total to be
proportional to the total wall-time spent in the actual sampling mutex
block sampling portion of the code. This should be a generous
upper-bound on how much contention there could be, because it should in
theory capture any delays from the environment in it as well.

Still, rounding errors could be an issue, and on Windows the time
granularity is quite low (~15ms, or 15% of what each goroutine is
supposed to add to the mutex profile), so getting unlucky with where
time measurements fall within each tick could also be a problem. Add an
extra 10%, which seems to make it much less likely to fail in a Windows
gomote.

Fixes #62094.

Change-Id: I59a10a73affd077185dada8474b91d0bc43b4a43
Reviewed-on: https://go-review.googlesource.com/c/go/+/520635
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Michael Knyszek <mknyszek@google.com>

diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go
index 948024061524b2d5d97c6939c9155d967a4b5738..029a362cb41b9c443438a163b3927c40cae090ac 100644 (file)
--- a/src/runtime/pprof/pprof_test.go
+++ b/src/runtime/pprof/pprof_test.go
@@ -1245,7 +1245,9 @@ func TestMutexProfile(t *testing.T) {
                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
@@ -1307,9 +1309,22 @@ func TestMutexProfile(t *testing.T) {
                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)
-               if d < N*D*9/10 || d > N*D*2 { // want N*D but allow [0.9,2.0]*that.
-                       t.Fatalf("profile samples total %v, want %v", d, N*D)
+               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)
                }
        })
 }