runtime: sporadic but frequent "signal: illegal instruction" during all.bash on darwin/arm64 at CL 272258 PS 1

[dmitshur]

CL 272258 has made it easy to run all.bash, so I ran it a few times. It has passed at least once, but most of the some test will fail due to "signal: illegal instruction".

This is on a MacBook Air (M1, 2020), macOS 11.0.1 (20B29).

This may get resolved as part of finishing work on #42684, but reporting this in case these failures are helpful to see sooner, since I don't think of any existing macOS/ARM64 issues cover this failure mode specifically.

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

$ go version
go version devel +7716a2fbb7 Sun Nov 22 11:44:49 2020 -0500 darwin/arm64

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

go env Output

$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/dmitri/Library/Caches/go-build"
GOENV="/Users/dmitri/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/dmitri/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/dmitri/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/dmitri/go116r2"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/dmitri/go116r2/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="devel +7716a2fbb7 Sun Nov 22 11:44:49 2020 -0500"
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 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_0/h0671fcn4rgb5pn9c745dx2h0000gn/T/go-build446541792=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Built Go at commit 7716a2fbb7 (CL 272258 PS 1) successfully, pointed GOROOT_BOOTSTRAP to it, then checked out the same commit elsewhere and ran all.bash repeatedly.

What did you expect to see?

$ ./all.bash
Building Go cmd/dist using /Users/dmitri/go116r2. (devel +7716a2fbb7 Sun Nov 22 11:44:49 2020 -0500 darwin/arm64)
Building Go toolchain1 using /Users/dmitri/go116r2.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
Building Go toolchain3 using go_bootstrap and Go toolchain2.
Building packages and commands for darwin/arm64.

[...]

ALL TESTS PASSED
---
Installed Go for darwin/arm64 in /Users/dmitri/gotip
Installed commands in /Users/dmitri/gotip/bin
*** You need to add /Users/dmitri/gotip/bin to your PATH.

What did you see instead?

Most of the time, a failure like:

##### ../test
# go run run.go -- fixedbugs/issue5856.go
exit status 1
go tool compile: signal: illegal instruction

FAIL	fixedbugs/issue5856.go	0.015s
2020/11/22 15:17:43 Failed: exit status 1

##### ../test
# go run run.go -- fixedbugs/issue16095.go
exit status 1
go tool link: signal: illegal instruction

FAIL	fixedbugs/issue16095.go	0.027s
2020/11/22 15:49:41 Failed: exit status 1

##### ../test
# go run run.go -- fixedbugs/issue29264.go
exit status 1
go tool compile: signal: illegal instruction

FAIL	fixedbugs/issue29264.go	0.020s
2020/11/22 16:02:34 Failed: exit status 1

$ ./all.bash
Building Go cmd/dist using /Users/dmitri/gotip. (devel +7716a2fbb7 Sun Nov 22 11:44:49 2020 -0500 darwin/arm64)
Building Go toolchain1 using /Users/dmitri/gotip.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
go build internal/testlog: /Users/dmitri/go116r2/pkg/tool/darwin_arm64/compile: signal: illegal instruction
go tool dist: FAILED: /Users/dmitri/go116r2/pkg/tool/darwin_arm64/go_bootstrap install -gcflags=all= -ldflags=all= -i cmd/asm cmd/cgo cmd/compile cmd/link: exit status 1

--- FAIL: TestCover (1.48s)
    cover_test.go:141: running [go -build -o /var/folders/_0/h0671fcn4rgb5pn9c745dx2h0000gn/T/go-testcover103682725/toolexec.exe testdata/toolexec.go]
    cover_test.go:130: running [go build -o /var/folders/_0/h0671fcn4rgb5pn9c745dx2h0000gn/T/go-testcover103682725/cover.exe]
    cover_test.go:173: failed to build testcover or toolexec program: signal: illegal instruction
--- FAIL: TestCoverHTML (1.48s)
    cover_test.go:390: failed to build testcover or toolexec program: signal: illegal instruction
--- FAIL: TestFuncWithDuplicateLines (1.48s)
    cover_test.go:537: failed to build testcover or toolexec program: signal: illegal instruction
--- FAIL: TestHtmlUnformatted (1.48s)
    cover_test.go:454: failed to build testcover or toolexec program: signal: illegal instruction
--- FAIL: TestDirectives (1.48s)
    cover_test.go:249: failed to build testcover or toolexec program: signal: illegal instruction
--- FAIL: TestCoverFunc (1.48s)
    cover_test.go:368: failed to build testcover or toolexec program: signal: illegal instruction
FAIL
FAIL	cmd/cover	1.728s

--- FAIL: TestDWARF (0.85s)
    --- FAIL: TestDWARF/testprog (1.75s)
        dwarf_test.go:99: symbols testprog.exe: exit status 255: /var/folders/_0/h0671fcn4rgb5pn9c745dx2h0000gn/T/go-link-TestDWARF652205567/testprog.exe [arm64, 0.054295 seconds]:
                null-uuid                            /private/var/folders/_0/h0671fcn4rgb5pn9c745dx2h0000gn/T/go-link-TestDWARF652205567/testprog.exe [AOUT, PIE, FaultedFromDisk]  
                    0x0000000000000000 (0x100000000) __PAGEZERO SEGMENT
                    0x0000000100000000 ( 0xf0000) __TEXT SEGMENT
                        0x0000000100000000 (  0x1000) MACH_HEADER
                        0x0000000100001000 ( 0xc6c90) __TEXT __text
                            0x0000000100001000 (    0x70) go.buildid [FUNC, NameNList, MangledNameNList, Merged, NList] 
                            0x0000000100001070 (    0x50) internal/cpu.Initialize [FUNC, NameNList, MangledNameNList, NList] 
