2021-02-20T00:01:22-078f08f/freebsd-amd64-11_2
2021-02-05T22:35:11-b54cd94/freebsd-amd64-12_0

https://storage.googleapis.com/go-build-log/3eb689ef/freebsd-amd64-12_0_ce80ab4c.log (a TryBot)

https://storage.googleapis.com/go-build-log/9f7e3663/linux-386_959f2886.log

https://storage.googleapis.com/go-build-log/84f87b94/linux-386_0622a5f1.log (a TryBot)

greplogs --dashboard -md -l -e '(?m)##### ../misc/cgo/testcarchive\n--- FAIL: TestSIGPROF(?:.+\n)*.*profiling timer expired'

2021-11-18T02:11:51-9115a7b/linux-386-softfloat
2021-11-10T00:56:09-cc14fca/linux-386-jessie
2021-10-18T16:01:55-3e5cc4d/linux-386-stretch
2021-08-16T14:27:31-fe489c8/linux-ppc64le-power9osu
2021-05-27T19:55:46-cdcd028/linux-386-sid
2021-03-13T18:09:48-4bd4dfe/linux-amd64-buster
2021-03-09T18:44:23-98dfdc8/linux-amd64-clang
2021-02-20T00:01:22-078f08f/freebsd-amd64-11_2
2021-02-05T22:35:11-b54cd94/freebsd-amd64-12_0
2021-01-18T17:21:53-5a8fbb0/freebsd-amd64-11_2
2021-01-14T22:01:23-e125ccd/linux-amd64-wsl
2019-07-30T20:49:54-1ad64fa/freebsd-amd64-12_0

https://storage.googleapis.com/go-build-log/80097106/linux-amd64_555a0395.log (a TryBot)

Given that this has affected at least three TryBots in the last month alone, I'm marking it as a release-blocker via #11811.

Checking on this as a release blocker. Are there any updates? @ianlancetaylor

I'll take a look.

I think I have a hunch. When we turn off profiling,

		if !sigInstallGoHandler(_SIGPROF) {
			if atomic.Cas(&handlingSig[_SIGPROF], 1, 0) {
				h := atomic.Loaduintptr(&fwdSig[_SIGPROF])
				if h == _SIG_DFL {
					h = _SIG_IGN
				}
				setsig(_SIGPROF, h)
			}
		}

If a pending profiling signal lands right after the Cas but before the setsig (including in another thread running concurrently), in the signal handler, sigfwdgo will see that we're not handling that signal (handlingSig[sig] is 0) and fwdFn is _SIG_DFL, it will die.

Maybe we could do the Cas after the setsig? We have prof.signalLock held so at lease it cannot race with other profiling operation. Or, maybe we could Cas handlingSig[_SIGPROF] to some nonzero value (e.g. 2), setsig, then store 0?

Good catch. I think it would be correct to change the code to

    if atomic.Load(&handlingSig[_SIGPROF]) != 0 {
        ...
        setsig(...)
        atomic.Store(&handlingSig[_SIGPROF], 0)
    }

It can mess up if there a race between enabling and disabling profiling, but that will always have unpredictable results.

SGTM. With that change I still see failures, possibly with a lower rate (same for CAS'ing to 2 then store 0). Still looking.

While I haven't got any useful debugging, here is another guess: when we do the atomic load, setsig, atomic store, a signal handler may be running concurrently on another thread, and it may still observe handlingSig[_SIGPROF] as 0. (The signal is triggered before the setsig, but the atomic load in sigfwdgo occurs after the atomic store.)

Maybe we need some mechanism to synchronize with a concurrently running signal handler. Or maybe we could atomic store fwdSig to _SIG_IGN and carefully do the atomic loads in sigfwdgo in the right order?

With this patch I cannot reproduce the failure. But the code is a bit weird... Maybe there is a better way.

diff --git a/src/runtime/signal_unix.go b/src/runtime/signal_unix.go
index dbcbfc67bc..12340628ad 100644
--- a/src/runtime/signal_unix.go
+++ b/src/runtime/signal_unix.go
@@ -298,12 +298,14 @@ func setProcessCPUProfilerTimer(hz int32) {
                // that use profiling don't want to crash on a stray SIGPROF.
                // See issue 19320.
                if !sigInstallGoHandler(_SIGPROF) {
-                       if atomic.Cas(&handlingSig[_SIGPROF], 1, 0) {
+                       if atomic.Load(&handlingSig[_SIGPROF]) != 0 {
                                h := atomic.Loaduintptr(&fwdSig[_SIGPROF])
                                if h == _SIG_DFL {
                                        h = _SIG_IGN
+                                       atomic.Storeuintptr(&fwdSig[_SIGPROF], h)
                                }
                                setsig(_SIGPROF, h)
+                               atomic.Store(&handlingSig[_SIGPROF], 0)
                        }
                }
        }
@@ -1034,6 +1036,8 @@ func sigfwdgo(sig uint32, info *siginfo, ctx unsafe.Pointer) bool {
 
        // If we aren't handling the signal, forward it.
        if atomic.Load(&handlingSig[sig]) == 0 || !signalsOK {
+               fwdFn = atomic.Loaduintptr(&fwdSig[sig]) // XXX load again
+
                // If the signal is ignored, doing nothing is the same as forwarding.
                if fwdFn == _SIG_IGN || (fwdFn == _SIG_DFL && flags&_SigIgn != 0) {
                        return true

Interesting. So the problem may be that the switch from SIG_DFL to SIG_IGN done by setProcessCPUProfilerTimer isn't observed by sigfwdgo.

What if we change the code that enables profiling instead? If getsig(_SIGPROF) returns SIG_DFL, record SIG_IGN in fwdSig[_SIGPROF]. Then we can drop the check when disabling profiling, and it seems likely that we won't crash in sigfwdgo either.

Good idea! Thanks. Sent CL https://go-review.googlesource.com/c/go/+/374074 .

Change https://golang.org/cl/374074 mentions this issue: runtime: handle stray profiling signal better