runtime: scheduler change causes Delve's function call injection to fail intermittently

[aarzilli]

Starting with change ad94306 (https://go.dev/cl/501976) I see frequent (but intermittent) failures of TestCallFunction of github.com/go-delve/delve/pkg/proc. The failure has a few different presentations, a frequent one is this one:

    variables_test.go:1353: call "getAStruct(3).VRcvr(1)"
2023-08-03T10:27:16+02:00 info kind=fncall,layer=proc function call initiated <nil> frame size 65535 goroutine 1 (thread 550064)
2023-08-03T10:27:16+02:00 info kind=fncall,layer=proc findCallInjectionStateForThread thread=550069 goroutine=59
    variables_test.go:1367: call "getAStruct(3).VRcvr(1)": error "could not recover call injection state for goroutine 59 (thread 550069)"
--- FAIL: TestCallFunction (0.53s)

Produced passing -v -log=fncall to TestCallFunction.

Delve keeps a map from goroutine IDs to call injection states, wherever it sees a SIGINT in one of the debugCall functions (runtime.debugCallV2, debugCall32, &c) it reads the goroutine id and searches the map for the corresponding call injection state. If none is found it looks for a call injection state that has just been started on the same thread.

The assumption here is that when the runtime spawns a new goroutine to handle the call injection it will use the same thread to run it, initially. This was agreed upon in https://go-review.googlesource.com/c/go/+/229299:

More generally, though, it's guaranteed to keep the whole call injection protocol on one OS thread and it won't let anything else happen on that thread during the protocol, so if you know what G you're on when you start the injection and associate that with the OS thread, you can check which G it's on when it reaches debugCallNNNN and you know they're tied together.

The logs above suggest that this invariant is being violated, the injection starts on thread 550064 goroutine 1 but the first stop is on thread 550069 goroutine 59.

I'm not 100% sure that the bug was introduced by this commit, I think I saw a similar failure in CI before but I could never reproduce it locally (or see it frequently enough in CI). It could be that the bug already existed and this change made it orders of magnitude more likely.

cc @prattmic @mknyszek @aclements

[dr2chase]

@mpratt @mknyszek

[mknyszek]

I'm familiar with the debugCallWrap path but not familiar with exactly the guarantees needed. What is the point until which the new goroutine needs to be running on the same thread?

AFAICT, here's what the code guarantees:

• debugCallV2 through debugCallWrap is very careful to stay on the same thread.
• Once debugCallWrap calls execute, starting the new goroutine to dispatch the function, all bets are off (mainly, debugCallWrap1 just isn't very careful). There could technically be a preemption point in between the goroutine starting to run and the debugCall32 or whatever being dispatched.

If this sounds right to you, then there's a bug I'm not seeing. If you expect debugCallWrap1 to be on the same M up until it calls debugCall32 (or whichever one) and hits the SIGINT, then that's probably where something is going wrong.

AFAICT, debugCallWrap1 could grow the stack, and if it happens to have a preemption flag set, it might call into the scheduler before dispatching the function. I'm not 100% sure how the preemption flag would be set, but we don't seem to clear it if a goroutine happens to die while the flag is set (which I think is harmless in general). If the g struct gets reused I suppose I could see the preemption flag still set? The stack bound is not going to be poisoned, though. It would have to try to grow the stack explicitly.

RE: the change you linked, it's possible with the wakep it's just more likely to end up on a different thread after a round-trip through the scheduler. In other words, the failure was rare before because most of the time it would just end up back on the same thread.

[aarzilli]

I'm familiar with the debugCallWrap path but not familiar with exactly the guarantees needed. What is the point until which the new goroutine needs to be running on the same thread?

We only observe the program after it calls INT 3, so it would be the BYTE $0xcc instruction in debugCall

If you expect debugCallWrap1 to be on the same M up until it calls debugCall32 (or whichever one) and hits the SIGINT, then that's probably where something is going wrong.

I do expect that and it's possible that this is the problem (although I'm also seeing different failures that I can't explain like this, so maybe there's multiple problems? weird). If making everything run on the same thread is complicated I'm ok with signalling the starting goroutine explicitly in one of the ways I was describing in https://go.dev/cl/229299.

[mknyszek]

Thanks for confirming.

If making everything run on the same thread is complicated

Nah, I don't think it'd be too complicated. I think this just needs to prevent preemption until we get to riiiight before the dispatch. The dispatch call is nosplit, so we just need to get there without calling into the scheduler. I'll send a patch to try out shortly.

[mknyszek]

Oh, also, is this relatively easy to reproduce for you? Is it as simple as just running that Delve test in a loop a bunch of times?

[mknyszek]

Here's an attempt to close off the possible preemption points: https://go.dev/cl/515637

[aarzilli]

Oh, also, is this relatively easy to reproduce for you? Is it as simple as just running that Delve test in a loop a bunch of times?

Yes. Just go test -run TestCallFunction github.com/go-delve/delve/pkg/proc in a loop. It usually fails within 20 iterations.

Here's an attempt to close off the possible preemption points: https://go.dev/cl/515637

I'll test it tomorrow morning.

[gopherbot]

Change https://go.dev/cl/515637 mentions this issue: runtime: stay non-preemptible until dispatch in debugcall

[mknyszek]

I can reproduce, trying out the change...

[mknyszek]

I think it might fix it? I'm having a hard time telling because I'm also seeing a failure involving main.regabistacktest and I'm trying to confirm I didn't introduce that with the change.

EDIT: I can make that main.regabistacktest failure happen without the change, so I don't think it's new. I haven't yet reproduced the "could not recover call injection state" issue with the change applied.