Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: scan missed a g #17473

Closed
aclements opened this issue Oct 17, 2016 · 2 comments
Closed

runtime: scan missed a g #17473

aclements opened this issue Oct 17, 2016 · 2 comments
Milestone

Comments

@aclements
Copy link
Member

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

Current master (42f5ee4).

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/austin/r/go"
GORACE=""
GOROOT="/home/austin/go.dev"
GOTOOLDIR="/home/austin/go.dev/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build843179543=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"

What did you do?

cd misc/cgo/test
while GOGC=10 GODEBUG=gccheckmark=1 GOTRACEBACK=2 go test -ldflags -linkmode=auto; do date; done

What did you expect to see?

Endless PASSes.

What did you see instead?

After ~20 iterations:

gp 0xc4200de820 goid 86 status 3 gcscandone false gcscanvalid true
fatal error: scan missed a g

runtime stack:
runtime.throw(0x5ae8b3, 0xf)
    /home/austin/go.dev/src/runtime/panic.go:587 +0x95 fp=0x7f0caf7fddd0 sp=0x7f0caf7fddb0
runtime.gcMarkRootCheck()
    /home/austin/go.dev/src/runtime/mgcmark.go:126 +0x20c fp=0x7f0caf7fde20 sp=0x7f0caf7fddd0
runtime.gcMark(0xb987937f9bef)
    /home/austin/go.dev/src/runtime/mgc.go:1599 +0x4e3 fp=0x7f0caf7fde68 sp=0x7f0caf7fde20
runtime.gcMarkTermination.func1()
    /home/austin/go.dev/src/runtime/mgc.go:1194 +0x2d fp=0x7f0caf7fde80 sp=0x7f0caf7fde68
runtime.systemstack(0xc420028600)
    /home/austin/go.dev/src/runtime/asm_amd64.s:298 +0x79 fp=0x7f0caf7fde88 sp=0x7f0caf7fde80
runtime.mstart()
    /home/austin/go.dev/src/runtime/proc.go:1081 fp=0x7f0caf7fde90 sp=0x7f0caf7fde88

goroutine 20 [garbage collection]:
runtime.systemstack_switch()
    /home/austin/go.dev/src/runtime/asm_amd64.s:252 fp=0xc42002d540 sp=0xc42002d538
runtime.gcMarkTermination()
    /home/austin/go.dev/src/runtime/mgc.go:1202 +0x141 fp=0xc42002d728 sp=0xc42002d540
runtime.gcMarkDone()
    /home/austin/go.dev/src/runtime/mgc.go:1166 +0x1db fp=0xc42002d748 sp=0xc42002d728
runtime.gcBgMarkWorker(0xc420026000)
    /home/austin/go.dev/src/runtime/mgc.go:1513 +0x2c6 fp=0xc42002d7b8 sp=0xc42002d748
runtime.goexit()
    /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42002d7c0 sp=0xc42002d7b8
created by runtime.gcBgMarkStartWorkers
    /home/austin/go.dev/src/runtime/mgc.go:1357 +0x98
*** Test killed: ran too long (10m0s).

Note that the "scan missed a g" check is only done in gccheckmark mode, which means this bug could be manifesting as a dangling pointer in normal usage. Also, I found this while stress-testing all.bash and it only affected the misc/cgo tests.

/cc @RLH

@aclements aclements added this to the Go1.8 milestone Oct 17, 2016
@aclements aclements self-assigned this Oct 17, 2016
@aclements
Copy link
Member Author

aclements commented Oct 17, 2016

Faster (and more debuggable) way to reproduce:

cd misc/cgo/test
go test -c -ldflags -linkmode=auto
while GOGC=10 GODEBUG=gccheckmark=1 GOTRACEBACK=2 ./test.test; do; done