[...]
                            0x00000001002683a8 (     0x8) p [EXT, NameNList, MangledNameNList, NList] 
                            0x00000001002683b0 (     0x4) threadExited [EXT, NameNList, MangledNameNList, NList] 
                    0x000000010026c000 ( 0x402d2) __LINKEDIT SEGMENT
            symbols[31119]: [fatal]  child process status could not be determined; exit code unavailable.
FAIL
FAIL	cmd/link	20.081s

(Full log for TestDWARF/testprog failure.)

CC @cherrymui.

[tmm1]

It's worth trying with GODEBUG=asyncpreemptoff=1 set /cc #42700

[dmitshur]

I think that issue is about running Go darwin/amd64 port under Rosetta 2. This is about running the darwin/arm64 port natively.

I can try it anyway to see what effect it has, thanks for the suggestion.

[cherrymui]

Interesting. Looks similar to #41702. If I'm not mistaken, all failed cases above involve starting processes. Maybe it is more likely to fail on ARM64 than AMD64? Maybe the workaround in #41702 is not effective enough?

@tmm1 this is not Rosetta 2, so #42700 is irrelevant.

That said, GODEBUG=asyncpreemptoff=1 is a workaround of #41702 as well.

[cherrymui]

I rarely see this on the DTK. I think I never see it since the workaround of #41702 is added. It is interesting that it more likely to fail on M1.

Does TestExec in syscall package pass reliably?

[rolandshoemaker]

I've also seen this happen a few times. Interestingly the place I ran into it most often is when running the io benchmarks, particularly BenchmarkCopyNLarge-8.

~/go/src % ../bin/go test ./io -run=XXX -bench=. -count=10
goos: darwin
goarch: arm64
pkg: io
BenchmarkCopyNSmall-8   	 5467614	       425.9 ns/op
BenchmarkCopyNSmall-8   	 3287067	       428.3 ns/op
BenchmarkCopyNSmall-8   	 5085464	       740.8 ns/op
BenchmarkCopyNLarge-8   	signal: illegal instruction
FAIL	io	24.012s
FAIL

[dmitshur]

Does TestExec in syscall package pass reliably?

I believe it does:

$ go version
go version devel +7716a2fbb7 Sun Nov 22 11:44:49 2020 -0500 darwin/arm64
$ go test -run=TestExec syscall
ok  	syscall	0.500s
$ go test -count=1 -run=TestExec syscall
ok  	syscall	0.227s
$ go test -count=10 -run=TestExec syscall
ok  	syscall	1.216s
$ go test -count=100 -run=TestExec syscall
ok  	syscall	7.949s
$ go test -count=1000 -run=TestExec syscall
ok  	syscall	137.463s
$ go test -count=1 -v -run=TestExec syscall 
=== RUN   TestExec
--- PASS: TestExec (0.02s)
=== RUN   TestExecHelper
--- PASS: TestExecHelper (0.00s)
=== RUN   TestExecPtrace
--- PASS: TestExecPtrace (0.00s)
=== RUN   TestExecErrPermutedFds
--- PASS: TestExecErrPermutedFds (0.00s)
PASS
ok  	syscall	0.193s

[dmitshur]

I'm able to reproduce @rolandshoemaker's finding above with go test io -run='^$' -bench=BenchmarkCopy -count=10, 5 out of 5 times. It triggers within 5-30 seconds.

---

I've tried GODEBUG=asyncpreemptoff=1. With it set, all.bash also passed 5 of 5 times, and BenchmarkCopy also worked okay 5 of 5 times, all without any instances of "signal: illegal instruction". When I cleared GODEBUG, the problem started to happen again (although seemingly less frequently...).

[cherrymui]

Okay, I can reproduce the SIGILL with running the io benchmarks in a loop on the DTK, although with a much lower failure rate. I'll take it from there. (I'll be OOO this afternoon, though, so I probably won't get back to this very soon.)

[tonistiigi]

Crash report for this error: https://gist.github.com/tonistiigi/23fbd4be8d1562ff935aa36b2dcdb299

With GODEBUG=asyncpreemptoff=1 ./io.test benchmark doesn't reproduce issue for me either.

[cherrymui]

@tonistiigi thanks for the crash report. I can reproduce the failure and get similar crash reports. I also managed to get a core dump, which is also quite similar.

In the crash report, it says it SIGILLs at __psynch_cvwait + 8, which doesn't make sense. It points to a valid instruction (b.lo $pc-4). In the core dump, the register and stack trace matches, and the memory it points to does have valid instructions. However, the core dump doesn't specify which thread crashes, so I checked them all, and found that two other threads, the PC of which are supposed to be in __semwait_signal and __pthread_kill, respectively, but actually in a page of zeros. This page is next to __psynch_cvwait and in the range of libsystem_kernel.dylib. That page should be mapped read-only, right? So it should not be possible for Go the overwrite that page.

It could be the core file being somehow truncated. Or, if it is actually right, somehow a page of system functions is replaced with a page of 0. I'll try to get more core files.

I haven't been able to get a crash while running under lldb (to eliminate the possibility of truncated core file).

Either way, it seems it crashed in some system function, with SIGILL. I don't see how that could be possible from the Go runtime. Also, normally, when a Go program encounters a SIGILL it will print a stack trace. In this case it doesn't. The only possibilities I can think of is that it crashes before the runtime is initialized, or it SIGILLs while handing signal (so it cannot handle another signal). From the crash report and the core dump, neither seems the case. Maybe the kernel directly kills it when it sees SIGILL in a system library?