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: fatal error: m changed unexpectedly in cgocallbackg on 386 #62102

Closed
mknyszek opened this issue Aug 17, 2023 · 14 comments
Closed

runtime: fatal error: m changed unexpectedly in cgocallbackg on 386 #62102

mknyszek opened this issue Aug 17, 2023 · 14 comments
Assignees
Labels
arch-386 Issues solely affecting the 32-bit x86 architecture compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@mknyszek
Copy link
Contributor

mknyszek commented Aug 17, 2023

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`

2023-08-02 15:24 linux-386 go@0f1491de cmd/cgo/internal/test.TestCallbackStack (log)
2023-08-07 06:58 linux-386 go@088f953f cmd/cgo/internal/test.TestCallbackStack (log)
2023-08-14 19:23 linux-386 go@02b548e5 cmd/cgo/internal/test.TestCallbackStack (log)

@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Aug 17, 2023
@dmitshur dmitshur added this to the Backlog milestone Aug 17, 2023
@dmitshur dmitshur added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. arch-386 Issues solely affecting the 32-bit x86 architecture labels Aug 17, 2023
@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`
2023-08-02 15:24 linux-386 go@0f1491de cmd/cgo/internal/test.TestCallbackStack (log)
fatal error: m changed unexpectedly in cgocallbackg

runtime.throw({0x5677c60d, 0x26})
	/workdir/go/src/runtime/panic.go:837 +0x52 fp=0x57050c8c sp=0x57050c78 pc=0x56629d72
runtime.cgocallbackg(0x5676af90, 0xe4ff52bf, 0x0)
	/workdir/go/src/runtime/cgocall.go:257 +0x16e fp=0x57050cc4 sp=0x57050c8c pc=0x565ef64e
runtime.cgocallback(0x565ef47e, 0x5676d1a0, 0x57050d04)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x57050cd4 sp=0x57050cc4 pc=0x56663865
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x57050cd8 sp=0x57050cd4 pc=0x566624e0
runtime.cgocall(0x5676d1a0, 0x57050d04)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x57050cf0 sp=0x57050cd8 pc=0x565ef47e
cmd/cgo/internal/test._Cfunc_callGoStackCheck()
	_cgo_gotypes.go:1247 +0x3b fp=0x57050d04 sp=0x57050cf0 pc=0x567395ab
cmd/cgo/internal/test.stack580()
	/workdir/go/src/cmd/cgo/internal/test/callback.go:677 +0x53 fp=0x57050f4c sp=0x57050d04 pc=0x56740e43
cmd/cgo/internal/test.testCallbackStack(...)
	/workdir/go/src/cmd/cgo/internal/test/callback.go:301
cmd/cgo/internal/test.TestCallbackStack(0x570a43c0)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:84 +0x3e fp=0x57050f5c sp=0x57050f4c pc=0x56737c2e
testing.tRunner(0x570a43c0, 0x567ecf54)
2023-08-07 06:58 linux-386 go@088f953f cmd/cgo/internal/test.TestCallbackStack (log)
fatal error: m changed unexpectedly in cgocallbackg

runtime.throw({0x567ef60d, 0x26})
	/workdir/go/src/runtime/panic.go:845 +0x52 fp=0x57e32c74 sp=0x57e32c60 pc=0x5669b0f2
runtime.cgocallbackg(0x567dd730, 0xc01c62bf, 0x0)
	/workdir/go/src/runtime/cgocall.go:257 +0x16e fp=0x57e32cac sp=0x57e32c74 pc=0x5666068e
runtime.cgocallback(0x566604be, 0x567df940, 0x57e32cec)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x57e32cbc sp=0x57e32cac pc=0x566d4e95
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x57e32cc0 sp=0x57e32cbc pc=0x566d3b10
runtime.cgocall(0x567df940, 0x57e32cec)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x57e32cd8 sp=0x57e32cc0 pc=0x566604be
cmd/cgo/internal/test._Cfunc_callGoStackCheck()
	_cgo_gotypes.go:1247 +0x3b fp=0x57e32cec sp=0x57e32cd8 pc=0x567abc7b
