runtime: TestDebugCallUnsafePoint failure on noopt builder

[bcmills]

--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
FAIL
FAIL	runtime	23.293s

2019-12-12T17:47:19-100bf44/linux-amd64-noopt

Possibly related to async preemption?

CC @cherrymui @aclements @mknyszek @ianlancetaylor

[cherrymui]

I think the idea is that function debugCallUnsafePointWorker (https://go.googlesource.com/go/+/refs/heads/master/src/runtime/debug_test.go#188) does not contain any safe points after the atomic variable ready is set to 1. But this is not true for noopt build, where the atomic functions are not intrinsified and are calls (therefore safe points). I guess we should either skip the test on noopt build, or rewrite the worker function in a way that contains no calls even with noopt (I don't know how).

It doesn't seem related to preemption.

[bcmills]

This has recurred several times since. Seems to have started in December.

2020-01-19T15:28:32-02816a2/linux-amd64-noopt
2020-01-09T17:52:05-cec535b/linux-amd64-noopt
2019-12-20T20:12:18-b234fdb/linux-amd64-noopt
2019-12-12T17:47:19-100bf44/linux-amd64-noopt

[bcmills]

Given the timing, I suspect that CL 205718 made this particular test flakier by making InjectDebugCall more likely to succeed (for #35376).

I don't think we should just skip the test on the noopt builder, since the test may also flake for non-builder users and developers using the same flags.

However, if we could detect the presence of safe points at runtime, perhaps we could skip the test dynamically.

[bcmills]

2020-02-19T20:50:11-a737299/linux-amd64-noopt
2020-02-04T15:32:32-b8d339b/linux-amd64-noopt
2020-01-27T14:34:16-4615b39/linux-amd64-noopt
2020-01-22T16:57:26-fb2e3b8/linux-amd64-noopt
2020-01-21T23:58:09-1424889/linux-amd64-noopt

[bcmills]

2020-02-21T18:36:57-6c61a57/linux-amd64-noopt
2020-02-21T18:18:25-30e3bf2/linux-amd64-noopt

[josharian]

https://build.golang.org/log/fad8b580cc951f6c6cf80603454a76a161dc5069

[bcmills]

2020-03-09T18:07:53-b559a17/linux-amd64-noopt
2020-03-02T21:59:19-37fc092/linux-amd64-noopt
2020-03-01T22:26:33-529988d/linux-amd64-noopt
2020-02-28T19:04:46-156c607/linux-amd64-noopt
2020-02-26T15:50:14-975c013/linux-amd64-noopt
2020-02-26T01:52:42-c46ffdd/linux-amd64-noopt
2020-02-25T22:42:00-0652c80/linux-amd64-noopt
2020-02-25T02:50:24-7485050/linux-amd64-noopt
2020-02-24T01:50:28-402ea9e/linux-amd64-noopt

[bcmills]

The failure mode has changed, but the test remains flaky. (It now has extra recurseFn lines in the output.)

2020-03-13T00:19:08-85e87f9/linux-amd64-noopt
2020-03-12T20:00:02-e221a75/linux-amd64-noopt

--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
recurseFn 0 4294967295
recurseFn 1 4294967295
recurseFn 2 4294967295
recurseFn 3 4294967295
recurseFn 4 4294967295
recurseFn 5 4294967295
recurseFn 6 4294967295
recurseFn 7 4294967295
recurseFn 8 4294967295
recurseFn 0 4294967295
recurseFn 1 4294967295
recurseFn 2 4294967295
recurseFn 3 4294967295
recurseFn 4 4294967295
recurseFn 5 4294967295
recurseFn 6 4294967295
recurseFn 7 4294967295
recurseFn 8 4294967295
recurseFn 0 4294967295
recurseFn 1 4294967295
recurseFn 2 4294967295
recurseFn 3 4294967295
recurseFn 4 4294967295
recurseFn 5 4294967295
recurseFn 6 4294967295
recurseFn 7 4294967295
recurseFn 8 4294967295
FAIL
FAIL	runtime	22.758s

[bcmills]

2020-03-31T20:59:14-3431428/linux-amd64-noopt
2020-03-27T14:49:08-dbd22c7/linux-amd64-noopt
2020-03-23T17:47:29-24925c7/linux-amd64-noopt
2020-03-23T16:55:37-7af6a31/linux-amd64-noopt
2020-03-19T17:52:50-cbd421f/linux-amd64-noopt
2020-03-18T19:13:50-f1f947a/linux-amd64-noopt
2020-03-15T07:13:18-2a08f3c/linux-amd64-noopt
2020-03-15T06:42:43-3e00061/linux-amd64-noopt
2020-03-13T19:06:00-be72e3c/linux-amd64-noopt
2020-03-13T19:05:54-fc8a633/linux-amd64-noopt

[thanm]

I see this pretty regularly on the dev.link dashboard.

Also worth noting that it's not hard to reproduce by hand, e.g.

$  cd $GOROOT/src/runtime
$  go test -i -o t -gcflags=all="-l -N" .
$ ./t -test.count=100 -test.run=TestDebugCallUnsafePoint
--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
--- FAIL: TestDebugCallUnsafePoint (0.00s)
    debug_test.go:220: want "call not at safe point", got %!s(<nil>)
FAIL

[gopherbot]

Change https://golang.org/cl/236597 mentions this issue: cmd/compile: mark block control instruction unsafe in "all unsafe" functions