The panic happens almost immediately, but then the process wedges hard in the middle of printing the traceback (doesn't even respond to SIGINT). It's stuck on the lock(&allglock) in tracebackothers.

Poking around in gdb, the missed G is indeed not on the rescan list and its g.gcRescan is -1.

If I force it past the lock, I get the following traceback:

gp 0xc420074d00 goid 84 status 3 gcscandone false gcscanvalid true
fatal error: scan missed a g
runtime stack:
runtime.throw(0x5ae8b3, 0xf)
    /home/austin/go.dev/src/runtime/panic.go:587 +0x95 fp=0x7ff9c999ddd0 sp=0x7ff9c999ddb0
runtime.gcMarkRootCheck()
    /home/austin/go.dev/src/runtime/mgcmark.go:126 +0x20c fp=0x7ff9c999de20 sp=0x7ff9c999ddd0
runtime.gcMark(0xbd9385843f3e)
    /home/austin/go.dev/src/runtime/mgc.go:1599 +0x4e3 fp=0x7ff9c999de68 sp=0x7ff9c999de20
runtime.gcMarkTermination.func1()
    /home/austin/go.dev/src/runtime/mgc.go:1194 +0x2d fp=0x7ff9c999de80 sp=0x7ff9c999de68
runtime.systemstack(0xc420030000)
    /home/austin/go.dev/src/runtime/asm_amd64.s:298 +0x79 fp=0x7ff9c999de88 sp=0x7ff9c999de80
runtime.mstart()
    /home/austin/go.dev/src/runtime/proc.go:1081 fp=0x7ff9c999de90 sp=0x7ff9c999de88
goroutine 18 [garbage collection]:
runtime.systemstack_switch()
    /home/austin/go.dev/src/runtime/asm_amd64.s:252 fp=0xc420036540 sp=0xc420036538
runtime.gcMarkTermination()
    /home/austin/go.dev/src/runtime/mgc.go:1202 +0x141 fp=0xc420036728 sp=0xc420036540
runtime.gcMarkDone()
    /home/austin/go.dev/src/runtime/mgc.go:1166 +0x1db fp=0xc420036748 sp=0xc420036728
runtime.gcBgMarkWorker(0xc420030000)
    /home/austin/go.dev/src/runtime/mgc.go:1513 +0x2c6 fp=0xc4200367b8 sp=0xc420036748
runtime.goexit()
    /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc4200367c0 sp=0xc4200367b8
created by runtime.gcBgMarkStartWorkers
    /home/austin/go.dev/src/runtime/mgc.go:1357 +0x98
More... goroutine 1 [chan receive, 16 minutes]: runtime.gopark(0x5b8fd0, 0xc4200c6a18, 0x5add18, 0xc, 0xc420018317, 0x3) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42004ab58 sp=0xc42004ab28 runtime.goparkunlock(0xc4200c6a18, 0x5add18, 0xc, 0xc4200c6917, 0x3) /home/austin/go.dev/src/runtime/proc.go:267 +0x5e fp=0xc42004ab98 sp=0xc42004ab58 runtime.chanrecv(0x55c380, 0xc4200c69c0, 0x0, 0xc42004ac01, 0x4d90dc) /home/austin/go.dev/src/runtime/chan.go:496 +0x2fb fp=0xc42004ac20 sp=0xc42004ab98 runtime.chanrecv1(0x55c380, 0xc4200c69c0, 0x0) /home/austin/go.dev/src/runtime/chan.go:378 +0x35 fp=0xc42004ac58 sp=0xc42004ac20 testing.(*T).Run(0xc4200c4000, 0x5ad896, 0xb, 0x5b61d8, 0x894801) /home/austin/go.dev/src/testing/testing.go:658 +0x2e6 fp=0xc42004ad00 sp=0xc42004ac58 testing.RunTests.func1(0xc4200c4000) /home/austin/go.dev/src/testing/testing.go:804 +0x67 fp=0xc42004ad50 sp=0xc42004ad00 testing.tRunner(0xc4200c4000, 0xc42004ae30) /home/austin/go.dev/src/testing/testing.go:621 +0x81 fp=0xc42004ad78 sp=0xc42004ad50 testing.RunTests(0x5b8c50, 0x881780, 0x46, 0x46, 0x406dc8) /home/austin/go.dev/src/testing/testing.go:810 +0x2bb fp=0xc42004ae60 sp=0xc42004ad78 testing.(*M).Run(0xc42004aef8, 0xc42005ff30) /home/austin/go.dev/src/testing/testing.go:754 +0x85 fp=0xc42004aee8 sp=0xc42004ae60 main.main() _/home/austin/go.dev/misc/cgo/test/_test/_testmain.go:194 +0xc6 fp=0xc42004af58 sp=0xc42004aee8 runtime.main() /home/austin/go.dev/src/runtime/proc.go:185 +0x20a fp=0xc42004afb0 sp=0xc42004af58 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42004afb8 sp=0xc42004afb0 goroutine 17 [runnable, locked to thread]: runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42004efb8 sp=0xc42004efb0 goroutine 2 [force gc (idle), 16 minutes]: runtime.gopark(0x5b8fd0, 0x894520, 0x5ae7b4, 0xf, 0x5b8e14, 0x1) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42003a748 sp=0xc42003a718 runtime.goparkunlock(0x894520, 0x5ae7b4, 0xf, 0xc420000114, 0x1) /home/austin/go.dev/src/runtime/proc.go:267 +0x5e fp=0xc42003a788 sp=0xc42003a748 runtime.forcegchelper() /home/austin/go.dev/src/runtime/proc.go:226 +0x9e fp=0xc42003a7c0 sp=0xc42003a788 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42003a7c8 sp=0xc42003a7c0 created by runtime.init.4 /home/austin/go.dev/src/runtime/proc.go:215 +0x35 goroutine 3 [GC sweep wait, 16 minutes]: runtime.gopark(0x5b8fd0, 0x894700, 0x5adfd8, 0xd, 0x453914, 0x1) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42003af38 sp=0xc42003af08 runtime.goparkunlock(0x894700, 0x5adfd8, 0xd, 0x14, 0x1) /home/austin/go.dev/src/runtime/proc.go:267 +0x5e fp=0xc42003af78 sp=0xc42003af38 runtime.bgsweep(0xc42001a070) /home/austin/go.dev/src/runtime/mgcsweep.go:79 +0x12e fp=0xc42003afb8 sp=0xc42003af78 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42003afc0 sp=0xc42003afb8 created by runtime.gcenable /home/austin/go.dev/src/runtime/mgc.go:213 +0x61 goroutine 4 [finalizer wait, 16 minutes]: runtime.gopark(0x5b8fd0, 0x8f1840, 0x5ae415, 0xe, 0x14, 0x1) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42003b708 sp=0xc42003b6d8 runtime.goparkunlock(0x8f1840, 0x5ae415, 0xe, 0x14, 0x1) /home/austin/go.dev/src/runtime/proc.go:267 +0x5e fp=0xc42003b748 sp=0xc42003b708 runtime.runfinq() /home/austin/go.dev/src/runtime/mfinal.go:161 +0xaf fp=0xc42003b7c0 sp=0xc42003b748 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42003b7c8 sp=0xc42003b7c0 created by runtime.createfing /home/austin/go.dev/src/runtime/mfinal.go:142 +0x62 goroutine 5 [runnable]: runtime.notetsleepg(0x8f1ac0, 0xffffffffffffffff, 0x0) /home/austin/go.dev/src/runtime/lock_futex.go:205 +0x42 fp=0xc42003bf60 sp=0xc42003bf30 os/signal.signal_recv(0x0) /home/austin/go.dev/src/runtime/sigqueue.go:116 +0x104 fp=0xc42003bf88 sp=0xc42003bf60 os/signal.loop() /home/austin/go.dev/src/os/signal/signal_unix.go:22 +0x22 fp=0xc42003bfc0 sp=0xc42003bf88 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42003bfc8 sp=0xc42003bfc0 created by os/signal.init.1 /home/austin/go.dev/src/os/signal/signal_unix.go:28 +0x41 goroutine 75 [runnable, locked to thread]: runtime.cgocall(0x52fe60, 0xc42003c7b0, 0xc42003c798) /home/austin/go.dev/src/runtime/cgocall.go:130 +0xe2 fp=0xc42003c770 sp=0xc42003c730 _/home/austin/go.dev/misc/cgo/test._Cfunc_usleep(0x2710, 0xc400000000) _/home/austin/go.dev/misc/cgo/test/_test/_obj_test/_cgo_gotypes.go:1802 +0x4d fp=0xc42003c7b0 sp=0xc42003c770 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42003c7b8 sp=0xc42003c7b0 created by _/home/austin/go.dev/misc/cgo/test.lockOSThreadCallback /home/austin/go.dev/misc/cgo/test/issue3775.go:37 +0xe0 goroutine 19 [GC worker (idle), 16 minutes]: runtime.gopark(0x5b8e70, 0xc4200c0020, 0x5aea6b, 0x10, 0x14, 0x0) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc420036f48 sp=0xc420036f18 runtime.gcBgMarkWorker(0xc420031300) /home/austin/go.dev/src/runtime/mgc.go:1436 +0x108 fp=0xc420036fb8 sp=0xc420036f48 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc420036fc0 sp=0xc420036fb8 created by runtime.gcBgMarkStartWorkers /home/austin/go.dev/src/runtime/mgc.go:1357 +0x98 goroutine 76 [syscall, 16 minutes, locked to thread]: runtime.cgocall(0x52f8f0, 0xc420037f08, 0x4529e0) /home/austin/go.dev/src/runtime/cgocall.go:130 +0xe2 fp=0xc420037ec8 sp=0xc420037e88 _/home/austin/go.dev/misc/cgo/test._Cfunc_doAdd(0x60000000a) _/home/austin/go.dev/misc/cgo/test/_test/_obj_test/_cgo_gotypes.go:931 +0x45 fp=0xc420037f08 sp=0xc420037ec8 _/home/austin/go.dev/misc/cgo/test.testCthread(0xc4200c4900) /home/austin/go.dev/misc/cgo/test/cthread.go:38 +0x3f fp=0xc420037f70 sp=0xc420037f08 _/home/austin/go.dev/misc/cgo/test.TestCthread(0xc4200c4900) /home/austin/go.dev/misc/cgo/test/cgo_test.go:39 +0x2b fp=0xc420037f88 sp=0xc420037f70 testing.tRunner(0xc4200c4900, 0x5b61d8) /home/austin/go.dev/src/testing/testing.go:621 +0x81 fp=0xc420037fb0 sp=0xc420037f88 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc420037fb8 sp=0xc420037fb0 created by testing.(*T).Run /home/austin/go.dev/src/testing/testing.go:657 +0x2bc goroutine 22 [select, 16 minutes, locked to thread]: runtime.gopark(0x5b9008, 0x0, 0x5ac46a, 0x6, 0x18, 0x2) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42004bca0 sp=0xc42004bc70 runtime.selectgoImpl(0xc42004bf20, 0x0, 0x18) /home/austin/go.dev/src/runtime/select.go:423 +0x1198 fp=0xc42004bec0 sp=0xc42004bca0 runtime.selectgo(0xc42004bf20) /home/austin/go.dev/src/runtime/select.go:238 +0x1c fp=0xc42004bee8 sp=0xc42004bec0 runtime.ensureSigM.func1() /home/austin/go.dev/src/runtime/signal_unix.go:408 +0x2dd fp=0xc42004bfb0 sp=0xc42004bee8 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42004bfb8 sp=0xc42004bfb0 created by runtime.ensureSigM /home/austin/go.dev/src/runtime/signal_unix.go:421 +0xda goroutine 9 [runnable]: runtime.notetsleepg(0x8947b8, 0x10c2c9a50, 0x0) /home/austin/go.dev/src/runtime/lock_futex.go:205 +0x42 fp=0xc420061f40 sp=0xc420061f10 runtime.timerproc() /home/austin/go.dev/src/runtime/time.go:209 +0x2ec fp=0xc420061fc0 sp=0xc420061f40 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc420061fc8 sp=0xc420061fc0 created by runtime.addtimerLocked /home/austin/go.dev/src/runtime/time.go:116 +0xed goroutine 41 [GC worker (idle), 16 minutes]: runtime.gopark(0x5b8e70, 0xc4200ec7c0, 0x5aea6b, 0x10, 0x4f1d14, 0x0) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42005d748 sp=0xc42005d718 runtime.gcBgMarkWorker(0xc420032600) /home/austin/go.dev/src/runtime/mgc.go:1436 +0x108 fp=0xc42005d7b8 sp=0xc42005d748 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42005d7c0 sp=0xc42005d7b8 created by runtime.gcBgMarkStartWorkers /home/austin/go.dev/src/runtime/mgc.go:1357 +0x98 goroutine 42 [GC worker (idle), 16 minutes]: runtime.gopark(0x5b8e70, 0xc4200ec7d0, 0x5aea6b, 0x10, 0x4f1914, 0x0) /home/austin/go.dev/src/runtime/proc.go:261 +0x13a fp=0xc42003cf48 sp=0xc42003cf18 runtime.gcBgMarkWorker(0xc420033900) /home/austin/go.dev/src/runtime/mgc.go:1436 +0x108 fp=0xc42003cfb8 sp=0xc42003cf48 runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42003cfc0 sp=0xc42003cfb8 created by runtime.gcBgMarkStartWorkers /home/austin/go.dev/src/runtime/mgc.go:1357 +0x98 goroutine 82 [runnable, locked to thread]: runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc420606fb8 sp=0xc420606fb0 goroutine 83 [syscall, 16 minutes, locked to thread]: runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc420607fb8 sp=0xc420607fb0
goroutine 84 [syscall, locked to thread]: runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc42004ffb8 sp=0xc42004ffb0 goroutine 85 [runnable, locked to thread]: runtime.goexit() /home/austin/go.dev/src/runtime/asm_amd64.s:2158 +0x1 fp=0xc420608fb8 sp=0xc420608fb0

Based on the traceback of goroutine 84, this goroutine is a cgo spare that was created by oneNewExtraM. We're probably just putting this G into the wrong state. Most likely this is harmless in reality.

@gopherbot
Copy link

CL https://golang.org/cl/31139 mentions this issue.

@golang golang locked and limited conversation to collaborators Oct 19, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

2 participants