cmd/cgo/internal/test.stack604()
	/workdir/go/src/cmd/cgo/internal/test/callback.go:683 +0x53 fp=0x57e32f4c sp=0x57e32cec pc=0x567b37e3
cmd/cgo/internal/test.testCallbackStack(...)
	/workdir/go/src/cmd/cgo/internal/test/callback.go:301
cmd/cgo/internal/test.TestCallbackStack(0x57ed6000)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:84 +0x3e fp=0x57e32f5c sp=0x57e32f4c pc=0x567aa2fe
testing.tRunner(0x57ed6000, 0x5685fef4)
2023-08-14 19:23 linux-386 go@02b548e5 cmd/cgo/internal/test.TestCallbackStack (log)
fatal error: m changed unexpectedly in cgocallbackg

runtime.throw({0x567df629, 0x26})
	/workdir/go/src/runtime/panic.go:859 +0x52 fp=0x57c54860 sp=0x57c5484c pc=0x5668b432
runtime.cgocallbackg(0x567cd770, 0xe9fff2bf, 0x0)
	/workdir/go/src/runtime/cgocall.go:257 +0x16e fp=0x57c54898 sp=0x57c54860 pc=0x5665098e
runtime.cgocallback(0x566507be, 0x567cf980, 0x57c548d8)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x57c548a8 sp=0x57c54898 pc=0x566c53b5
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x57c548ac sp=0x57c548a8 pc=0x566c4030
runtime.cgocall(0x567cf980, 0x57c548d8)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x57c548c4 sp=0x57c548ac pc=0x566507be
cmd/cgo/internal/test._Cfunc_callGoStackCheck()
	_cgo_gotypes.go:1247 +0x3b fp=0x57c548d8 sp=0x57c548c4 pc=0x5679bccb
cmd/cgo/internal/test.stack1680()
	/workdir/go/src/cmd/cgo/internal/test/callback.go:952 +0x53 fp=0x57c54f6c sp=0x57c548d8 pc=0x567aade3
cmd/cgo/internal/test.testCallbackStack(...)
	/workdir/go/src/cmd/cgo/internal/test/callback.go:301
cmd/cgo/internal/test.TestCallbackStack(0x57c7a3c0)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:84 +0x3e fp=0x57c54f7c sp=0x57c54f6c pc=0x5679a34e
testing.tRunner(0x57c7a3c0, 0x56850a74)

watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`
2023-08-22 22:09 linux-386 go@4dc25649 cmd/cgo/internal/test.TestCallbackStack (log)
fatal error: m changed unexpectedly in cgocallbackg

runtime.throw({0x5676a6e4, 0x26})
	/workdir/go/src/runtime/panic.go:1018 +0x52 fp=0x58abd6b4 sp=0x58abd6a0 pc=0x566154c2
runtime.cgocallbackg(0x56759250, 0xcbbde2bf, 0x0)
	/workdir/go/src/runtime/cgocall.go:257 +0x16e fp=0x58abd6ec sp=0x58abd6b4 pc=0x565da98e
runtime.cgocallback(0x565da7be, 0x5675b460, 0x58abd72c)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x58abd6fc sp=0x58abd6ec pc=0x5664f485
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x58abd700 sp=0x58abd6fc pc=0x5664e100
runtime.cgocall(0x5675b460, 0x58abd72c)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x58abd718 sp=0x58abd700 pc=0x565da7be
cmd/cgo/internal/test._Cfunc_callGoStackCheck()
	_cgo_gotypes.go:1247 +0x3b fp=0x58abd72c sp=0x58abd718 pc=0x5672774b
cmd/cgo/internal/test.stack52()
	/workdir/go/src/cmd/cgo/internal/test/callback.go:545 +0x45 fp=0x58abd764 sp=0x58abd72c pc=0x5672beb5
cmd/cgo/internal/test.testCallbackStack(...)
	/workdir/go/src/cmd/cgo/internal/test/callback.go:301
cmd/cgo/internal/test.TestCallbackStack(0x58c9e000)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:84 +0x3e fp=0x58abd774 sp=0x58abd764 pc=0x56725dce
testing.tRunner(0x58c9e000, 0x567dbfb4)

watchflakes

@mknyszek mknyszek self-assigned this Aug 23, 2023
@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`
2023-09-07 16:10 android-386-emu go@dc6513b8 cmd/cgo/internal/test.TestThreadLock (log)
scatter = 0xe87733c0
sqrt is: 0
fatal error: m changed unexpectedly in cgocallbackghello from C


