runtime: AVX512 register state clobbered by signal on macOS

[vsivsi]

What version of Go are you using (go version)?

% go version
go version go1.17.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

 % go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/vsi/Library/Caches/go-build"
GOENV="/Users/vsi/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/vsi/go/pkg/mod"
GONOPROXY="github.com/vsivsi"
GONOSUMDB="github.com/vsivsi"
GOOS="darwin"
GOPATH="/Users/vsi/go"
GOPRIVATE="github.com/vsivsi"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.17.2/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.17.2/libexec/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.2"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/kp/kjdr0ytx5z9djnq4ysl15x0h0000gn/T/go-build4285878374=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

In writing AVX-512 assembly functions using the Go assembler (via Avo), I began to notice unexplained intermittent test failures. A lot of painful investigation revealed that golang async preemption does not seem to be properly save/restoring AVX512 state when assembly functions are interrupted. From visual inspection of the runtime/preempt_amd64.s source, it also seems likely that AVX/AVX2 state (YMM upper 128 bits) may not be properly save/restored either, but I have not encountered/tested that case in my own code.

A complete minimal reproduction illustrating the clobbering of the AVX512 K1 opmask register is here:
https://gist.github.com/vsivsi/fff8618ace4b02eb410dd8792779bf32

Note, in my testing running with GODEBUG=asyncpreemptoff=1 rescues every failure case I have identified.

What did you expect to see?

I expected all relevant processor state to be properly restored in an assembly function following an async preemption.

What did you see instead?

Critical state is being clobbered, leading to intermittent undefined behavior.

[dmitshur]

CC @ianlancetaylor, @prattmic, @FiloSottile.

[randall77]

Hmm, this may be the VZEROUPPER we introduced in CL 219131 to fix #37174. Or it may be worse than that, I'm not sure.
@cherrymui

@vsivsi Can you try patching out #ifdef GOOS_darwin clause in runtime/preempt_amd64.s and see if that helps?

[cherrymui]

The runtime doesn't async preempt assembly functions. asyncPreempt (the function in runtime/preempt_amd64.s) should not be executed if it is running in an assembly function. The runtime sends a signal, but if the signal lands in an assembly function the signal handler will return immediately without actually preempt.

I suspect that the darwin kernel doesn't preserve AVX512 state when handling signals. Then the problem would not be preemption, but any asynchronous signal could cause it to fail, including profiling signals or user signals.

What version of macOS are you running on?

