runtime: "lock ordering problem" between forcegc and traceStackTab

[bcmills]

2021-04-23T21:42:54-cef3a44/linux-amd64-staticlockranking
2021-04-05T16:22:12-24dd8cf/linux-amd64-staticlockranking
2021-03-29T21:50:14-1ef114d/linux-amd64-staticlockranking

33489  ======
0 : forcegc 3 0x6c18e0
1 : traceStackTab 26 0x6c9b60
fatal error: lock ordering problem

runtime stack:
runtime.throw({0x59fc0d, 0x6a8760})
	/workdir/go/src/runtime/panic.go:1198 +0x71
runtime.checkRanks(0xc0000821a0, 0x46a981, 0x46a981)
	/workdir/go/src/runtime/lockrank_on.go:152 +0xc9
runtime.lockWithRank.func1()
	/workdir/go/src/runtime/lockrank_on.go:79 +0x87
runtime.lockWithRank(0x43aef6, 0x7f49d35ae018)
	/workdir/go/src/runtime/lockrank_on.go:68 +0x85
runtime.lock(...)
	/workdir/go/src/runtime/lock_futex.go:48
runtime.(*traceStackTable).put(0x6c9b60, {0x7f49d35ae018, 0x2, 0x459dee})
	/workdir/go/src/runtime/trace.go:791 +0x85
runtime.traceStackID(0xe495471088, {0x7f49d35ae018, 0x2, 0x1}, 0xeb15dd0)
	/workdir/go/src/runtime/trace.go:608 +0xb6
runtime.traceEventLocked(0x43cb95, 0x44559a, 0x821a0, 0x2, 0x14, 0x1, {0x0, 0x0, 0x7f49aab15e40})
	/workdir/go/src/runtime/trace.go:580 +0x1f7
runtime.traceEvent(0x60, 0x1, {0x0, 0x7f49aab15e78, 0xc000000b60})
	/workdir/go/src/runtime/trace.go:540 +0xa5
runtime.traceGoPark(0xd4, 0x43d90d)
	/workdir/go/src/runtime/trace.go:1098 +0x52
runtime.park_m(0xc000000b60)
	/workdir/go/src/runtime/proc.go:3486 +0x45
runtime.mcall()
	/workdir/go/src/runtime/asm_amd64.s:307 +0x43

CC @danscales @mknyszek

[danscales]

I don't see where forcegc is acquired during the stacktrace, so I'm wondering if forcegc has somehow been left held during a park operation, or something like that. (I.e. I'm not sure this lock ordering is expected based on the code.)

@mknyszek , do you have any thoughts on whether forcegc is fine to be held in this situation (maybe I missed a place in the stack where it was acquired, though there seem to be very few places)? Or @prattmic (since this may be scheduler-related).

[fraenkel]

Its legit.
traceGoPark() at proc.go:3486 is called and the unlock doesn't occur until proc.go:3493

[danscales]

@fraenkel Thanks for pointing out the exact lines - now it makes sense.

[gopherbot]

Change https://golang.org/cl/316029 mentions this issue: cmd/compile: add edge from lock rank edge from forceGC to traceStackTab