runtime/pprof: remove arbitrary sleeps in TestBlockProfile

The "block" helpers in TestBlockProfile previously slept for an
arbitrary duration and assumed that that duration was long enough for
the parent goroutine to have registered as blocking. However —
especially on slow or overloaded builders — the current arbitrary
duration is sometimes not quite long enough.

Rather than increasing the duration to a different arbitrary value
(which would make the test slower but not actually eliminate the
possibility of flakes!), we can use the runtime's own accounting to
detect when the goroutine is actually blocked: we obtain a goroutine
dump from the runtime, and assume that blocking has been registered in
the profile only if the runtime shows the test goroutine in the
appropriate blocked state.

That not only makes the test more reliable, but also makes it
significantly lower-latency when run on a fast machine.

Fixes #6999
Fixes #37844

Change-Id: I465ed2afd406fd2b621419e1f06925f283525f25
Reviewed-on: https://go-review.googlesource.com/c/go/+/384534
Trust: Bryan Mills <bcmills@google.com>
Trust: Benny Siegert <bsiegert@gmail.com>
Run-TryBot: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

src/runtime/pprof/pprof_test.go

@@ -794,7 +794,7 @@ func use(x [8 << 18]byte) {}
 func TestBlockProfile(t *testing.T) {
 	type TestCase struct {
 		name string
-		f    func()
+		f    func(*testing.T)
 		stk  []string
 		re   string
 	}
@@ -903,7 +903,7 @@ func TestBlockProfile(t *testing.T) {
 	runtime.SetBlockProfileRate(1)
 	defer runtime.SetBlockProfileRate(0)
 	for _, test := range tests {
-		test.f()
+		test.f(t)
 	}
 
 	t.Run("debug=1", func(t *testing.T) {
@@ -979,42 +979,73 @@ func containsStack(got [][]string, want []string) bool {
 	return false
 }
 
-const blockDelay = 10 * time.Millisecond
+// 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) {
+	re := fmt.Sprintf(`(?m)^goroutine \d+ \[%s\]:\n(?:.+\n\t.+\n)*runtime/pprof\.%s`, regexp.QuoteMeta(state), fName)
+	r := regexp.MustCompile(re)
 
-func blockChanRecv() {
+	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 r.Match(buf[:n]) {
+			return
+		}
+	}
+}
+
+func blockChanRecv(t *testing.T) {
 	c := make(chan bool)
 	go func() {
-		time.Sleep(blockDelay)
+		awaitBlockedGoroutine(t, "chan receive", "blockChanRecv")
 		c <- true
 	}()
 	<-c
 }
 
-func blockChanSend() {
+func blockChanSend(t *testing.T) {
 	c := make(chan bool)
 	go func() {
-		time.Sleep(blockDelay)
+		awaitBlockedGoroutine(t, "chan send", "blockChanSend")
 		<-c
 	}()
 	c <- true
 }
 
-func blockChanClose() {
+func blockChanClose(t *testing.T) {
 	c := make(chan bool)
 	go func() {
-		time.Sleep(blockDelay)
+		awaitBlockedGoroutine(t, "chan receive", "blockChanClose")
 		close(c)
 	}()
 	<-c
 }
 
-func blockSelectRecvAsync() {
+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++ {
-			time.Sleep(blockDelay)
+			awaitBlockedGoroutine(t, "select", "blockSelectRecvAsync")
 			c <- true
 		}
 	}()
@@ -1026,11 +1057,11 @@ func blockSelectRecvAsync() {
 	}
 }
 
-func blockSelectSendSync() {
+func blockSelectSendSync(t *testing.T) {
 	c := make(chan bool)
 	c2 := make(chan bool)
 	go func() {
-		time.Sleep(blockDelay)
+		awaitBlockedGoroutine(t, "select", "blockSelectSendSync")
 		<-c
 	}()
 	select {
@@ -1039,11 +1070,11 @@ func blockSelectSendSync() {
 	}
 }
 
-func blockMutex() {
+func blockMutex(t *testing.T) {
 	var mu sync.Mutex
 	mu.Lock()
 	go func() {
-		time.Sleep(blockDelay)
+		awaitBlockedGoroutine(t, "semacquire", "blockMutex")
 		mu.Unlock()
 	}()
 	// Note: Unlock releases mu before recording the mutex event,
@@ -1053,12 +1084,12 @@ func blockMutex() {
 	mu.Lock()
 }
 
-func blockCond() {
+func blockCond(t *testing.T) {
 	var mu sync.Mutex
 	c := sync.NewCond(&mu)
 	mu.Lock()
 	go func() {
-		time.Sleep(blockDelay)
+		awaitBlockedGoroutine(t, "sync.Cond.Wait", "blockCond")
 		mu.Lock()
 		c.Signal()
 		mu.Unlock()
@@ -1144,7 +1175,7 @@ func TestMutexProfile(t *testing.T) {
 		t.Fatalf("need MutexProfileRate 0, got %d", old)
 	}
 
-	blockMutex()
+	blockMutex(t)
 
 	t.Run("debug=1", func(t *testing.T) {
 		var w bytes.Buffer