I have a vague memory that Apple suggests that before using AVX512 one must check its availability with some sysctl (but I'm not really sure). Do we do that?

[vsivsi]

@randall77 I can try that, but the initial issue I encountered (as reflected in the repro case) was clobbering of the K0-K7 opmask registers, which are distinct from the vector registers affected by VZEROUPPER, etc.

@cherrymui Yes, Darwin requires special checking to identify AVX512 support. I submitted a fix for this last year. See here for details on that saga: #43089

It is quite possible that this issue I'm seeing is new with golang 1.17. Is it possible that the new assembly adapter funcs required for inter-operation with the new function parameter passing spec could be interfering with the assembly code detection during preemption?

To maintain compatibility with existing assembly functions, the compiler generates adapter functions that convert between the new register-based calling convention and the previous stack-based calling convention. These adapters are typically invisible to users, except that taking the address of a Go function in assembly code or taking the address of an assembly function in Go code using reflect.ValueOf(fn).Pointer() or unsafe.Pointer will now return the address of the adapter. Code that depends on the value of these code pointers may no longer behave as expected. Adapters also may cause a very small performance overhead in two cases: calling an assembly function indirectly from Go via a func value, and calling Go functions from assembly.

[josharian]

How we detect asm routines during preempt changed in Go 1.18. (c2483a5#diff-47fd68949147d260b91998c0d6eabffcdb74c58991fc386b40e14a6ed710b17d)

Does this reproduce at tip? (I'm AFK.)

[leitzler]

It does, with:

% go version
go version devel go1.18-6113dacf32 Sat Oct 30 18:30:34 2021 +0000 darwin/amd64
% sysctl machdep.cpu.brand_string
machdep.cpu.brand_string: Intel(R) Core(TM) i7-1068NG7 CPU @ 2.30GHz
% sw_vers
ProductName:	macOS
ProductVersion:	11.6
BuildVersion:	20G165

% go test .
--- FAIL: TestMask (0.43s)
    maskcheck_test.go:16: Failed for iteration: 0 with return value: 88007197
    maskcheck_test.go:16: Failed for iteration: 1 with return value: 61939268
    maskcheck_test.go:16: Failed for iteration: 2 with return value: 50093958
    maskcheck_test.go:16: Failed for iteration: 3 with return value: 57687622
    maskcheck_test.go:16: Failed for iteration: 4 with return value: 55302035
    maskcheck_test.go:16: Failed for iteration: 5 with return value: 50302791
    maskcheck_test.go:16: Failed for iteration: 6 with return value: 55661062
    maskcheck_test.go:16: Failed for iteration: 7 with return value: 54177345
    maskcheck_test.go:16: Failed for iteration: 8 with return value: 58187395
    maskcheck_test.go:16: Failed for iteration: 9 with return value: 51991146
    maskcheck_test.go:16: Failed for iteration: 10 with return value: 56438664
    maskcheck_test.go:16: Failed for iteration: 11 with return value: 54676159
    maskcheck_test.go:16: Failed for iteration: 12 with return value: 50955817
    maskcheck_test.go:16: Failed for iteration: 13 with return value: 52912278
    maskcheck_test.go:16: Failed for iteration: 14 with return value: 57776646
    maskcheck_test.go:16: Failed for iteration: 15 with return value: 54628233
    maskcheck_test.go:16: Failed for iteration: 16 with return value: 55309645
    maskcheck_test.go:16: Failed for iteration: 17 with return value: 52719044
    maskcheck_test.go:16: Failed for iteration: 18 with return value: 57165517
    maskcheck_test.go:16: Failed for iteration: 19 with return value: 57336883
FAIL
FAIL	x	0.570s
FAIL

[cherrymui]

It is quite possible that this issue I'm seeing is new with golang 1.17. Is it possible that the new assembly adapter funcs required for inter-operation with the new function parameter passing spec could be interfering with the assembly code detection during preemption?

It seems unlikely. You can try building with Go 1.17 with GOEXPERIMENT=noregabi environment variable set (at go run/build/test time).

Also, you can try running the program with preemption disabled but CPU profiling enabled and see if profiling signal changes anything. You can also try running the program with preemption disabled while having a separate process sending SIGURG signals to it. Thanks.

[vsivsi]

@cherrymui Good suggestions. Running the repro test case as:

 % GODEBUG=asyncpreemptoff=1 go test -cpuprofile cpu.out -count 1 -timeout 15m -run '^TestMask$' gist.github.com/vsivsi/fff8618ace4b02eb410dd8792779bf32
--- FAIL: TestMask (0.26s)
    maskcheck_test.go:21: Failed for iteration: 0 with return value: 47429074
    maskcheck_test.go:21: Failed for iteration: 1 with return value: 45358536
    maskcheck_test.go:21: Failed for iteration: 2 with return value: 52675366
    maskcheck_test.go:21: Failed for iteration: 3 with return value: 44456167
    maskcheck_test.go:21: Failed for iteration: 4 with return value: 72420817
    maskcheck_test.go:21: Failed for iteration: 5 with return value: 72654067
    maskcheck_test.go:21: Failed for iteration: 6 with return value: 72091434
    maskcheck_test.go:21: Failed for iteration: 7 with return value: 73369163
    maskcheck_test.go:21: Failed for iteration: 8 with return value: 72828760
    maskcheck_test.go:21: Failed for iteration: 9 with return value: 73065114
    maskcheck_test.go:21: Failed for iteration: 10 with return value: 73038149
    maskcheck_test.go:21: Failed for iteration: 11 with return value: 72684990
    maskcheck_test.go:21: Failed for iteration: 12 with return value: 72653599
    maskcheck_test.go:21: Failed for iteration: 13 with return value: 72440260
    maskcheck_test.go:21: Failed for iteration: 14 with return value: 72201890
    maskcheck_test.go:21: Failed for iteration: 15 with return value: 45021003
    maskcheck_test.go:21: Failed for iteration: 16 with return value: 72012922
    maskcheck_test.go:21: Failed for iteration: 17 with return value: 44692569
    maskcheck_test.go:21: Failed for iteration: 18 with return value: 72992403
    maskcheck_test.go:21: Failed for iteration: 19 with return value: 73178568
FAIL
FAIL	gist.github.com/vsivsi/fff8618ace4b02eb410dd8792779bf32	0.601s
FAIL

This leads to the test failing, and with different looking stats (each iteration fails earlier in the loop on average, probably due to different signaling rates between profiling and preemption).

Two other data points:

1. I have not yet observed corruption of actual ZMM vector state in my testing. From what I've seen this appears to be limited to the K0-K7 opmask registers.
2. The above observation is curious in light of the fact that the Darwin kernel code I've been looking at is at least not obviously broken w.r.t to handling the opmask registers and AVX512 thread state in signal handling. Opmask data is present in all of the relevant state structures, there appear to be tests that check that it is properly saved and restored, etc. So whatever is happening is more subtle than mere omission of this detail in the kernel. See e.g.:
   https://github.com/apple/darwin-xnu/search?q=opmask