cmd/cgo/internal/test.TestThreadLock(0xbf93d4a0)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:105 +0x37 fp=0xbf8de774 sp=0xbf8de770 pc=0xe873da47
testing.tRunner(0xbf93d4a0, 0xe87f05f8)

watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`
2023-09-08 19:09 linux-386-longtest go@5d9e0be1 cmd/cgo/internal/test.TestCallbackStack (log)
fatal error: m changed unexpectedly in cgocallbackg

runtime.throw({0x5673d647, 0x26})
	/workdir/go/src/runtime/panic.go:1018 +0x52 fp=0x58ac06bc sp=0x58ac06a8 pc=0x565e8692
runtime.cgocallbackg(0x5672b6a0, 0xc5bd12bf, 0x0)
	/workdir/go/src/runtime/cgocall.go:261 +0x17a fp=0x58ac06f4 sp=0x58ac06bc pc=0x565adb6a
runtime.cgocallback(0x565ad98e, 0x5672d890, 0x58ac0734)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x58ac0704 sp=0x58ac06f4 pc=0x56622425
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x58ac0708 sp=0x58ac0704 pc=0x566210a0
runtime.cgocall(0x5672d890, 0x58ac0734)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x58ac0720 sp=0x58ac0708 pc=0x565ad98e
cmd/cgo/internal/test._Cfunc_callGoStackCheck()
	_cgo_gotypes.go:1251 +0x3b fp=0x58ac0734 sp=0x58ac0720 pc=0x566f9cdb
cmd/cgo/internal/test.stack44()
	/workdir/go/src/cmd/cgo/internal/test/callback.go:543 +0x45 fp=0x58ac0764 sp=0x58ac0734 pc=0x566fe465
cmd/cgo/internal/test.testCallbackStack(...)
	/workdir/go/src/cmd/cgo/internal/test/callback.go:301
cmd/cgo/internal/test.TestCallbackStack(0x5847a0f0)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:84 +0x3e fp=0x58ac0774 sp=0x58ac0764 pc=0x566f835e
testing.tRunner(0x5847a0f0, 0x567afed4)

watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`
2023-09-11 20:12 linux-386-buster go@afa3f8e1 cmd/cgo/internal/test (log)
fatal error: m changed unexpectedly in cgocallbackg

goroutine 494 [running]:
runtime.throw({0x567b8647, 0x26})
	/workdir/go/src/runtime/panic.go:1018 +0x52 fp=0x58b10770 sp=0x58b1075c pc=0x566636b2
runtime.cgocallbackg(0x567a71a0, 0xde8ff29c, 0x0)
	/workdir/go/src/runtime/cgocall.go:261 +0x17a fp=0x58b107a8 sp=0x58b10770 pc=0x56628bca
runtime.cgocallback(0x566289ee, 0x567a9d90, 0x58b107e8)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x58b107b8 sp=0x58b107a8 pc=0x5669d445
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x58b107bc sp=0x58b107b8 pc=0x5669c0c0
runtime.cgocall(0x567a9d90, 0x58b107e8)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x58b107d4 sp=0x58b107bc pc=0x566289ee
cmd/cgo/internal/test._Cfunc_cFunc37033(0xb)
	_cgo_gotypes.go:1170 +0x3b fp=0x58b107e8 sp=0x58b107d4 pc=0x567748db
cmd/cgo/internal/test.testHandle.func1()
	/workdir/go/src/cmd/cgo/internal/test/test.go:2278 +0x21 fp=0x58b107f0 sp=0x58b107e8 pc=0x567a32f1
runtime.goexit({})
	/workdir/go/src/runtime/asm_386.s:1363 +0x1 fp=0x58b107f4 sp=0x58b107f0 pc=0x5669d6e1
created by cmd/cgo/internal/test.testHandle in goroutine 336
	/workdir/go/src/cmd/cgo/internal/test/test.go:2277 +0xab

watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `fatal error: m changed unexpectedly in cgocallbackg`
2023-10-03 14:13 linux-386-softfloat go@f79c99fe cmd/cgo/internal/test.TestCallbackStack (log)
fatal error: m changed unexpectedly in cgocallbackg

runtime.throw({0x567a7673, 0x26})
	/workdir/go/src/runtime/panic.go:1018 +0x52 fp=0x57c435e8 sp=0x57c435d4 pc=0x566505a2
runtime.cgocallbackg(0x567961b0, 0xe57f52bf, 0x0)
	/workdir/go/src/runtime/cgocall.go:333 +0x197 fp=0x57c43620 sp=0x57c435e8 pc=0x56614f07
runtime.cgocallback(0x56614ace, 0x56798370, 0x57c43660)
	/workdir/go/src/runtime/asm_386.s:779 +0xa5 fp=0x57c43630 sp=0x57c43620 pc=0x5668c605
runtime.systemstack_switch()
	/workdir/go/src/runtime/asm_386.s:341 fp=0x57c43634 sp=0x57c43630 pc=0x5668b280
runtime.cgocall(0x56798370, 0x57c43660)
	/workdir/go/src/runtime/cgocall.go:175 +0x8e fp=0x57c4364c sp=0x57c43634 pc=0x56614ace
cmd/cgo/internal/test._Cfunc_callGoStackCheck()
	_cgo_gotypes.go:1251 +0x3b fp=0x57c43660 sp=0x57c4364c pc=0x567645db
cmd/cgo/internal/test.stack256()
	/workdir/go/src/cmd/cgo/internal/test/callback.go:596 +0x4e fp=0x57c43764 sp=0x57c43660 pc=0x56769f3e
cmd/cgo/internal/test.testCallbackStack(...)
	/workdir/go/src/cmd/cgo/internal/test/callback.go:301
cmd/cgo/internal/test.TestCallbackStack(0x57c783c0)
	/workdir/go/src/cmd/cgo/internal/test/cgo_test.go:84 +0x3e fp=0x57c43774 sp=0x57c43764 pc=0x56762c6e
testing.tRunner(0x57c783c0, 0x56818e74)

watchflakes

@prattmic
Copy link
Member

prattmic commented Oct 3, 2023

@cherrymui this is happening quite consistently on linux-386. I fear that this is another issue with https://go.dev/cl/495855.

@cherrymui
Copy link
Member

Yeah, probably related. I'll take a look.

@cherrymui
Copy link
Member

Interestingly, this seems to happen more frequently with -buildmode=pie, which is the 5th run of cmd/cgo/internal/test, although not all of the failures above are from this. Running stress test on gomote it is also more likely to fail with -buildmode=pie.

@cherrymui
Copy link
Member

cgocallbackg1 calls unlockOSThread as seemingly the very last step, in a deferred call https://cs.opensource.google/go/go/+/master:src/runtime/cgocall.go;l=349 . Then in the caller cgocallbackg it immediately set m.incgo to true to prevent the scheduler moving it to another M. There is seemingly no preemption point before the two operations. However, on 386, in PIE buildmode, it does not use open coded defers https://cs.opensource.google/go/go/+/master:src/cmd/compile/internal/ssagen/ssa.go;l=403 , therefore unlockOSThread is called via deferreturn, and there is actually preemption point, e.g. p.nextDefer in deferreturn https://cs.opensource.google/go/go/+/master:src/runtime/panic.go;l=591 (on the next iteration after unlockOSThread is called), which is not nosplit. Therefore the G can be preempted and rescheduled to a different M.

@ianlancetaylor
Copy link
Contributor

Ouch, nice catch. I think I wrote that code (https://go.dev/cl/64070) before we had asynchronous preemption, and I assumed that no preemption was possible.

@cherrymui
Copy link
Member

I think this is synchronous preemption (e.g. in function prologues). We don't yet preempt runtime code asynchronously (for now).

I'm working on a fix.

@ianlancetaylor
Copy link
Contributor

Thanks.

@gopherbot
Copy link
Contributor

Change https://go.dev/cl/532615 mentions this issue: runtime: unlock OS thread after cgocallbackg1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
arch-386 Issues solely affecting the 32-bit x86 architecture compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Archived in project
Development

No branches or pull requests

6 participants